Subgraph syncing "old cursor" error

[YaroShkvorets]

Moving this here from Slack discussion.

When syncing on hosted service, getting this error from time to time:

Text:

INFO
2023-03-22 09:37:16 a.m.
Blockstreams connected, component: SubstreamsBlockStream
INFO
2023-03-22 09:37:16 a.m.
Blockstreams disconnected, connecting, cursor: -_zKZlp9K6Q-AAhrtI2lqqWwLpcyB1xnXQjmKRdLgtnxonXH2siuVWNyPhuEkKv3iBTvTQ6qj93KQn9498EGvoTjxr9i6Sc_FCp9loi9-Oa6e_r7PwgaI7JrX7iMYtLaXTTfYQj_c7sD4t3ka6fbMREwapQuLTXm2z9V9IJdJqsX7SZjkTv1JZ2E0qiWpIQQ-eJ2F-aiwSjyUjUuLE4LO8iBZ_GavDhz, start_block: 16870271, endpoint_uri: mainnet-substreams-sf-0, component: SubstreamsBlockStream
ERROR
2023-03-22 09:36:31 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
INFO
2023-03-22 09:36:31 a.m.
received err, component: SubstreamsBlockStream

Could be related to #195 because cursor is the same

[sduchesneau]

hi! does this error resolve itself after a while (and keeps progressing) ?

[sduchesneau]

Info:

That cursor points to: block #16883336 (0x7b7b727e8e27f6d027e146d6a27f1351f2e9576467baa51c3be399621b990b20) ( I use https://github.com/streamingfast/opaque to decode it)

the correct (canonical) hash for block 16883336 is 0xc4f41c2b55475d421e046491b2df9bd1a47b13ae8a9016ed65051347f4509e63

I see that we have the forked version of this block at streamingfast: eth-mainnet/v4-forked/0016883336-3be399621b990b20-899aa0b076a807cb-16883249-default.dbin.zst

The block 16883336 came in at 13h09 UTC (it must have been live at the time, since it is a forked block) You tried to reconnect with that cursor at 13h36 UTC.

Do you know why it took so long to reconnect ?

[sduchesneau]

I remember that, to replay from old forked blocks in substreams, we had to replay UP TO THAT WRONG BLOCK (generating the bad state...) in order send the proper "undo" data. this was never implemented in case of "old forks" (from blocks out of RAM and written to disk) because of the complexity needed in substreams codebase.

At the time, we figured that this situation would very rarely happen, because the cursor is still valid for quite a number of minutes before it becomes an "old" fork.

Do you have any insight on why it would have disconnected at 9h36 and try to reconnect with a cursor of a block from 9h09 ?

[sduchesneau]

ok, looking at the logs from #195, I see that there is another underlying error that caused it to retry multiple times and always fail accross retries, which have exponential back-off, so eventually the cursor is wrong... got it !

[YaroShkvorets]

hi! does this error resolve itself after a while (and keeps progressing) ?

Here's a list of this error events (searched by "old cursor" keywords). Seems to go away. No real pattern - could go many hours without it, then happening every couple of minutes, etc.

ERROR
2023-03-22 09:44:12 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 09:43:24 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 09:36:31 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:57:57 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:57:11 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:56:26 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:55:40 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:54:55 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:54:09 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:53:23 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:52:38 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:39:41 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 08:38:55 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:56:42 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:55:53 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:55:03 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:54:13 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:53:23 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:52:33 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:51:42 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:45:04 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:44:13 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:43:24 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:42:34 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:41:44 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:40:55 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:40:05 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:39:15 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:38:25 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:37:34 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 03:36:42 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:52:48 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:51:14 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:50:26 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:49:39 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:48:51 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:48:03 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:47:16 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:46:28 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:39:39 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:38:52 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:38:05 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:37:17 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:35:43 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:34:55 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-22 02:34:05 a.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 03:08:36 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 03:07:42 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 03:06:48 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 03:05:55 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 03:05:03 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 02:58:10 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 02:57:16 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 02:51:08 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 02:50:09 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 01:26:07 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 01:25:19 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 01:24:32 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 01:23:44 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 01:22:57 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream
ERROR
2023-03-21 01:22:09 p.m.
An error occurred while streaming blocks: status: Internal, message: "cannot resolve 'old cursor' from files in passthrough mode -- not implemented", details: [], metadata: MetadataMap { headers: {} }, component: SubstreamsBlockStream

[sduchesneau]

^ I don't see how it could go away... do you have proof that the cursor (and subgraph) is progressing ?

[YaroShkvorets]

It was receiving recent blocks and applying entity operations, so I assume it was progressing:

INFO
2023-03-22 10:24:09 a.m.
Applying 3 entity operation(s), block_hash: 0xe415b1b8d639f5a69c3c5b097365436197fd7ff9522740f0fd15d70cccf59226, block_number: 16883702
INFO
2023-03-22 10:23:48 a.m.
Applying 3 entity operation(s), block_hash: 0xaec2c9ab2493a2cb51bc3888e79cb7488ea922ff9f67ca5b98fdd0414a0934f9, block_number: 16883701
INFO
2023-03-22 10:23:37 a.m.
Applying 3 entity operation(s), block_hash: 0x3fff3b7a6b02185bd5e3543691856e6640b23267e6ded47ce29ff97c3c6a9be9, block_number: 16883700
INFO
2023-03-22 10:23:26 a.m.
Applying 3 entity operation(s), block_hash: 0x2b8fe013025f7e422878c4636abdabc178f6275449c52c896364fdd9f4cd6c1d, block_number: 16883699
INFO
2023-03-22 10:23:13 a.m.
Applying 3 entity operation(s), block_hash: 0xc72b7335574b8f7d997603a92397d2d085f312286f35c430f804a414a80977df, block_number: 16883698
INFO
2023-03-22 10:23:02 a.m.
Applying 3 entity operation(s), block_hash: 0x7179bb1e873f15453e4750ed357d4896a17c131890421ee4590283462bf1b991, block_number: 16883697

[sduchesneau]

I am very worried about the fact that it eventually started working. I will schedule some time to dig deeper into this this week or next week...

[sduchesneau]

the main issue will be resolved by #199 .

[sduchesneau]

I found out why it started working at some point:

when handling undo, in the case where we restarted directly from a cursor, the "content to UNDO" was actually not produced, so it is not part of the f.reversibleOutputs map, so the message is ignored: https://github.com/streamingfast/substreams/blob/develop/pipeline/forkhandler.go#L36-L43

This is not pretty, because it means that your data may be corrupted after that point, since your instance did not perform the 'undo' operation.

Unfortunately, we cannot fix this issue directly without addressing this: https://github.com/streamingfast/substreams/issues/199 (which will soon be implemented, but requires a change in the protocol)

[sduchesneau]

https://github.com/graphprotocol/graph-node/issues/4531 ^ graph-node side of implementation.

[jubeless]

Is this still an issue? If so re-open the ticket