The testnet runs for a long time and dfuseeos exits

cppfuns commented 3 years ago

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"}

matthewdarwin commented 3 years ago

error is "too many open files". Increase the number of files you allow open with the "ulimit" command.

cppfuns commented 3 years ago

error is "too many open files". Increase the number of files you allow open with the "ulimit" command.

Surou:~$ ulimit -a
core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
scheduling priority             (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 63982
max locked memory       (kbytes, -l) 65536
max memory size         (kbytes, -m) unlimited
open files                      (-n) 65535
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
real-time priority              (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 63982
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited

open files (-n) 65535 The current setting is 65535. Does it mean that this value is not enough? The current server only runs dfuseeos

cppfuns commented 3 years ago

Will this "open files" be continuously accumulatively occupied or consumed? I am currently modifying it to 655350. After observing for a period of time, the test transfer pressure during my test chain is constant. I don't know if this "open files" keeps occupying more and more, will there be a problem. If the default value of the system is not enough to support the operation of dfuseeos, should you give a default value check prompt, or open the order of magnitude at the lower limit of the given parameter?

dfuse-io / dfuse-eosio