dfuse-eosio
dfuse-eosio copied to clipboard
The testnet runs for a long time and dfuseeos exits
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"}
error is "too many open files". Increase the number of files you allow open with the "ulimit" command.
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
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?