Error running event-replay from v4.1.1 -> v6.1.0

[wileyj]

Describe the bug
Errors running the event-replay import when upgrading from v4.1.1 to v6.1.0

To Reproduce

1. stop blockchain instance
2. stop api
3. pull from master branch and rebuild
4. run node ./lib/index.js import-events --file /tmp/stacks-node-events.tsv --wipe-db --force using local tsv location

Expected behavior
event-replay runs and replays the events from the tsv file to postgres 14.5

Console log

# node ./lib/index.js import-events --file /stacks-node/stacks-node-events.tsv --wipe-db --force
{"level":"error","message":"Error running pg-migrate Definitions of migrations 1655235863682_nft_custody_value_index, 1652304516306_token_metadata_queue_retry_count have been deleted.","stack":"Error: Definitions of migrations 1655235863682_nft_custody_value_index, 1652304516306_token_metadata_queue_retry_count have been deleted.\n    at getMigrationsToRun (/stacks-node/stacks-blockchain-api/node_modules/node-pg-migrate/dist/runner.js:94:19)\n    at exports.default (/stacks-node/stacks-blockchain-api/node_modules/node-pg-migrate/dist/runner.js:158:23)\n    at processTicksAndRejections (node:internal/process/task_queues:96:5)\n    at runMigrations (/stacks-node/stacks-blockchain-api/src/datastore/migrations.ts:43:5)\n    at cycleMigrations (/stacks-node/stacks-blockchain-api/src/datastore/migrations.ts:58:3)\n    at importEventsFromTsv (/stacks-node/stacks-blockchain-api/src/event-replay/event-replay.ts:104:3)\n    at handleProgramArgs (/stacks-node/stacks-blockchain-api/src/index.ts:271:5)","timestamp":"2022-10-20T18:26:20.953Z"}
Error: Definitions of migrations 1655235863682_nft_custody_value_index, 1652304516306_token_metadata_queue_retry_count have been deleted.
    at getMigrationsToRun (/stacks-node/stacks-blockchain-api/node_modules/node-pg-migrate/dist/runner.js:94:19)
    at exports.default (/stacks-node/stacks-blockchain-api/node_modules/node-pg-migrate/dist/runner.js:158:23)
    at processTicksAndRejections (node:internal/process/task_queues:96:5)
    at runMigrations (/stacks-node/stacks-blockchain-api/src/datastore/migrations.ts:43:5)
    at cycleMigrations (/stacks-node/stacks-blockchain-api/src/datastore/migrations.ts:58:3)
    at importEventsFromTsv (/stacks-node/stacks-blockchain-api/src/event-replay/event-replay.ts:104:3)
    at handleProgramArgs (/stacks-node/stacks-blockchain-api/src/index.ts:271:5)
import-events process failed

After the failure, the API was rebuilt on tag v4.1.1 and restarted successfully (tsv file is being updated and events are being stored from the stacks-node).

Desktop (please complete the following information):

• OS: Debian based

Additional context
last 10 lines of tsv file:

