[Bug] Substreams subgraph stopped indexing with error: subgraph QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw has already processed block 17203799

[oleksandrmarkelov]

Bug report

fireeth version 1.3.8
geth version 1.11.5-fh2-dbf9c7ed
graph-node:v0.30.0

The indexing of subgraph QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw was completed but later stopped with error "Failed to transact block operations: subgraph QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw has already processed block 17203799; there are most likely two (or more) nodes indexing this subgraph"

There are definitely only one instance is running (using graphprotocol-testnet-docker setup).

Relevant log output

root@1363ac1ca2da:~# graph indexer status
Registration
┌─────────────────────────────┬────────────────────────────────────────────┬────────────┬──────────────────────────────────────┐
│ url                         │ address                                    │ registered │ location                             │
├─────────────────────────────┼────────────────────────────────────────────┼────────────┼──────────────────────────────────────┤
│ https://swissstarnode.tech/ │ 0x72fDf34F142FDB6f40CC1220E1Ae959f6c84DDC4 │ true       │ 50.45001268386841,30.523345470428467 │
└─────────────────────────────┴────────────────────────────────────────────┴────────────┴──────────────────────────────────────┘

Endpoints
┌─────────┬───────────────────────────────────┬────────┐
│ name    │ url                               │ status │
├─────────┼───────────────────────────────────┼────────┤
│ service │ https://swissstarnode.tech/       │ up     │
├─────────┼───────────────────────────────────┼────────┤
│ status  │ https://swissstarnode.tech/status │ up     │
└─────────┴───────────────────────────────────┴────────┘

Indexer Deployments
┌────────────────────────────────────────────────┬────────┬────────┬───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┬──────────────┬─────────┬───────────────────┬──────────────────────┬─────────────────────┐
│ deployment                                     │ synced │ health │ fatalError                                                                                                                                                                                                │ node         │ network │ latestBlockNumber │ chainHeadBlockNumber │ earliestBlockNumber │
├────────────────────────────────────────────────┼────────┼────────┼───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┼──────────────┼─────────┼───────────────────┼──────────────────────┼─────────────────────┤
│ QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw │ true   │ failed │ "Failed to transact block operations: subgraph `QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw` has already processed block `17203799`; there are most likely two (or more) nodes indexing this subgraph" │ index_node_0 │ mainnet │ 17203799          │ 17205842             │ 12964999            │
└────────────────────────────────────────────────┴────────┴────────┴───────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────────┴──────────────┴─────────┴───────────────────┴──────────────────────┴─────────────────────┘

Indexer Allocations
┌────────────────────────────────────────────┬────────────────────────────────────────────────┬─────────────────┬────────────────┬─────────────────┬──────────────┐
│ id                                         │ subgraphDeployment                             │ allocatedTokens │ createdAtEpoch │ signalledTokens │ stakedTokens │
├────────────────────────────────────────────┼────────────────────────────────────────────────┼─────────────────┼────────────────┼─────────────────┼──────────────┤
│ 0x67f83e208741484c6feee79565f87262d774c448 │ QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw │ 200,000.0       │ 3112           │ 0.0             │ 4,672,256.0  │
└────────────────────────────────────────────┴────────────────────────────────────────────────┴─────────────────┴────────────────┴─────────────────┴──────────────┘

Indexing Rules
┌────────────────────────────────────────────────┬────────────────┬──────────────────┬────────────────────┬─────────────┬─────────────────────┬─────────────────────────┬───────────┬───────────┬──────────┬─────────────────────┬────────┬───────────────┬──────────────────┬────────┐
│ identifier                                     │ identifierType │ allocationAmount │ allocationLifetime │ autoRenewal │ parallelAllocations │ maxAllocationPercentage │ minSignal │ maxSignal │ minStake │ minAverageQueryFees │ custom │ decisionBasis │ requireSupported │ safety │
├────────────────────────────────────────────────┼────────────────┼──────────────────┼────────────────────┼─────────────┼─────────────────────┼─────────────────────────┼───────────┼───────────┼──────────┼─────────────────────┼────────┼───────────────┼──────────────────┼────────┤
│ QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw │ deployment     │ 200,000.0        │ null               │ true        │ 1                   │ null                    │ null      │ null      │ null     │ null                │ null   │ always        │ true             │ true   │
├────────────────────────────────────────────────┼────────────────┼──────────────────┼────────────────────┼─────────────┼─────────────────────┼─────────────────────────┼───────────┼───────────┼──────────┼─────────────────────┼────────┼───────────────┼──────────────────┼────────┤
│ global                                         │ group          │ 0.01             │ null               │ true        │ 1                   │ null                    │ null      │ null      │ null     │ null                │ null   │ rules         │ true             │ true   │
└────────────────────────────────────────────────┴────────────────┴──────────────────┴────────────────────┴─────────────┴─────────────────────┴─────────────────────────┴───────────┴───────────┴──────────┴──────

IPFS hash

QmeWyu8pzV3zViL5nz813NxKSab7REh9qJBivjzkCzE9Vw

Subgraph name or link to explorer

https://testnet.thegraph.com/explorer/subgraphs/3e63xu6PWvSGphm2hPbKtvh4rziS2jYSqxhz5rmRmcnx?view=Indexers&chain=goerli

Some information to help us out

• Tick this box if this bug is caused by a regression found in the latest release.
• Tick this box if this bug is specific to the hosted service.
• I have searched the issue tracker to make sure this issue is not a duplicate.

OS information

Linux

[oleksandrmarkelov]

Retested with
Firehose: 1.4.0
graph-node:v0.31.0-rc.0

The issue is with sf.substreams.internal.v2.Substreams
May 07 13:50:59 node023 fireeth[1389719]: 2023-05-07T13:50:59.656Z INFO (firehose.tier1) job completed {"trace_id": "e18ae81c8122da86a0f560d24228a59a", "job": {"module_name": "store_supply", "start_block": 17206000, "end_block": 17208900}, "error": "receiving stream resp: rpc error: code = Unimplemented desc = unknown service sf.substreams.internal.v2.Substreams"} May 07 13:50:59 node023 fireeth[1389719]: 2023-05-07T13:50:59.656Z INFO (firehose.tier1) shutting down request stats {"trace_id": "e18ae81c8122da86a0f560d24228a59a"} May 07 13:50:59 node023 fireeth[1389719]: 2023-05-07T13:50:59.656Z INFO (firehose.tier1) unexpected termination of stream of blocks {"trace_id": "e18ae81c8122da86a0f560d24228a59a", "error": "error building pipeline: failed setup request: parallel processing run: scheduler run: process job result for target \"store_supply\": worker ended in error: receiving stream resp: rpc error: code = Unimplemented desc = unknown service sf.substreams.internal.v2.Substreams"} May 07 13:50:59 node023 fireeth[1389719]: 2023-05-07T13:50:59.656Z ERRO (firehose) finished streaming call with code Internal {"grpc.start_time": "2023-05-07T13:50:53Z", "system": "grpc", "span.kind": "server", "grpc.service": "sf.substreams.rpc.v2.Stream", "grpc.method": "Blocks", "peer.address": "172.24.0.14:49022", "error": "rpc error: code = Internal desc = error building pipeline: failed setup request: parallel processing run: scheduler run: process job result for target \"store_supply\": worker ended in error: receiving stream resp: rpc error: code = Unimplemented desc = unknown service sf.substreams.internal.v2.Substreams", "grpc.code": "Internal", "grpc.time_ms": 6029.10693359375} May 07 13:50:59 node023 fireeth[1389719]: 2023-05-07T13:50:59.656Z INFO (firehose.tier1) worker failed with retryable error {"trace_id": "e18ae81c8122da86a0f560d24228a59a", "error": "receiving stream resp: rpc error: code = Unimplemented desc = unknown service sf.substreams.internal.v2.Substreams"} May 07 13:50:59 node023 fireeth[1389719]: 2023-05-07T13:50:59.656Z INFO (firehose.tier1) job completed {"trace_id": "e18ae81c8122da86a0f560d24228a59a", "job": {"module_name": "map_entity_changes", "start_block": 17205000, "end_block": 17208900}, "error": "receiving stream resp: rpc error: code = Unimplemented desc = unknown service sf.substreams.internal.v2.Substreams"}

[azf20]

hello - are you running the latest version of substreams? https://github.com/streamingfast/substreams/releases/tag/v1.1.1

[matthewdarwin]

I assume when they say they are running firehose 1.4.0, that means firehose-ethereum version 1.4.0, which is indeed substreams 1.1.1

I believe this issue is duplicate of streamingfast/firehose-ethereum#60

[sduchesneau]

The error in the parallel processing should NOT generate a duplicate error at block 17203800. This is weird. Let's see if we can get the error later when the firehose-ethereum#60 issue is fixed.

[sduchesneau]

The issue does not happen at all (with v1.4.0) when a specific "tier2" substreams endpoint was specified in the config. It happens only when we run a "standalone" substreams instance.

Should be fixed with https://github.com/streamingfast/firehose-ethereum/releases/tag/v1.4.1 <-----

The other error (has already processed block 17203799; there are most likely two (or more) nodes indexing this subgraph) was probably an error that came BEFORE the switch to substreams with RPC v2. The solution to that other error is to issue a "graphman rewind" command to that deployment and rewind to a few blocks before 17203799.

[github-actions]

Looks like this issue has been open for 6 months with no activity. Is it still relevant? If not, please remember to close it.