Import events failed

[friedger]

Describe the bug Import of events fails with internal error

To Reproduce

1. run api node on 3.+
2. run upgrade using stacks-blockchain-docker
3. see error as shown below

Expected behavior api node should close gracefully and provide information how to fix the issue OR better continue

Console log

stacks-blockchain-api    | {"level":"warn","message":"Could not find tx index for subdomain entry: {\"name\":\"id.stx\",\"namespace_id\":\"stx\",\"fully_qualified_subdomain\":\"niko_nie.id.stx\",\"owner\":\"SP3J34ASN2SDA641KT9MD4Y84SJ0P2FBY6HM89RPG\",\"zonefile_hash\":\"27c87cc6331bc588d21a911238aad4a9\",\"zonefile\":\"$ORIGIN niko_nie.id.stx\\n$TTL 3600\\n_http._tcp\\tIN\\tURI\\t10\\t1\\t\\\"https://gaia.blockstack.org/hub/1MobAXTm9b5wkfoBWEVVSxa5hkhiJhmyEW/profile.json\\\"\\n\\n\",\"tx_id\":\"0x2cd0c1d8be0dbdd1f5af45c30c172b91eb1e3fd2fa226dfa3d3f9bbf7a4b8be2\",\"tx_index\":-1,\"canonical\":true,\"parent_zonefile_hash\":\"90c356d9444bd6ed21274df21798a9a910003035\",\"parent_zonefile_index\":0,\"block_height\":56291,\"zonefile_offset\":1,\"resolver\":\"https://registrar.stacks.co\"}","timestamp":"2022-06-07T14:21:33.013Z"}
stacks-blockchain-api    | {"level":"error","message":"Error processing core node block message DB does not contain a parent block at height 56320 with index_hash 0x81c4b32fad872a2d5ad590de51cd09b77b15c9039ab57b7c0e75bb7822dacc90","stack":"Error: DB does not contain a parent block at height 56320 with index_hash 0x81c4b32fad872a2d5ad590de51cd09b77b15c9039ab57b7c0e75bb7822dacc90\n    at PgDataStore.handleReorg (/app/src/datastore/postgres-store.ts:2699:15)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)\n    at /app/src/datastore/postgres-store.ts:1313:7\n    at /app/src/datastore/postgres-store.ts:941:24\n    at PgDataStore.query (/app/src/datastore/postgres-store.ts:927:22)\n    at PgDataStore.queryTx (/app/src/datastore/postgres-store.ts:938:12)\n    at PgDataStore.update (/app/src/datastore/postgres-store.ts:1311:5)\n    at handleBlockMessage (/app/src/event-stream/event-server.ts:319:3)\n    at run (/app/node_modules/p-queue/dist/index.js:163:29)","timestamp":"2022-06-07T14:21:33.221Z"}
stacks-blockchain-api    | {"level":"error","message":"error processing core-node /new_block: Error: DB does not contain a parent block at height 56320 with index_hash 0x81c4b32fad872a2d5ad590de51cd09b77b15c9039ab57b7c0e75bb7822dacc90 DB does not contain a parent block at height 56320 with index_hash 0x81c4b32fad872a2d5ad590de51cd09b77b15c9039ab57b7c0e75bb7822dacc90","stack":"Error: DB does not contain a parent block at height 56320 with index_hash 0x81c4b32fad872a2d5ad590de51cd09b77b15c9039ab57b7c0e75bb7822dacc90\n    at PgDataStore.handleReorg (/app/src/datastore/postgres-store.ts:2699:15)\n    at runMicrotasks (<anonymous>)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)\n    at /app/src/datastore/postgres-store.ts:1313:7\n    at /app/src/datastore/postgres-store.ts:941:24\n    at PgDataStore.query (/app/src/datastore/postgres-store.ts:927:22)\n    at PgDataStore.queryTx (/app/src/datastore/postgres-store.ts:938:12)\n    at PgDataStore.update (/app/src/datastore/postgres-store.ts:1311:5)\n    at handleBlockMessage (/app/src/event-stream/event-server.ts:319:3)\n    at run (/app/node_modules/p-queue/dist/index.js:163:29)","timestamp":"2022-06-07T14:21:33.222Z"}
stacks-blockchain-api    | {"level":"error","message":"HTTP POST /new_block","req":{"headers":{"connection":"close","content-length":"2635","content-type":"application/json","host":"127.0.0.1:34739"},"httpVersion":"1.1","method":"POST","originalUrl":"/new_block","query":{},"url":"/new_block"},"res":{"statusCode":500},"responseTime":192,"timestamp":"2022-06-07T14:21:33.222Z"}
postgres                 | 2022-06-07 14:21:33.226 UTC [35] LOG:  unexpected EOF on client connection with an open transaction
stacks-blockchain-api    | Error: Bad status response status code 500: Internal Server Error
stacks-blockchain-api    |     at IncomingMessage.<anonymous> (/app/src/helpers.ts:351:29)
stacks-blockchain-api    |     at IncomingMessage.emit (node:events:539:35)
stacks-blockchain-api    |     at endReadableNT (node:internal/streams/readable:1345:12)
stacks-blockchain-api    |     at processTicksAndRejections (node:internal/process/task_queues:83:21) {
stacks-blockchain-api    |   requestUrl: 'http://127.0.0.1:34739/new_block',
stacks-blockchain-api    |   statusCode: 500,
stacks-blockchain-api    |   response: '{"error":{}}'
stacks-blockchain-api    | }
stacks-blockchain-api    | import-events process failed

Desktop (please complete the following information): stacks-blockchain-docker upgrade 3.+ to 4.0.1

Additional context Initially posted on https://github.com/stacks-network/stacks-blockchain-docker/issues/65

[rafaelcr]

@friedger can you share the postgres version you're using as well as the TSV file for event replay?

[friedger]

@rafaelcr from .env: POSTGRES_VERSION=13 I don't think I have the tsv file anymore, at least I can't find it.

As this happened more than once to me, it looks like it is not related to one particular tsv file.

[rafaelcr]

@friedger could you try upgrading to PG 14?

To give a bit more context, we haven't seen that error in the past in our deployments or local test environments. Looks like postgres is having a hard time keeping a connection alive, though, so we'd like to first rule out if it has anything to do with the version.

[davidkarim]

I am seeing this same error and I am running PG 14. I am also looking through the postgres database, although there are many tables; they are all empty. Here is a sample of the log output:

{"level":"error","message":"error processing core-node /new_block: Error: DB does not contain a parent block at height 70753 with index_hash 0x14ab57afe075ce13035b938a9c47c06254d30df6c12fc4d5e38450453412d3f8 DB does not contain a parent block at height 70753 with index_hash 0x14ab57afe075ce13035b938a9c47c06254d30df6c12fc4d5e38450453412d3f8","stack":"Error: DB does not contain a parent block at height 70753 with index_hash 0x14ab57afe075ce13035b938a9c47c06254d30df6c12fc4d5e38450453412d3f8\n    at PgDataStore.handleReorg (/stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:2702:15)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)\n    at /stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:1316:7\n    at /stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:944:24\n    at PgDataStore.query (/stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:930:22)\n    at PgDataStore.queryTx (/stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:941:12)\n    at PgDataStore.update (/stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:1314:5)\n    at handleBlockMessage (/stacks-node/stacks-blockchain-api/src/event-stream/event-server.ts:319:3)\n    at run (/stacks-node/stacks-blockchain-api/node_modules/p-queue/dist/index.js:163:29)","timestamp":"2022-08-08T16:21:04.171Z"}

There seem to be corresponding error messages in the stacks binary running on the same node. Looks like it's trying to send a POST to port 3700 (which appears to be open and accepting connections). But the API then responds with an internal server error. Maybe due to error above?

ERRO [1659979264.272658] [testnet/stacks-node/src/event_dispatcher.rs:144] [chains-coordinator] Event dispatcher: Failed POST, url: http://localhost:3700/new_block, err: Response { status: InternalServerError, headers: {"date": "Mon, 08 Aug 2022 17:21:04 GMT", "content-length": "12", "keep-alive": "timeout=5", "content-type": "application/json; charset=utf-8", "etag": "W/\"c-3Rk1bge0s6VuJbi+S2m2iU0UGdY\"", "connection": "keep-alive", "x-powered-by": "Express"}, version: None, has_trailers: false, trailers_sender: Some(Sender { .. }), trailers_receiver: Some(Receiver { .. }), upgrade_sender: Some(Sender { .. }), upgrade_receiver: Some(Receiver { .. }), has_upgrade: false, body: Body { reader: "<hidden>", length: Some(12), bytes_read: 0 }, ext: Extensions, local_addr: None, peer_addr: None }

[CharlieC3]

Seeing a similar error on my end for API v6.x:

10/29/2022, 08:58:21 PM	mainnet-postgresql-snapshot-0 >>> 2022-10-30 00:58:21.435 GMT [6968] LOG:  unexpected EOF on client connection with an open transaction
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>> Error: Bad status response status code 500: Internal Server Error
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>>     at IncomingMessage.<anonymous> (/app/src/helpers.ts:345:29)
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>>     at IncomingMessage.emit (node:events:525:35)
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>>     at endReadableNT (node:internal/streams/readable:1358:12)
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>>     at processTicksAndRejections (node:internal/process/task_queues:83:21) {
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>>   requestUrl: 'http://127.0.0.1:37239/new_block',
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>>   statusCode: 500,
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>>   response: '{"error":{}}'
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>> }
10/29/2022, 08:58:21 PM	mainnet-api-snapshot-writer-0 >>> import-events process failed

Is retry logic in place for HTTP 500's during event replay? If not, it may help cases like mine where the issue is purely network-related.

[zone117x]

@CharlieC3's assessment sounds correct here for the unexpected EOF on client connection errors.

There is no http request retry logic in place for this area of event-replay. It looks pretty simple to add (probably just a simple sleep(500ms) & retry either indefinitely or for some reasonable default amount of time).

Although, I'm pretty surprised something like a transient network error would happen here. Not only are these HTTP POST request being made against localhost / same machine, it's even the within the same process. If I had to hazard a guess, I'd assume something larger is going wrong in environment, which wouldn't necessarily be solved by a simple retry. We should certainly try though.

Note that any of the other error logs pasted in this issue which do not include the unexpected EOF on client connection line are probably unrelated.

[zone117x]

We haven't seen any additional reports of the original error Could not find tx index for subdomain entry ... for a while. I'm assuming it was a one-off or ended up getting unintentionally fixed, so closing for now.

Please comment if anyone sees that error again.