944359 2022-10-20 18:08:12.141826+00 /new_mempool_tx ["0x00000000010400260109968b7bce656a2fb5baf97db07bcfb228a300000000000000000000000000000bb80001770b640d68d3fc6f56b2389ed735b72df5f73cd7b678115382bc2b0423d269b750aad5d10c5900d9ba167c04e87b1d326c7cd948e3c76fce2c9b0a08b1b1a303030200000001000216260109968b7bce656a2fb5baf97db07bcfb228a30100000000001e84800216000000000000000000000000000000000000000003626e730d6e616d652d7072656f72646572000000020200000014c209b9e1521e55b5f6b053b72806c7157a2839c201000000000000000000000000001e8480"]
944360 2022-10-20 18:08:13.804599+00 /new_mempool_tx ["0x000000000104008d10fe13014ca7b35662d1a29070d2e53b63de0400000000000002bb00000000000001dd000173e14b8dae33468f31d72158eb5002bba9705b1b227d660849455149bb719937596aa46582d498356f687cb5ce4830dcbb10d8dea7270cf35d3a77ea2e218ad20301000000000216a8083594d7ea0e3568c2335d446ddef53b1abb0c186578636974696e672d61707269636f742d726163636f6f6e0e464831393066494e6232316250480000000c01000000000000000000000000000003e803030406167e9152cdbbb9fef066df4e1b88b19bcb313acc900e777374782d746f6b656e2d76346106167e9152cdbbb9fef066df4e1b88b19bcb313acc900e737473772d746f6b656e2d76346106167e9152cdbbb9fef066df4e1b88b19bcb313acc900e6c6274632d746f6b656e2d76316306167e9152cdbbb9fef066df4e1b88b19bcb313acc90186c69717569646974792d746f6b656e2d7374782d7374737706167e9152cdbbb9fef066df4e1b88b19bcb313acc901b6c69717569646974792d746f6b656e2d76356b72716264386e683606167e9152cdbbb9fef066df4e1b88b19bcb313acc901b6c69717569646974792d746f6b656e2d76356b7a6b6b73326332790100000000000000000000000005f5e10003"]
944361 2022-10-20 18:08:17.507344+00 /new_mempool_tx ["0x0000000001040092518ff2ea60fac5e8e64128d35e8f8f42844ef200000000000002bd00000000000001dd0000c253c8691e72177f42c58f36a7c7b4637dc46c3b8f5909c50072282c6010870c44ce936b95f3800263ed9054e9f8726908fdd72a36f14f33645ef3d02c4741480301000000000216a8083594d7ea0e3568c2335d446ddef53b1abb0c186578636974696e672d61707269636f742d726163636f6f6e0e464831393066494e6232316250480000000c01000000000000000000000000000003e803040406167e9152cdbbb9fef066df4e1b88b19bcb313acc900e777374782d746f6b656e2d76346106167e9152cdbbb9fef066df4e1b88b19bcb313acc900e6c6274632d746f6b656e2d76316306167e9152cdbbb9fef066df4e1b88b19bcb313acc900e737473772d746f6b656e2d76346106167e9152cdbbb9fef066df4e1b88b19bcb313acc901b6c69717569646974792d746f6b656e2d76356b7a6b6b733263327906167e9152cdbbb9fef066df4e1b88b19bcb313acc901b6c69717569646974792d746f6b656e2d76356b72716264386e683606167e9152cdbbb9fef066df4e1b88b19bcb313acc90186c69717569646974792d746f6b656e2d7374782d737473770100000000000000000000000005f5e10003"]
944362 2022-10-20 18:08:26.603878+00 /new_mempool_tx ["0x0000000001040031ee3dd8a19c4db3528f4234fbecce03e2bd9db30000000000000003000000000000ceb4000106711bbd408f37457705cb4a317512a58c718eae495a78a8c9401dc7306cca682635cb8cb7aab28daee5e32d3f9867a04519e86e5ed08b0fd64227dc2f6a478d030200000000000516e9c7f81586feb02b1468c388dce79b2e09d5e58400000000002dc6c000000000000000000000000000000000000000000000000000000000000000000000"]
944363 2022-10-20 18:08:31.272167+00 /new_mempool_tx ["0x00000000010400260109968b7bce656a2fb5baf97db07bcfb228a300000000000000010000000000000bb80000fd608a122f069481f4b47251093e42ea4c2cdb060fe32757f83799223d2078340424fef0a6a1ae1317f0c5f1db0de73d21232a1cad1be4ba36168c76d5ca158b0302000000000216000000000000000000000000000000000000000003626e730d6e616d652d72656769737465720000000402000000036274630200000003746e6902000000145e8b1ba2154eb37c608723103df798823c9a84d802000000142b92ca6092bf82201c809a5a4d19f08c116c4ad9"]
944364 2022-10-20 18:08:32.824586+00 /new_mempool_tx ["0x00000000010400604d9721a23d834b7c301f54966dd4e55e7c892d000000000000003a000000000000d789000182e4911298bd04622d2996afccda2ebf9459608a02cde18f05841d90f4fbf8232200b9fd4d6e9506b25520afd855d639e4770c7cb36c387430f137ec2a787e1b030200000000000516c137a80550fad068b49c41beb5705ebfa96d0f9d00000000002625a000000000000000000000000000000000000000000000000000000000000000000000"]
944365 2022-10-20 18:08:33.836349+00 /new_mempool_tx ["0x0000000001040063073d7289091a205335ab3fb3b499cc6506579600000000000004b000000000000009c40001f7ef0e73f48637c9827a98ba68bdcae91335d34a6e154f1bc7f4f8eb2b480a96462a9aab265574090c7366d6370295d06bf7e2bbf250e33bf41cc45e3fa1105c03020000000601021663073d7289091a205335ab3fb3b499cc6506579616982f3ec112a5f5928a5c96a914bd733793b896a50e61726b6164696b6f2d746f6b656e0464696b6f01000000003c51b52f01021663073d7289091a205335ab3fb3b499cc6506579616982f3ec112a5f5928a5c96a914bd733793b896a50a757364612d746f6b656e0475736461030000000000000000010316982f3ec112a5f5928a5c96a914bd733793b896a51261726b6164696b6f2d737761702d76322d3116982f3ec112a5f5928a5c96a914bd733793b896a50a757364612d746f6b656e0475736461030000000000000000000316982f3ec112a5f5928a5c96a914bd733793b896a51261726b6164696b6f2d737761702d76322d31030000000003a8b12f01021663073d7289091a205335ab3fb3b499cc6506579616982f3ec112a5f5928a5c96a914bd733793b896a511777261707065642d7374782d746f6b656e0477737478030000000003a8b12f010316982f3ec112a5f5928a5c96a914bd733793b896a51261726b6164696b6f2d737761702d76322d3116982f3ec112a5f5928a5c96a914bd733793b896a511777261707065642d7374782d746f6b656e0477737478030000000003a8b12f0216982f3ec112a5f5928a5c96a914bd733793b896a51c61726b6164696b6f2d6d756c74692d686f702d737761702d76312d310c737761702d782d666f722d7a000000070616982f3ec112a5f5928a5c96a914bd733793b896a50e61726b6164696b6f2d746f6b656e0616982f3ec112a5f5928a5c96a914bd733793b896a50a757364612d746f6b656e0616982f3ec112a5f5928a5c96a914bd733793b896a511777261707065642d7374782d746f6b656e010000000000000000000000003c51b52f0100000000000000000000000003a8b12f0403"]
944366 2022-10-20 18:08:48.886888+00 /new_mempool_tx ["0x00000000010400279809a29e84a458d915e7d8b41fac287a51418f00000000000000010000000000000bb80001098fd43d7a0daddc2872bc3b96a5de654c4df97a9a3d4efd368d14ad8b4dcc5f486ca30821e1bd0df5abb566de9913691c090696b65e74d69b1ac0ddc345c2200302000000000216000000000000000000000000000000000000000003626e730d6e616d652d726567697374657200000004020000000362746302000000067072657362790200000014eb8c890dd1defc62ef85648e259d81f4c916787c0200000014d8cf1a9b3dfbe62f3630f848f24d50c2b4274d63"]
944367 2022-10-20 18:08:50.708936+00 /new_mempool_tx ["0x0000000001040031ee3dd8a19c4db3528f4234fbecce03e2bd9db30000000000000004000000000000ceb40000f26aff38ee19778e26aa7b7691cc4d37069ba2386dcd2a1bc0b334925634666d7203c3badca038929039f0604dac79268876681d83cb52e63b2a6a738fb1a71d030200000000000516bf7ef545148815a6a6f89ccf142e642ea7e6eccc00000000002dc6c000000000000000000000000000000000000000000000000000000000000000000000"]
944368 2022-10-20 18:08:54.914327+00 /new_mempool_tx ["0x00000000010400d81775ff4360c570ffd9282abd7ad2aeb0803d9f0000000000000000000000000000cd970000622156d7090657a25070ed5b9c62bf923e21f25ce85c14cc56b1e911b079d0b713aa78d05745bf5c5d1a2ea2ce4322f410753027121678ae9a2a419594f4b61d0302000000000005168099148b4f8492e4d846d0a0a04e3e516f4d965800000000002625a000000000000000000000000000000000000000000000000000000000000000000000"]

