# Kiwi News critical database corruption writeup

Source: https://github.com/attestate/kiwistand/issues/131
Kiwi News: https://news.kiwistand.com/stories/Kiwi-News-critical-database-corruption-writeup?index=0x65baef9d4a6e71164c23f8b1b8754d4c2e30a5ad05f9099685b78b57cc21f4f1284c62a3
Submitted by tim on 2024-02-01 UTC, 3 upvotes, 1 comment

## Summary

The writeup describes a Kiwi News node crash that left its Merkle trie in an inconsistent state, with the error "Missing node in DB" when reading the root e49c93db1dd3c722e8b3c75b07f2a5b61a01699f3e384437c7643772449129c4. The author found that trie.checkRoot returned false for that root, then loaded the prior root ddaae02d59d184e0f8278315499f5115c16d508bfe54c034f45e732cef0eb9fa, which the logs showed as the last good root. After calling trie.persistRoot(), checkRoot returned true, and the author suspects the program crashed partway through persisting the ethereumjs trie.

## Article

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.

## Comments

**tim**: Hey,

if you've used the site between 1 am and 2 am today (2024-02-01), then you might have noticed that it was down for an hour. This was due to a known corruption issue in the database that we don't exactly know where it comes from. We're still investigating. 

It took us a while to find a solution because corrupted databases are always really scary, and mistakes can be consequential. But by rolling back the trie's root to the prior root, we managed to recover all messages, and the site is now back up.

This is very good because today was an all-time high in DAU, and it would have been so bad if that data on the achievement was now lost!