Firehose crashes every 25min w/ SeaweedFS S3 server

[aasseman]

Using:

• firehose-ethereum:v1.4.4-geth-v1.12.0-fh2.2
• chrislusf/seaweedfs:3.57 (though the issue was happening for many versions prior, didn't keep track)

Chain of events:

• The firehose would work full speed for ~25 minutes. No error messages on either side.
• After 25 minutes, the firehose would stop serving historical data, only serves last blocks. CPU usage falls to almost 0. SeaweedFS logs many errors like this:

  I0927 20:02:47.092092 filechunk_manifest.go:197 read http://127.0.0.1:8080/81883,cbbda166b6a42e failed, err: read tcp 
  127.0.0.1:44244->127.0.0.1:8080: read: connection reset by peer
  I0927 20:02:47.092110 filechunk_manifest.go:203 retry reading in 1s

  Then like that:

  E0927 20:02:48.650523 common.go:297 processRangeRequest: read chunk: http://127.0.0.1:8080/82254,cd85ecc70c87fe?readDeleted=true: 500 Internal Server Error
  2023/09/27 20:02:48 http: superfluous response.WriteHeader call from github.com/seaweedfs/seaweedfs/weed/server.processRangeRequest (common.go:298)
  E0927 20:02:48.650636 filer_server_handlers_read.go:259 failed to stream content /buckets/fireeth-merged-blocks/0014719400.dbin.zst: read chunk: http://127.0.0.1:8080/82253,cd85a91873c7d3?readDeleted=true: 500 Internal Server Error

• After ~5min, the Firehose finally crashes with:

  2023-09-27T12:50:01.846-0400 INFO (firehose) blocks archive streaming was asked to stop {"trace_id": "e98af87e6fe0eb6088a82cdc239ba4df"}
  2023-09-27T12:50:01.847-0400 DEBG (firehose) source shutting down {"trace_id": "e98af87e6fe0eb6088a82cdc239ba4df", "error": "processing of file \"0013351400\" failed: error processing incoming file: failed reading next dbin message: unexpected literal count, want 92 bytes, but only 61 is available"}
  2023-09-27T12:50:01.847-0400 INFO (firehose) firehose process completed {"trace_id": "e98af87e6fe0eb6088a82cdc239ba4df", "error": "processing of file \"0013351400\" failed: error processing incoming file: failed reading next dbin message: unexpected literal count, want 92 bytes, but only 61 is available"}
  2023-09-27T12:50:01.847-0400 INFO (firehose) unexpected stream of blocks termination {"trace_id": "e98af87e6fe0eb6088a82cdc239ba4df", "error": "processing of file \"0013351400\" failed: error processing incoming file: failed reading next dbin message: unexpected literal count, want 92 bytes, but only 61 is available"}
  2023-09-27T12:50:01.847-0400 ERRO (firehose) finished streaming call with code Internal {"grpc.start_time": "2023-09-27T12:38:43-04:00", "system": "grpc", "span.kind": "server", "grpc.service": "sf.firehose.v2.Stream", "grpc.method": "Blocks", "peer.address": "10.0.0.129:44700", "error": "rpc error: code = Internal desc = unexpected stream termination", "grpc.code": "Internal", "grpc.time_ms": 678650.8125}
  2023-09-27T12:50:02.449-0400 INFO (firehose) processing incoming blocks request {"trace_id": "d45dd5e0349bad9fa9f4032c86ff8328", "req_start_block": 14676216, "req_cursor": "TvEQnm9CXPwCG67Os7-AwqWwLpc_DFtrUwzjKBdEj473oiOW35muUTcnbUnTk6n21Ba_TVL4iNyfF3gu98lTvYW_wbxj6nI_T3N-kYy__-K5ePbwO1wYcrpgWbyGM4rRWjjRZQz5fLQK5dS1a6DbY0pjNJUjeGWwjzlZodFSePdHuiE2xWn4eszThK6U9YVGrOUsTLajkHqnUWN9KU1Ya8-BZvCZ6TRxNw==", "req_stop_block": 0, "final_blocks_only": false, "with_index_provider": true, "transform_desc": "Combined filter: Calls:[], Logs:[{addrs: 0x7f2722741f997c63133e656a70ae5ae0614ad7f5,0x92e0d1ca2de2c8c7a11e27c4494024aa6f9e9...}], SendAllBlockHeaders: false"}
  2023-09-27T12:50:02.449-0400 DEBG (firehose) setting up firehose source {"trace_id": "d45dd5e0349bad9fa9f4032c86ff8328"}
  2023-09-27T12:50:02.449-0400 INFO (firehose) creating new joining source {"trace_id": "d45dd5e0349bad9fa9f4032c86ff8328", "cursor": "c1:17:14676265:51bac248afb5d330693d68df3b36e5931de2477c798b25a4ff0522f33126f8ab:14676265:51bac248afb5d330693d68df3b36e5931de2477c798b25a4ff0522f33126f8ab", "start_block_num": 14676216}
  2023-09-27T12:50:02.449-0400 DEBG (bstream) error getting source_from_cursor {"error": "complete segment does not include cursor LIB (lowest block: 18228000, cursor lib: 14676265)"}
  2023-09-27T12:50:02.450-0400 DEBG (bstream) couldn't open index from dstore {"error": "s3 open object (1 attempts, buffered_read: false): not found", "filename": "0014600000.100000.combined.idx"}
  2023-09-27T12:50:07.628-0400 INFO (firehose) processing incoming blocks request {"trace_id": "d98c6504fe2b4a458cab3d10b4509fc7", "req_start_block": 18228360, "req_cursor": "", "req_stop_block": 18228360, "final_blocks_only": false}
  2023-09-27T12:50:07.629-0400 DEBG (firehose) setting up firehose source {"trace_id": "d98c6504fe2b4a458cab3d10b4509fc7"}
  2023-09-27T12:50:07.629-0400 INFO (firehose) creating new joining source {"trace_id": "d98c6504fe2b4a458cab3d10b4509fc7", "cursor": "<nil>", "start_block_num": 18228360}
  2023-09-27T12:50:07.656-0400 DEBG (firehose) stream sent block {"trace_id": "d98c6504fe2b4a458cab3d10b4509fc7", "block": "#18228360 (082ff7255d20bdaef18a59afc9dc7c8e5fb22fa07456c1f5de1e121d834ab20d)", "duration": "17.017034ms"}
  2023-09-27T12:50:07.656-0400 DEBG (firehose) source shutting down {"trace_id": "d98c6504fe2b4a458cab3d10b4509fc7", "error": "stop block reached"}
  2023-09-27T12:50:07.656-0400 INFO (firehose) firehose process completed {"trace_id": "d98c6504fe2b4a458cab3d10b4509fc7", "error": "stop block reached"}
  2023-09-27T12:50:07.656-0400 INFO (firehose) stream of blocks reached end block {"trace_id": "d98c6504fe2b4a458cab3d10b4509fc7"}
  2023-09-27T12:50:07.656-0400 DEBG (firehose) finished streaming call with code OK {"grpc.start_time": "2023-09-27T12:50:07-04:00", "system": "grpc", "span.kind": "server", "grpc.service": "sf.firehose.v2.Stream", "grpc.method": "Blocks", "peer.address": "10.0.0.129:44700", "grpc.code": "OK", "grpc.time_ms": 27.53700065612793}
  2023-09-27T12:50:09.077-0400 INFO (firehose) blocks archive streaming was asked to stop {"trace_id": "6befdd868c074d9f22192f3255e2156b"}
  2023-09-27T12:50:09.077-0400 DEBG (firehose) source shutting down {"trace_id": "6befdd868c074d9f22192f3255e2156b", "error": "processing of file \"0016651000\" failed: error processing incoming file: failed reading next dbin message: tableLog too large"}
  2023-09-27T12:50:09.077-0400 INFO (firehose) firehose process completed {"trace_id": "6befdd868c074d9f22192f3255e2156b", "error": "processing of file \"0016651000\" failed: error processing incoming file: failed reading next dbin message: tableLog too large"}
  2023-09-27T12:50:09.079-0400 INFO (firehose) unexpected stream of blocks termination {"trace_id": "6befdd868c074d9f22192f3255e2156b", "error": "processing of file \"0016651000\" failed: error processing incoming file: failed reading next dbin message: tableLog too large"}
  2023-09-27T12:50:09.080-0400 ERRO (firehose) finished streaming call with code Internal {"grpc.start_time": "2023-09-27T12:41:40-04:00", "system": "grpc", "span.kind": "server", "grpc.service": "sf.firehose.v2.Stream", "grpc.method": "Blocks", "peer.address": "10.0.0.129:44700", "error": "rpc error: code = Internal desc = unexpected stream termination", "grpc.code": "Internal", "grpc.time_ms": 508598.59375}
  panic: unable to decode block #16651067 (fb80c53f0b9ad8a026d21cf9aab801e42ea6db209de86053fead6a751f8f6477) payload (kind: ETH, version: 3, size: 1047315, sha256: 0614c58482dfdd1ebfd10abda656531bd8b81e15852dc54138ad8e0f592e9f3c): unable to decode payload: proto: cannot parse invalid wire-format data
  
  Payload: [OMITTING HUGE LINE OF BINARY DATA]
  
  goroutine 345531 [running]:
  github.com/streamingfast/bstream.(*Block).ToProtocol(0xc02376c500)
  /home/runner/go/pkg/mod/github.com/streamingfast/bstream@v0.0.2-0.20230510131449-6b591d74130d/block.go:246 +0x6e9
  github.com/streamingfast/firehose-ethereum/transform.(*CombinedFilter).Transform(0xc0003b05f8?, 0x681d52?, {0x64c0f1?, 0x3476c60?})
  /home/runner/work/firehose-ethereum/firehose-ethereum/transform/combined_filter.go:185 +0x36
  github.com/streamingfast/bstream/transform.(*Registry).BuildFromTransforms.func1(0xc01fe9be00)
  /home/runner/go/pkg/mod/github.com/streamingfast/bstream@v0.0.2-0.20230510131449-6b591d74130d/transform/builder.go:82 +0x1d3
  github.com/streamingfast/bstream.(*FileSource).preprocess(0xc001bcf5c0, 0xc01fe9be00, 0xc0404bb860)
  /home/runner/go/pkg/mod/github.com/streamingfast/bstream@v0.0.2-0.20230510131449-6b591d74130d/filesource.go:506 +0x5b
  created by github.com/streamingfast/bstream.(*FileSource).streamReader
  /home/runner/go/pkg/mod/github.com/streamingfast/bstream@v0.0.2-0.20230510131449-6b591d74130d/filesource.go:495 +0x68a

• Firehose restarts, and works normally again for ~25min.

[maoueh]

@aasseman Do you run with DSTORE_S3_BUFFERED_READ=true or not? If not, could you try with it and see if it makes a difference?

The Seaweed logs shows http://127.0.0.1:8080 in your setup, what is this pointing to?

[aasseman]

@aasseman Do you run with DSTORE_S3_BUFFERED_READ=true or not? If not, could you try with it and see if it makes a difference?

I've never heard of it before, it's not listed when I run fireeth start --help. Is there a list for those extra options somewhere? I tried it and it worked! Ran for 3 hours without a crash!

The Seaweed logs shows http://127.0.0.1:8080 in your setup, what is this pointing to?

This is the address of what they call the "filer". Since I'm running SeaweedFS in the simplest form possible (single container), it spawns all of its components in it, that's why it shows as localhost.

[matthewdarwin]

I did mention this when we were discussing setting up S3: https://discord.com/channels/438038660412342282/877310167060971550/1075618323594743858

[aasseman]

I did mention this when we were discussing setting up S3: https://discord.com/channels/438038660412342282/877310167060971550/1075618323594743858

Indeed, I didn't catch it back then... Still, it'd be nice to have it all in one place (in --help for ex) with explanations. I still don't know what DSTORE_S3_BUFFERED_READ exactly means apart from the fact that now my firehose works :shrug:

[maoueh]

DSTORE_S3_BUFFERED_READ reads everything in memory and then act as a io.Reader interface while the normal operation is to expose the request as a io.Reader which "streams" from the HTTP request directly.

The DSTORE_S3_BUFFERED_READ increases memory usage since the full file is held in memory. It seems we have a problem with "streaming" in the S3 implementation, the same kind of weird errors has been reported on other providers.

[maoueh]

Indeed, I didn't catch it back then... Still, it'd be nice to have it all in one place (in --help for ex) with explanations.

I don't the --help would be a good place for this sadly, the options applies to a lot of flags. But there should be a least a mention of the page where all options are listed.

[aasseman]

Thanks @maoueh ! DSTORE_S3_BUFFERED_READ=true is a good workaround for me for now. I see that you opened an issue to tackle the underlying bug, so I think I can close this one.