Skip to content

The testnet runs for a long time and dfuseeos exits #215

Description

@cppfuns

The last part of the log of dfuse.log.json

{"level":"error","ts":1613751208.8336573,"logger":"mindreader","caller":"mindreader/mindreader.go:265","msg":"failed storing block in archiver, shutting down and losing blocks in transit...","error":"open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.833732,"logger":"mindreader","caller":"mindreader/mindreader.go:241","msg":"waiting until consume read flow (i.e. blocks) is actually done processing blocks..."}
{"level":"info","ts":1613751208.8337512,"logger":"mindreader","caller":"operator/operator.go:190","msg":"operator terminating, ending run/loop"}
{"level":"info","ts":1613751208.8337662,"logger":"mindreader","caller":"operator/operator.go:262","msg":"received operator command","command":"maintenance","params":null}
{"level":"info","ts":1613751208.8337796,"logger":"mindreader","caller":"operator/operator.go:265","msg":"preparing to stop process"}
{"level":"info","ts":1613751208.8337917,"logger":"mindreader","caller":"superviser/superviser.go:166","msg":"supervisor received a stop request"}
{"level":"info","ts":1613751208.8337991,"logger":"mindreader","caller":"superviser/superviser.go:174","msg":"stopping underlying process"}
{"level":"error","ts":1613751208.833777,"logger":"dfuse","caller":"launcher/launcher.go:174","msg":"\n################################################################\nFatal error in app mindreader:\n\narchiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files\n################################################################\n"}
{"level":"info","ts":1613751208.8338869,"logger":"dfuse","caller":"cli/start.go:164","msg":"Application mindreader shutdown unexpectedly, quitting"}
{"level":"info","ts":1613751208.8341792,"logger":"mindreader","caller":"log_plugin/to_zap_log_plugin.go:119","msg":"info  2021-02-19T16:13:28.834 nodeos    net_plugin.cpp:3515           plugin_shutdown      ] shutdown.."}
{"level":"info","ts":1613751208.834215,"logger":"mindreader","caller":"log_plugin/to_zap_log_plugin.go:119","msg":"info  2021-02-19T16:13:28.834 nodeos    net_plugin.cpp:3532           plugin_shutdown      ] close 1 connections"}
{"level":"info","ts":1613751208.8342638,"logger":"mindreader","caller":"log_plugin/to_zap_log_plugin.go:119","msg":"info  2021-02-19T16:13:28.834 net-0     net_plugin.cpp:943            _close               ] closing '172.17.116.158:2221', 172.17.116.158:2221"}
{"level":"info","ts":1613751208.8343852,"logger":"abicodec","caller":"abicodec/syncer.go:74","msg":"terminating syncer via shutter"}
{"level":"info","ts":1613751208.8349257,"logger":"dgraphql","caller":"dgraphql/http.go:110","msg":"sending stop signal to HTTP server"}
{"level":"info","ts":1613751208.8350377,"logger":"abicodec","caller":"abicodec/backuper.go:53","msg":"terminating backup via shutter"}
{"level":"info","ts":1613751208.8350608,"logger":"abicodec","caller":"abicodec/syncer.go:83","msg":"abi codec stream abi changes","error":"search stream terminated with error: context canceled"}
{"level":"info","ts":1613751208.835219,"logger":"blockmeta","caller":"bstream/eternalsource.go:125","msg":"eternal source failed","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8352358,"logger":"blockmeta","caller":"bstream/eternalsource.go:128","msg":"sleeping before restarting underlying source","wait_time":2}
{"level":"info","ts":1613751208.8352492,"logger":"blockmeta.js.live","caller":"blockstream/source.go:154","msg":"source shutting down","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.83537,"logger":"eosws.hub.js.live","caller":"blockstream/source.go:154","msg":"source shutting down","error":"rpc error: code = Canceled desc = context canceled"}
{"level":"info","ts":1613751208.8355148,"logger":"bstream","caller":"bstream/eternalsource.go:125","msg":"eternal source failed","error":"live source failed: rpc error: code = Canceled desc = context canceled"}
{"level":"info","ts":1613751208.8355274,"logger":"bstream","caller":"bstream/eternalsource.go:128","msg":"sleeping before restarting underlying source","wait_time":2}
{"level":"info","ts":1613751208.8357668,"logger":"relayer","caller":"blockstream/server.go:234","msg":"unsubscribed","new_length":5}
{"level":"info","ts":1613751208.8361373,"logger":"mindreader","caller":"log_plugin/to_zap_log_plugin.go:119","msg":"info  2021-02-19T16:13:28.834 nodeos    net_plugin.cpp:3552           plugin_shutdown      ] exit shutdown"}
{"level":"info","ts":1613751208.836167,"logger":"mindreader","caller":"log_plugin/to_zap_log_plugin.go:119","msg":"info  2021-02-19T16:13:28.834 nodeos    chain_plugin.cpp:1259         plugin_shutdown      ] chain shutdown"}
{"level":"info","ts":1613751208.836376,"logger":"relayer","caller":"blockstream/server.go:234","msg":"unsubscribed","new_length":4}
{"level":"info","ts":1613751208.8373,"logger":"accounthist","caller":"grpc/server.go:79","msg":"gRPC server teminated gracefully"}
{"level":"info","ts":1613751208.8373196,"logger":"accounthist","caller":"injector/injector.go:106","msg":"accounthist service has been shutdown, about to terminate child services"}
{"level":"info","ts":1613751208.837329,"logger":"accounthist","caller":"injector/injector.go:98","msg":"accounthist service is shutting down down, shutting down block source"}
{"level":"info","ts":1613751208.837337,"logger":"accounthist","caller":"injector/injector.go:93","msg":"block source is shutting down, notifying service about its termination"}
{"level":"info","ts":1613751208.8373427,"logger":"accounthist","caller":"injector/injector.go:106","msg":"accounthist service has been shutdown, about to terminate child services"}
{"level":"error","ts":1613751208.8373709,"logger":"search-router","caller":"router/router.go:227","msg":"router terminated with error","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.837417,"logger":"merger","caller":"merger/merger.go:237","msg":"merger exited","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8374357,"logger":"relayer","caller":"relayer/relayer.go:313","msg":"shutting down source"}
{"level":"info","ts":1613751208.8374634,"logger":"relayer","caller":"relayer/relayer.go:316","msg":"closing block stream server"}
{"level":"info","ts":1613751208.8376408,"logger":"search-archive","caller":"archive/app.go:231","msg":"archive application is terminating, shutting down archive backend"}
{"level":"info","ts":1613751208.8376703,"logger":"search-archive","caller":"archive/backend.go:255","msg":"shutting down search archive","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8376796,"logger":"search-archive","caller":"archive/backend.go:281","msg":"cleaning up archive backend","shutdown_delay":0}
{"level":"info","ts":1613751208.8376913,"logger":"search-archive","caller":"archive/backend.go:299","msg":"gracefully shutting down http server, draining connections"}
{"level":"error","ts":1613751208.8377259,"logger":"search-forkresolver","caller":"forkresolver/forkresolver.go:117","msg":"search forkresolver terminated with error","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8377597,"logger":"search-indexer","caller":"indexer/indexer.go:271","msg":"shutting down indexer's source"}
{"level":"info","ts":1613751208.8377836,"logger":"search-indexer","caller":"indexer/indexer.go:273","msg":"shutting down indexer","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8377905,"logger":"search-indexer","caller":"indexer/indexer.go:296","msg":"cleaning up indexer"}
{"level":"info","ts":1613751208.8377964,"logger":"search-indexer","caller":"indexer/indexer.go:299","msg":"waiting on uploads"}
{"level":"info","ts":1613751208.8378143,"logger":"search-live","caller":"live/backend.go:71","msg":"shutting down search live","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8378222,"logger":"search-live","caller":"live/backend.go:126","msg":"setting search peer "}
{"level":"info","ts":1613751208.8378296,"logger":"search-live","caller":"live/backend.go:132","msg":"shutting down live search, setting ready flag to false","shutdown_delay":0}
{"level":"info","ts":1613751208.8378496,"logger":"relayer","caller":"bstream/eternalsource.go:125","msg":"eternal source failed","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8378572,"logger":"relayer","caller":"bstream/eternalsource.go:128","msg":"sleeping before restarting underlying source","wait_time":2}
{"level":"info","ts":1613751208.8378658,"logger":"relayer.src.13010","caller":"blockstream/source.go:154","msg":"source shutting down"}
{"level":"info","ts":1613751208.837975,"logger":"relayer","caller":"blockstream/server.go:234","msg":"unsubscribed","new_length":3}
{"level":"info","ts":1613751208.8380294,"logger":"relayer","caller":"blockstream/server.go:234","msg":"unsubscribed","new_length":2}
{"level":"info","ts":1613751208.8380716,"logger":"relayer","caller":"blockstream/server.go:234","msg":"unsubscribed","new_length":1}
{"level":"info","ts":1613751208.8381448,"logger":"relayer","caller":"blockstream/server.go:234","msg":"unsubscribed","new_length":0}
{"level":"info","ts":1613751208.83818,"logger":"search-archive","caller":"archive/backend.go:263","msg":"archive backend terminated"}
{"level":"info","ts":1613751208.838193,"logger":"search-indexer","caller":"bstream/eternalsource.go:125","msg":"eternal source failed","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8382006,"logger":"search-indexer","caller":"bstream/eternalsource.go:128","msg":"sleeping before restarting underlying source","wait_time":2}
{"level":"info","ts":1613751208.838215,"logger":"search-indexer.js.live","caller":"blockstream/source.go:154","msg":"source shutting down","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"error","ts":1613751208.8382936,"logger":"search-live","caller":"live/backend.go:117","msg":"search live terminated with error","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8383665,"logger":"mindreader","caller":"blockstream/server.go:234","msg":"unsubscribed","new_length":0}
{"level":"info","ts":1613751208.8385546,"logger":"statedb","caller":"bstream/eternalsource.go:125","msg":"eternal source failed","error":"live source failed: rpc error: code = Unavailable desc = transport is closing"}
{"level":"info","ts":1613751208.8385699,"logger":"statedb","caller":"bstream/eternalsource.go:128","msg":"sleeping before restarting underlying source","wait_time":2}
{"level":"info","ts":1613751208.83867,"logger":"tokenmeta","caller":"bstream/eternalsource.go:125","msg":"eternal source failed","error":"live source failed: rpc error: code = Unavailable desc = transport is closing"}
{"level":"info","ts":1613751208.838679,"logger":"tokenmeta","caller":"bstream/eternalsource.go:128","msg":"sleeping before restarting underlying source","wait_time":2}
{"level":"info","ts":1613751208.8389251,"logger":"statedb.js.live","caller":"blockstream/source.go:154","msg":"source shutting down","error":"rpc error: code = Unavailable desc = transport is closing"}
{"level":"info","ts":1613751208.838955,"logger":"tokenmeta.js.live","caller":"blockstream/source.go:154","msg":"source shutting down","error":"rpc error: code = Unavailable desc = transport is closing"}
{"level":"info","ts":1613751208.8391995,"logger":"trxdb-loader.js.live","caller":"blockstream/source.go:154","msg":"source shutting down","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8392224,"logger":"statedb","caller":"server/server.go:82","msg":"gracefully shutting down http server, draining connections"}
{"level":"info","ts":1613751208.839229,"logger":"statedb","caller":"server/server.go:84","msg":"allowing fluxdb server to gracefully shuts down without interrupting any active connections"}
{"level":"info","ts":1613751208.8392649,"logger":"tokenmeta","caller":"tokenmeta/tokenmeta.go:73","msg":"source is done"}
{"level":"info","ts":1613751208.839272,"logger":"tokenmeta","caller":"tokenmeta/tokenmeta.go:75","msg":"export cache"}
{"level":"info","ts":1613751208.8392782,"logger":"tokenmeta","caller":"cache/default_cache.go:110","msg":"trying to save to token cache file","filename":"/data/dfuseeos/dfuse-data/tokenmeta/token-cache.gob","temp_filename":"/data/dfuseeos/dfuse-data/tokenmeta/token-cache.gob.tmp"}
{"level":"error","ts":1613751208.839645,"logger":"tokenmeta","caller":"tokenmeta/tokenmeta.go:82","msg":"source shutdown with error","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.8396819,"logger":"trxdb-loader","caller":"bstream/eternalsource.go:125","msg":"eternal source failed","error":"archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}
{"level":"info","ts":1613751208.83969,"logger":"trxdb-loader","caller":"bstream/eternalsource.go:128","msg":"sleeping before restarting underlying source","wait_time":2}
{"level":"error","ts":1613751208.841975,"logger":"common","caller":"derr/cli.go:25","msg":"dfuse","error":"unable to launch: archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002257/0002257182-20210219T161329.0-2206ae27-be9aceaa.dat.temp: too many open files"}

After restarting, the log is as follows, observe that the synchronization is normal

invalid range (router/router.go:151){"trace_id": "c9664d3e7d2cc12620017a222410df4a", "router_request": {"query":"receiver:fscio action:setabi notif:false","lowBlockNum":1,"highBlockUnbounded":true,"cursor":"1:59::f3d3bb6589ff","withReversible":true,"liveMarkerInterval":1}, "head_block": 0, "irr_block": 0, "error": "rpc error: code = InvalidArgument desc = invalid low block num: it goes beyond the current head block, use `-1` for to follow the HEAD (requested: 0, head: 0)"}
found a hole in a oneblock files (merger/bundle.go:84){"bundle_lower_block": 2257100, "missing_block_num": 2257182, "missing_block_id": "2206ae27"}

But after continuing to synchronize for a period of time, the dfuseeos node exits again, the log is as follows

found a hole in a oneblock files (merger/bundle.go:84){"bundle_lower_block": 2257100, "missing_block_num": 2257182, "missing_block_id": "2206ae27"}
temporary failure trying to upload mindreader merged block files, will retry (mindreader/merge_archiver.go:70){"error": "moving file \"/data/dfuseeos/dfuse-data/mindreader/work/0002566700.merged\" to storage: writing \"/data/dfuseeos/dfuse-data/mindreader/work/0002566700.merged\" to storage \"/data/dfuseeos/dfuse-data/storage/merged-blocks/0002566700.dbin.zst\": unable to create file \"/data/dfuseeos/dfuse-data/storage/merged-blocks/0002566700.dbin.zst.tmp\": open /data/dfuseeos/dfuse-data/storage/merged-blocks/0002566700.dbin.zst.tmp: too many open files"}
failed storing block in archiver, shutting down and losing blocks in transit... (mindreader/mindreader.go:265){"error": "open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002566900.merged.temp: too many open files"}

################################################################
Fatal error in app mindreader:

archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002566900.merged.temp: too many open files
################################################################
 (launcher/launcher.go:174)
Application mindreader shutdown unexpectedly, quitting
dfuse (derr/cli.go:25){"error": "unable to launch: archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002566900.merged.temp: too many open files"}
router terminated with error (router/router.go:227){"error": "archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002566900.merged.temp: too many open files"}
search forkresolver terminated with error (forkresolver/forkresolver.go:117){"error": "archiver store block failed: open file: open /data/dfuseeos/dfuse-data/mindreader/work/0002566900.merged.temp: too many open files"}

Activity

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions