critical ethereumjs bug

[TimDaub]

2024-02-01T00:00:57: 2024-02-01T00:00:57.209Z @attestate/kiwistand Received levels and compari
ng them
2024-02-01T00:00:57: 2024-02-01T00:00:57.478Z @attestate/kiwistand Received levels and compari
ng them
2024-02-01T00:00:57: 2024-02-01T00:00:57.749Z @attestate/kiwistand Received levels and compari
ng them
2024-02-01T00:00:58: 2024-02-01T00:00:58.032Z @attestate/kiwistand handleLeaves: Received leav
es and storing them in db
2024-02-01T00:00:58: 2024-02-01T00:00:58.064Z @attestate/kiwistand Attempting to store message
 with index "64b96a11f9974259d667895ba04dee80dd955099d974ed089e9281aebdd21f42016c64c2" and mes
sage: "{"href":"https://loremipsum5.com/","signature":"0x8ce6b4e1220544196b96cd26711bbd7a28a43
376b692b8233d1aecb3f27c92c2617cba092ccacfdee72690971c658c255c69f281991c0be82351c6e6eade6bae1b"
,"timestamp":1689872913,"title":"test","type":"amplify"}"
2024-02-01T00:00:58: 2024-02-01T00:00:58.064Z @attestate/kiwistand Message with marker "0x3e6c
23CdAa52B1B6621dBb30c367d16ace21F760|https://loremipsum5.com|amplify" doesn't pass legitimacy
criteria (duplicate). It was probably submitted and accepted before.
2024-02-01T00:00:58: Message: put: Didn't add message to database
2024-02-01T00:00:58: Stack Trace: Error: Message with marker "0x3e6c23CdAa52B1B6621dBb30c367d1
6ace21F760|https://loremipsum5.com|amplify" doesn't pass legitimacy criteria (duplicate). It w
as probably submitted and accepted before.
2024-02-01T00:00:58:     at atomicPut (file:///root/kiwistand/src/store.mjs:274:13)
2024-02-01T00:00:58:     at process.processTicksAndRejections (node:internal/process/task_queu
es:95:5)
2024-02-01T00:00:58:     at async Module.add (file:///root/kiwistand/src/store.mjs:371:32)
2024-02-01T00:00:58:     at async put (file:///root/kiwistand/src/sync.mjs:332:7)
2024-02-01T00:00:58:     at async file:///root/kiwistand/src/sync.mjs:444:7
2024-02-01T00:00:58:     at async file:///root/kiwistand/src/sync.mjs:376:18
2024-02-01T00:00:58: 2024-02-01T00:00:58.068Z @attestate/kiwistand Unsetting global peer
2024-02-01T00:00:58: 2024-02-01T00:00:58.373Z @attestate/kiwistand Setting global peer: "16Uiu2HAkx7kBE976GUMjLJCYLKCn8onAbgm7qc1nY7GZeNxk64NQ"
2024-02-01T00:00:58: 2024-02-01T00:00:58.373Z @attestate/kiwistand Received levels and comparing them
2024-02-01T00:00:58: 2024-02-01T00:00:58.652Z @attestate/kiwistand Received levels and comparing them
2024-02-01T00:00:58: 2024-02-01T00:00:58.929Z @attestate/kiwistand Attempting to store message
 with index "65badc1d8b88b49217fda6abdb764eb69cf239d8d8e625eb0737f28762efa39bd9c8c727" and mes
sage: "{"title":"Why I Moved My Blog from IPFS to a Server","href":"https://neimanslab.org/2024-01-31/why-i-moved-my-blog-ipfs-to-server.html","type":"amplify","timestamp":1706744861,"signature":"0x2ce7b29f7f744acf9334c502ed918b1dedbbbab34877266ee73dd387761acdc042465489d9c1c115038cb9acbd17b8aee8c838472c62480235dcb1e9319f43141b"}"
2024-02-01T00:00:58: 2024-02-01T00:00:58.931Z @attestate/kiwistand handleLeaves: Received leaves and storing them in db
2024-02-01T00:00:58: Message: put: Didn't add message to database
2024-02-01T00:00:58: Stack Trace: Error: add: Didn't find root message of comment
2024-02-01T00:00:58:     at Module.add (file:///root/kiwistand/src/store.mjs:361:13)
2024-02-01T00:00:58:     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2024-02-01T00:00:58:     at async put (file:///root/kiwistand/src/sync.mjs:332:7)
2024-02-01T00:00:58:     at async file:///root/kiwistand/src/sync.mjs:444:7
2024-02-01T00:00:58:     at async file:///root/kiwistand/src/sync.mjs:376:18
2024-02-01T00:00:58: 2024-02-01T00:00:58.967Z @attestate/kiwistand Stored message with index "65badc1d8b88b49217fda6abdb764eb69cf239d8d8e625eb0737f28762efa39bd9c8c727"
2024-02-01T00:00:58: 2024-02-01T00:00:58.967Z @attestate/kiwistand New root: "e49c93db1dd3c722
e8b3c75b07f2a5b61a01699f3e384437c7643772449129c4"
2024-02-01T00:00:58: 2024-02-01T00:00:58.967Z @attestate/kiwistand Sending message to peers: "kiwi/5.0.0/messages" and index: "65badc1d8b88b49217fda6abdb764eb69cf239d8d8e625eb0737f28762efa39bd9c8c727"
2024-02-01T00:00:58: 2024-02-01T00:00:58.974Z @attestate/kiwistand Unsetting global peer
2024-02-01T00:00:59: 2024-02-01T00:00:59.260Z @attestate/kiwistand Setting global peer: "16Uiu
2HAkx7kBE976GUMjLJCYLKCn8onAbgm7qc1nY7GZeNxk64NQ"
2024-02-01T00:00:59: 2024-02-01T00:00:59.260Z @attestate/kiwistand Received levels and comparing them
2024-02-01T00:00:59: Message: handleLevels: error in compare, aborting
2024-02-01T00:00:59: Stack Trace: Error: Received empty list of levels.
2024-02-01T00:00:59:     at compare (file:///root/kiwistand/src/sync.mjs:359:11)
2024-02-01T00:00:59:     at file:///root/kiwistand/src/sync.mjs:413:27
2024-02-01T00:00:59:     at file:///root/kiwistand/src/sync.mjs:376:24
2024-02-01T00:00:59:     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2024-02-01T00:00:59: 2024-02-01T00:00:59.260Z @attestate/kiwistand Unsetting global peer
2024-02-01T00:00:59: 2024-02-01T00:00:59.260Z @attestate/kiwistand Failed to handle response from remote. Can't generate answer, closing stream.
2024-02-01T00:00:59: 2024-02-01T00:00:59.260Z @attestate/kiwistand Unsetting global peer
2024-02-01T00:01:00: 2024-02-01T00:01:00.736Z @attestate/kiwistand leaves: Does trie have checkpoints? "false"
2024-02-01T00:01:00: 2024-02-01T00:01:00.736Z @attestate/kiwistand leaves: Trie root "e49c93db
1dd3c722e8b3c75b07f2a5b61a01699f3e384437c7643772449129c4"
2024-02-01T00:01:00: 2024-02-01T00:01:00.737Z @attestate/kiwistand leaves: Does trie have checkpoints? "false"
2024-02-01T00:01:00: 2024-02-01T00:01:00.737Z @attestate/kiwistand leaves: Trie root "e49c93db
1dd3c722e8b3c75b07f2a5b61a01699f3e384437c7643772449129c4"
2024-02-01T00:01:00: /root/kiwistand/node_modules/@ethereumjs/trie/dist/trie/trie.js:309
2024-02-01T00:01:00:             throw new Error('Missing node in DB');
2024-02-01T00:01:00:                   ^
2024-02-01T00:01:00:
2024-02-01T00:01:00: Error: Missing node in DB
2024-02-01T00:01:00:     at Trie.lookupNode (/root/kiwistand/node_modules/@ethereumjs/trie/dist/trie/trie.js:309:19)
2024-02-01T00:01:00:     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2024-02-01T00:01:00:     at async walkTrieDfs (file:///root/kiwistand/src/store.mjs:581:16)
2024-02-01T00:01:00:     at async leaves (file:///root/kiwistand/src/store.mjs:535:25)
2024-02-01T00:01:00:     at async Module.posts (file:///root/kiwistand/src/store.mjs:487:17)
2024-02-01T00:01:00:     at async Module.recompute (file:///root/kiwistand/src/views/new.mjs:51:16)
2024-02-01T00:01:00:
2024-02-01T00:01:00: Node.js v19.9.0
2024-02-01T00:01:01: 2024-02-01T00:01:01.974Z @attestate/kiwistand Launching as bootstrap node
2024-02-01T00:01:01: 2024-02-01T00:01:01.975Z @attestate/kiwistand Using id from disk.
2024-02-01T00:01:04: 2024-02-01T00:01:04.958Z @attestate/crawler:lifecycle Starting to execute strategies with the following crawl path [ { name: ESC[32m'op-call-block-logs'ESC[39m, coordinator: { archive: ESC[33mfalseESC[39m, module: [Module: null prototype] { local: ESC[36m[Async
Function: local]ESC[39m, remote: ESC[36m[AsyncFunction: remote]ESC[39m }, interval: ESC[33m60000ESC[39m }, extractor: { module: [Module: null prototype] { init: ESC[36m[Function: init]ESC[39m, update: ESC[36m[Function: update]ESC[39m }, args: { start: ESC[33m109546193ESC[39m, address: ESC[32m'0x66747bdC903d17C586fA09eE5D6b54CC85bBEA45'ESC[39m, topics: [ ESC[32m'0xddf252ad1be2c89b69c2b068fc378daa952ba7f163c4a11628f55a4df523b3ef'ESC[39m, ESC[32m'0x0000000000000000000000000000000000000000000000000000000000000000'ESC[39m ], blockspan: ESC[33m5000ESC[39m, includeTimestamp: ESC[33mtrueESC[39m }, output: { name: ESC[32m'op-call-block-logs-extraction'ESC[39m
 } }, transformer: { module: [Module: null prototype] { onClose: ESC[36m[Function: onClose]ESC[39m, onLine: ESC[36m[Function: onLine]ESC[39m }, args: {}, input: { name: ESC[32m'op-call-block-logs-extraction'ESC[39m }, output: { name: ESC[32m'op-call-block-logs-transformation'ESC[39m } }, loader: { module: [Module: null prototype] { direct: ESC[36m[GeneratorFunction: direct]ESC[39m, order: ESC[36m[GeneratorFunction: order]ESC[39m }, input: { name: ESC[32m'op-call-blo
ck-logs-transformation'ESC[39m }, output: { name: ESC[32m'op-call-block-logs-load'ESC[39m } }

crash that leads to inconsistent trie data.

> await trie.checkRoot(await trie.root())
false

The error after that is

2024-02-01T00:01:06: 2024-02-01T00:01:06.345Z @attestate/kiwistand leaves: Trie root "e49c93db1dd3c722e8b3c75b07f2a5b61a01699f3e384437c7643772449129c4"
2024-02-01T00:01:06: /root/kiwistand/node_modules/@ethereumjs/trie/dist/trie/trie.js:309
2024-02-01T00:01:06:             throw new Error('Missing node in DB');
2024-02-01T00:01:06:                   ^
2024-02-01T00:01:06:
2024-02-01T00:01:06: Error: Missing node in DB
2024-02-01T00:01:06:     at Trie.lookupNode (/root/kiwistand/node_modules/@ethereumjs/trie/dist/trie/trie.js:309:19)
2024-02-01T00:01:06:     at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
2024-02-01T00:01:06:     at async walkTrieDfs (file:///root/kiwistand/src/store.mjs:581:16)
2024-02-01T00:01:06:     at async leaves (file:///root/kiwistand/src/store.mjs:535:25)
2024-02-01T00:01:06:     at async Module.posts (file:///root/kiwistand/src/store.mjs:487:17)
2024-02-01T00:01:06:     at async file:///root/kiwistand/src/launch.mjs:53:17
2024-02-01T00:01:06:
2024-02-01T00:01:06: Node.js v19.9.0
2024-02-01T00:01:07: 2024-02-01T00:01:07.562Z @attestate/kiwistand Launching as bootstrap node
2024-02-01T00:01:07: 2024-02-01T00:01:07.563Z @attestate/kiwistand Using id from disk.
2024-02-01T00:01:08: 2024-02-01T00:01:08.011Z @attestate/crawler:lifecycle Starting to execute

Here is what helped. Somehow trie root "e49c93db1dd3c722e8b3c75b07f2a5b61a01699f3e384437c7643772449129c4" couldn't be found anymore with await trie.checkRoot(Buffer.from("e49c93db1dd3c722e8b3c75b07f2a5b61a01699f3e384437c7643772449129c4", "hex")). So I went back in the logs and found the last root ddaae02d59d184e0f8278315499f5115c16d508bfe54c034f45e732cef0eb9fa.

Since the trie isn't pruning nodes, I was able to load the prior trie using await trie.root(Buffer.from("ddaae02d59d184e0f8278315499f5115c16d508bfe54c034f45e732cef0eb9fa", "hex")) and I then called trie.persistRoot()` upon which

> await trie.checkRoot(await trie.root())
true

My suspicion is that the program somehow crashes midway persisting the ethereumjs trie. Potentially it even crashes within ethereumjs/trie and so when it comes back up, maybe it has somehow already updated the trie root but it cannot find connections outgoing from the trie root or it can actually not query the newly updated root in the database. So resetting to the old and persisting makes it work again.