@davidkarim @zone117x @rafaelcr

[wileyj]

per @rafaelcr :

currently working on a PR that attempts to fix all of these issues... the TL:DR; is that the code we use to check if we should empty the DB upon event replays has a few bugs

for now, the workaround is to clear the DB manually before doing the event replay

[davidkarim]

So I just ran the import-events command without the --wipe-db option; instead I wiped the database manually. I tried with both the existing node-events.tsv file which was being populated while the stacks-api service was running and at tip (tsv file size was 2.5GB at that time). Then I tried by doing an export first (which gave me a .tsv file of 12GB size). Both gave me similar errors. Prior to running the import, I dropped tables manually, I got the following error. Also, after the error, I could see that the tables were recreated, but were empty.

# node ./lib/index.js import-events --file /stacks-node/stacks-node-events.tsv --force
Event file's block height: 80453
Starting event import and playback in archival mode
{"level":"info","message":"Event observer listening at: http://127.0.0.1:29707","timestamp":"2022-10-21T17:56:23.686Z"}
Importing raw event requests into temporary table...
Streaming raw event requests from temporary table...
{"level":"error","message":"Error processing core node block message DB does not contain a parent block at height 72324 with index_hash 0xaf17e3102755464a95135aca64f2f5185181787a2b2c093bc333fbcd6e23de2e","stack":"Error: DB does not contain a parent block at height 72324 with index_hash 0xaf17e3102755464a95135aca64f2f5185181787a2b2c093bc333fbcd6e23de2e\n    at PgDataStore.handleReorg (/stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:2702:15)\n    at runMicrotasks (<anonymous>)\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-10-21T17:58:10.814Z"}
{"level":"error","message":"error processing core-node /new_block: Error: DB does not contain a parent block at height 72324 with index_hash 0xaf17e3102755464a95135aca64f2f5185181787a2b2c093bc333fbcd6e23de2e DB does not contain a parent block at height 72324 with index_hash 0xaf17e3102755464a95135aca64f2f5185181787a2b2c093bc333fbcd6e23de2e","stack":"Error: DB does not contain a parent block at height 72324 with index_hash 0xaf17e3102755464a95135aca64f2f5185181787a2b2c093bc333fbcd6e23de2e\n    at PgDataStore.handleReorg (/stacks-node/stacks-blockchain-api/src/datastore/postgres-store.ts:2702:15)\n    at runMicrotasks (<anonymous>)\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-10-21T17:58:10.814Z"}
{"level":"error","message":"HTTP POST /new_block","req":{"headers":{"connection":"close","content-length":"65115","content-type":"application/json","host":"127.0.0.1:29707"},"httpVersion":"1.1","method":"POST","originalUrl":"/new_block","query":{},"url":"/new_block"},"res":{"statusCode":500},"responseTime":89,"timestamp":"2022-10-21T17:58:10.815Z"}
Error: Bad status response status code 500: Internal Server Error
    at IncomingMessage.<anonymous> (/stacks-node/stacks-blockchain-api/src/helpers.ts:351:29)
    at IncomingMessage.emit (node:events:525:35)
    at endReadableNT (node:internal/streams/readable:1358:12)
    at processTicksAndRejections (node:internal/process/task_queues:83:21) {
  requestUrl: 'http://127.0.0.1:29707/new_block',
  statusCode: 500,
  response: '{"error":{}}'
}
import-events process failed

