Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
cppfuns opened this issue Feb 22, 2021 · 3 comments
Open

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

cppfuns opened this issue Feb 22, 2021 · 3 comments

Comments

@cppfuns
Copy link

cppfuns commented Feb 22, 2021

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
Copy link

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

@cppfuns
Copy link
Author

cppfuns commented Feb 22, 2021

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
Copy link
Author

cppfuns commented Feb 22, 2021

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?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants