search

streamingfast / firehose-ethereum

Ethereum on StreamingFast
Apache License 2.0
79 stars 24 forks source link

merger reads files 1 one thread and deletes them in a another thread? #12

Closed matthewdarwin closed 2 years ago

matthewdarwin commented 2 years ago

race condition? merger reads files 1 one thread and deletes them in a another thread?

################################################################
Fatal error in app merger:
retreiving one block files: fetching one block files: processing object list: unable to read one block: 0014255900-20220110T225705.0-24f2e12c-ed760311-dom25:unable to read file header: EOF
################################################################
(launcher/launcher.go:174)
maoueh commented 2 years ago

We got the same error today when upgrading our eth-mainnet namespace, here our logs:

[2022-01-10 14:17:41.159 EST] INFO (dtracing@v0.0.0-20210811175635-d55665d3622a/api.go:139) registering development exporters from environment variables {"logger":"common"}
[2022-01-10 14:17:41.159 EST] INFO (cli/start.go:50) Starting with config file '' {"logger":"dfuse"}
[2022-01-10 14:17:41.160 EST] INFO (cli/start.go:124) Launching applications: merger {"logger":"dfuse"}
[2022-01-10 14:17:41.160 EST] INFO (merger/app.go:60) running merger {"config":{"GRPCListenAddr":":9000","MaxOneBlockOperationsBatchSize":2000,"NextExclusiveHighestBlockLimit":0,"OneBlockDeletionThreads":10,"StateFile":"/data/merger.seen.gob","StorageMergedBlocksFilesPath":"gs://dfuseio-global-blocks-us/eth-mainnet/v5","StorageOneBlockFilesPath":"gs://dfuseio-global-blocks-us/eth-mainnet/v5-oneblock","TimeBetweenStoreLookups":5000000000,"WritersLeewayDuration":20000000000},"logger":"merger"}
[2022-01-10 14:17:41.166 EST] WARNING (merger/app.go:88) failed to load bundle  {"file_name":"/data/merger.seen.gob","logger":"merger"}
[2022-01-10 14:17:43.088 EST] INFO (bundle/bundler.go:25) new bundler {"bundle_size":100,"first_exclusive_highest_block_limit":13979400,"logger":"merger"}
[2022-01-10 14:17:43.088 EST] INFO (bundle/bundler.go:64) fetching one block files {"at_low_block_num":13979300,"logger":"merger"}
[2022-01-10 14:17:43.624 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:244) Processed, already existing merged file {"highest_block":13979399,"logger":"merger","lower_block":0}
[2022-01-10 14:17:43.625 EST] INFO (bundle/bundler.go:73) found lib to reach {"lib_block_num":18446744073709552000,"logger":"merger"}
[2022-01-10 14:17:43.625 EST] INFO (bundle/bundler.go:83) processed one block files {"at_low_block_num":13979300,"lib_num_to_reach":13979199,"logger":"merger"}
[2022-01-10 14:17:43.625 EST] INFO (bundle/bundler.go:64) fetching one block files {"at_low_block_num":13979200,"logger":"merger"}
[2022-01-10 14:17:44.218 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:244) Processed, already existing merged file {"highest_block":13979299,"logger":"merger","lower_block":0}
[2022-01-10 14:17:44.218 EST] INFO (bundle/bundler.go:83) processed one block files {"at_low_block_num":13979200,"lib_num_to_reach":13979199,"logger":"merger"}
[2022-01-10 14:17:44.218 EST] INFO (bundle/bundler.go:64) fetching one block files {"at_low_block_num":13979100,"logger":"merger"}
[2022-01-10 14:17:44.697 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:244) Processed, already existing merged file {"highest_block":13979199,"logger":"merger","lower_block":0}
[2022-01-10 14:17:44.697 EST] INFO (merger/app.go:130) merger initiated {"logger":"merger"}
[2022-01-10 14:17:44.698 EST] INFO (merger/app.go:144) merger running {"logger":"merger"}
[2022-01-10 14:17:44.698 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger.go:73) starting merger {"bundle":"bundle_size: 100, last_merge_block_num: 0, inclusive_lower_block_num: 13979300, exclusive_highest_block_limit: 13979400","logger":"merger"}
[2022-01-10 14:17:44.698 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/server.go:20) grpc server created {"logger":"merger"}
[2022-01-10 14:17:44.698 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/server.go:27) tcp listener created {"logger":"merger"}
[2022-01-10 14:17:44.698 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/server.go:31) server registered {"logger":"merger"}
[2022-01-10 14:17:44.698 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/server.go:34) listening & serving grpc content {"grpc_listen_addr":":9000","logger":"merger"}
[2022-01-10 14:17:45.161 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:244) Processed, already existing merged file {"highest_block":13979399,"logger":"merger","lower_block":0}
[2022-01-10 14:17:51.164 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:101) retrieved list of files {"files_count":196,"logger":"merger"}
[2022-01-10 14:17:51.169 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger.go:179) retrieved list of files {"added_files_count":196,"logger":"merger","too_old_files_count":0}
[2022-01-10 14:17:51.169 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger.go:107) one block retrieved {"last_block_file":13979579,"logger":"merger"}
[2022-01-10 14:17:51.199 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger.go:128) merging bundle {"bundle":"bundle_size: 100, last_merge_block_num: 13979399, inclusive_lower_block_num: 13979400, exclusive_highest_block_limit: 13979500","highest_bundle_block_num":13979499,"logger":"merger"}
[2022-01-10 14:17:54.592 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:51) merged and uploaded {"filename":"0013979400","logger":"merger","merge_time":3.392849938}
[2022-01-10 14:17:54.593 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger.go:141) bundle merged and committed {"bundle":"bundle_size: 100, last_merge_block_num: 13979499, inclusive_lower_block_num: 13979500, exclusive_highest_block_limit: 13979600","last_merge_one_block_time":"2022-01-10T19:01:11Z","logger":"merger"}
[2022-01-10 14:17:54.593 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger.go:144) saving state {"logger":"merger","state":"exclusive_highest_block_limit: 13979600"}
[2022-01-10 14:17:54.595 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:165) deleting files that are too old or already seen {
  "first_file": "0013979275-20220110T180635.0-e63ac982-790b114c-13979075-generated",
  "last_file": "0013979497-20220110T190023.0-b94a8d69-bb30a7c6-13979297-default",
  "logger": "merger",
  "number_of_files": 328
}
[2022-01-10 14:17:54.930 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979284-20220110T180848.0-cad9d043-d8fbaf51-13979084-generated","logger":"merger"}
[2022-01-10 14:17:54.930 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979315-20220110T181559.0-9fe877c6-b056f2f4-13979115-generated","logger":"merger"}
[2022-01-10 14:17:54.932 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979367-20220110T182702.0-e0d7dddc-a893b78e-13979167-generated","logger":"merger"}
[2022-01-10 14:17:54.935 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979275-20220110T180635.0-e63ac982-790b114c-13979075-generated","logger":"merger"}
[2022-01-10 14:17:54.937 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979244-20220110T180019.0-636c426e-02332c7e-13979044-generated","logger":"merger"}
[2022-01-10 14:17:54.938 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979239-20220110T175921.0-ba841eb3-6b1227cf-13979039-generated","logger":"merger"}
[2022-01-10 14:17:54.938 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979341-20220110T182041.0-e98e20f0-488bdc95-13979141-generated","logger":"merger"}
[2022-01-10 14:17:54.939 EST] WARNING (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:205) cannot delete oneblock file after a few retries {"error":"storage: object doesn't exist","file":"0013979355-20220110T182336.0-614baa8d-dae5910e-13979155-generated","logger":"merger"}
[2022-01-10 14:17:55.150 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger_io.go:101) retrieved list of files {"files_count":9,"logger":"merger"}
[2022-01-10 14:17:55.150 EST] INFO (merger@v0.0.3-0.20211210145453-1cc2fa8425ea/merger.go:78) merger exited {"error":"retreiving one block files: fetching one block files: unable to read one block: 0013979408-20220110T183754.0-0b371194-51245564:unable to read file header: EOF","logger":"merger"}
[2022-01-10 14:17:55.150 EST] ERROR (launcher/launcher.go:174)
################################################################
Fatal error in app merger:

retreiving one block files: fetching one block files: unable to read one block: 0013979408-20220110T183754.0-0b371194-51245564:unable to read file header: EOF
################################################################
 {"context":{"reportLocation":{"filePath":"/work/go/pkg/mod/github.com/streamingfast/dlauncher@v0.0.0-20211210162313-cf4aa5fc4878/launcher/launcher.go","functionName":"github.com/streamingfast/dlauncher/launcher.(*Launcher).shutdownDueToApp.func1","lineNumber":"174"}},"logger":"dfuse"}
[2022-01-10 14:17:55.150 EST] INFO (cli/start.go:140) Application merger shutdown unexpectedly, quitting {"logger":"dfuse"}
[2022-01-10 14:17:55.150 EST] INFO (launcher/launcher.go:259) Waiting for all apps termination... {"logger":"dfuse"}
[2022-01-10 14:17:55.150 EST] INFO (launcher/launcher.go:273) All apps terminated gracefully {"logger":"dfuse"}
Error: unable to launch: retreiving one block files: fetching one block files: unable to read one block: 0013979408-20220110T183754.0-0b371194-51245564:unable to read file header: EOF
[2022-01-10 14:17:55.150 EST] ERROR (derr@v0.0.0-20210811180100-9138d738bcec/cli.go:25) dfuse {"context":{"reportLocation":{"filePath":"/work/go/pkg/mod/github.com/streamingfast/derr@v0.0.0-20210811180100-9138d738bcec/cli.go","functionName":"github.com/streamingfast/derr.Check","lineNumber":"25"}},"error":"unable to launch: retreiving one block files: fetching one block files: unable to read one block: 0013979408-20220110T183754.0-0b371194-51245564:unable to read file header: EOF","logger":"common"}

@billettc @froch

maoueh commented 2 years ago

This was a false error, it actually a case of bad handling of end of file.