[davidkarim]

That first error I posted happened without first running the export; I used the tsv which was being populated by the stacks-api process. After running export, wiping db, and running import I got a similar response, it was just complaining about a different parent block number:

# node ./lib/index.js import-events --file /stacks-node/stacks-node-events.tsv --force
Event file's block height: 80459
Starting event import and playback in archival mode
{"level":"info","message":"Event observer listening at: http://127.0.0.1:4447","timestamp":"2022-10-21T18:32:19.193Z"}
Importing raw event requests into temporary table...
Streaming raw event requests from temporary table...
{"level":"error","message":"Error processing core node block message 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 runMicrotasks (<anonymous>)\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-10-21T18:39:38.867Z"}
{"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 runMicrotasks (<anonymous>)\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-10-21T18:39:38.867Z"}
{"level":"error","message":"HTTP POST /new_block","req":{"headers":{"connection":"close","content-length":"10770","content-type":"application/json","host":"127.0.0.1:4447"},"httpVersion":"1.1","method":"POST","originalUrl":"/new_block","query":{},"url":"/new_block"},"res":{"statusCode":500},"responseTime":105,"timestamp":"2022-10-21T18:39:38.868Z"}
Error: Bad status response status code 500: Internal Server Error
    at IncomingMessage.<anonymous> (/stacks-node/stacks-blockchain-api/src/helpers.ts:351:29)
    at IncomingMessage.emit (node:events:525:35)
    at endReadableNT (node:internal/streams/readable:1358:12)
    at processTicksAndRejections (node:internal/process/task_queues:83:21) {
  requestUrl: 'http://127.0.0.1:4447/new_block',
  statusCode: 500,
  response: '{"error":{}}'
}

[rafaelcr]

node-events.tsv file which was being populated while the stacks-api service was running

Hi @davidkarim , starting in API v6 we removed this functionality (feed a TSV from live events) because blocks have become so big that the write to text file started showing some serious problems: #1315

Could you try generating a fresh TSV by first doing an event-export and then feeding that new TSV into event-import? That will copy the node event messages from the DB into the TSV directly, which will hopefully fix the issues you're seeing.

[rafaelcr]

I just verified that this upgrade is fixed with API v6.2.2 from v4.x in a local deployment