Subgraph syncing error "Multiple module output error"

[YaroShkvorets]

Syncing my subgraph on hosted service, ran into this error.

In text:

INFO
2023-03-22 09:09:49 a.m.
Blockstreams connected, component: SubstreamsBlockStream
INFO
2023-03-22 09:09:49 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
INFO
2023-03-22 09:09:49 a.m.
received err, component: SubstreamsBlockStream
ERROR
2023-03-22 09:09:49 a.m.
Mapping block to BlockStreamEvent failed: multiple module output error, component: SubstreamsBlockStream
INFO
2023-03-22 09:09:30 a.m.
Applying 3 entity operation(s), block_hash: 0x7b7b727e8e27f6d027e146d6a27f1351f2e9576467baa51c3be399621b990b20, block_number: 16883336
DEBUG
2023-03-22 09:09:30 a.m.
1 candidate trigger in this block, block_hash: 0x7b7b727e8e27f6d027e146d6a27f1351f2e9576467baa51c3be399621b990b20, block_number: 16883336

It's 9:37 now and there were no new messages in the log since 9:17. Subgraph shows it's at 99% synced.

[sduchesneau]

I think this issue is within graph-node integration, or in-between. let's dig a bit

[sduchesneau]

it comes from here: https://github.com/graphprotocol/graph-node/blob/master/chain/substreams/src/mapper.rs#L41

[YaroShkvorets]

Seems to have recovered and started injecting blocks again but then ran into it again (with different cursor):

[YaroShkvorets]

it comes from here: https://github.com/graphprotocol/graph-node/blob/master/chain/substreams/src/mapper.rs#L41

Yep, but seems like it's getting more than 1 module outputs from Firehose, which shouldn't be happenning.

[YaroShkvorets]

Let me start graph node with that subgraph locally and see if I can catch this error.

[YaroShkvorets]

Couldn't recreate this error locally with the same subgraph.

[YaroShkvorets]

Caught this error in debugger after several hours. Seeing outputs from 3 different modules in a message. Looks like a bug and the fact that we throw it away probably affects the subgraph state.

My debugger doesn't allow to copy the entire struct so here's a screenshot:

step = StepUndo cursor = 9HFR-B7u_oNymD5ufBmAQKWyLpQyB1xnXQ3hLhZLjd6i9CDC35yuVmh8PU_Tw6D12xK-Qlyuio6bECx_psdY6dDjl7s16HNtRikrkYrrqrfvcPenbFlNILprCe3dZtLaXTTfZA7_crsG6IDuP_baNEoyY8VyeDDl2zYCoYBddPUVuCEwxW_6dp7U066SooJE_eYgQeygwyuhATErLhwJOMTQNaed7jUib3Rr5gQf9IY6xcZaDI9qOYrdwCorQKn6YRXcbDqwQ1rAegubz0FJBcwQ_BbAnt0Vbc7ByLY9wuULnA060wwDSfGiAalNb9LCE5w= block number = 16886447

So I wonder if that other error with "old cursor" #196 happens because graph-node throws away this message because it doesn't like that there are 3 outputs, without properly handling UNDO.

I'm using StreamingFast substreams endpoint.

[YaroShkvorets]

Actually, graph-node will reconnect after encountering this error, so probably will properly handle it after that and it shouldn't be an issue.

Still, would be great if you could track down that bug with returning multiple outputs instead of one.

[sduchesneau]

Great work! great details! There may be an issue in how the "undo" messages are filtered to include the correct outputs.. The whole "undo" issues is related to the "old cursor" issue. We will be working towards removing some hard requirements for "undo data" inside subsreams, which should end up fixing both issues.

[sduchesneau]

will be addressed as part of #199