Standalone Mongodb suddenly failed and I'm unable to recover. Backups are also corrupt

Question

Running on FreeBSD/ZFS for several months, users reported trouble. At this point I'm out of options so any help is apreciated. The database backs a Node.js based authoring tool with a couple of users, so there isn't much load on it.

Summary (details below):

Mongodb 4.0.19 suddenly stops after months, with the error:

2021-04-16T23:03:46.877+0200 E STORAGE  [conn2] Failed to open a WiredTiger cursor: table:index-19-1736697557066001344

Running --repair didn't help:

2021-04-20T13:55:38.307+0200 W STORAGE  [initandlisten] Data file is missing for table:collection-6-997216952784910218. Attempting to drop and re-create the collection.
2021-04-20T13:55:38.307+0200 W STORAGE  [initandlisten] Moving data file /var/db/mongodb/collection-6-997216952784910218.wt to backup as /var/db/mongodb/collection-6-997216952784910218.wt.corrupt
2021-04-20T13:55:38.311+0200 W STORAGE  [initandlisten] Rebuilding ident collection-6-997216952784910218
2021-04-20T13:55:38.311+0200 E STORAGE  [initandlisten] Failed to get metadata for table:collection-6-997216952784910218
2021-04-20T13:55:38.311+0200 F STORAGE  [initandlisten] Failed to repair database 'adapt-tenant-master': Unable to find metadata for table:collection-6-997216952784910218
2021-04-20T13:55:38.311+0200 F STORAGE  [initandlisten] Record store did not exist. Collection: adapt-tenant-master.articles UUID: 1d718eb1-1263-48a8-a80e-e052e580898e
2021-04-20T13:55:38.311+0200 F -        [initandlisten] Fatal Assertion 50936 at src/mongo/db/catalog/database_impl.cpp 228

• Same result on all backups (ZFS snapshots), and the file that seems to be the problem always have a timestamp days in the past, rendering the backups useless.

• I've tries about 10 snapshots back to Mar 1st. And a few of them with Mongodb version 4.2 and 4.4. Also, just removing mongodb.lock just fails in a differet way, not surprisingly.

Questions:

1. Are there any other ways to recover worth trying? I'we noticed wt, but there are no package for FreeBSD. I assume I could compile it if its of any use.
2. Going forward, whats the culprit? How can I backup the database in a trustworthy way? Testing snapshot as the backup method worked fine initialy, and on one occasion last year. But maybe that was luck. If Mongodb are unable to detect data corruption, no fs-level backups can be trusted. The docs says journaling is enabled by default, and there are recent files in the /journal subdir. Are the docs wrong, is the mongodump the only trustworthy option? I've never utilized it.

More details

On investigation of the initial report, the last entries in the log were (note the time stamps):

2021-04-10T12:45:15.404+0200 I COMMAND  [conn8] command adapt-tenant-master.$cmd command: update { update: "sessions", ordered: true, lsid: { id: UUID("24fb5534-f57b-4cda-8ed0-cf266a61b4a4") }, $db: "adapt-tenant-master" } numYields:0 reslen:75 locks:{ Global: { acquireCount: { r: 30, w: 28 } }, Database: { acquireCount: { w: 28 } }, Collection: { acquireCount: { w: 28 } } } storage:{} protocol:op_query 110ms
2021-04-15T23:02:30.121+0200 I COMMAND  [conn5] command adapt-tenant-master.blocks command: find { find: "blocks", filter: { _courseId: ObjectId('5f912d3b0406a20d37ffa370') }, sort: { _sortOrder: 1 }, projection: {}, returnKey: false, showRecordId: false, $db: "adapt-tenant-master" } planSummary: COLLSCAN keysExamined:0 docsExamined:534 hasSortStage:1 cursorExhausted:1 numYields:5 nreturned:67 reslen:50340 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 6 } }, Collection: { acquireCount: { r: 6 } } } storage:{} protocol:op_query 183ms
2021-04-16T23:03:46.877+0200 E STORAGE  [conn2] Failed to open a WiredTiger cursor: table:index-19-1736697557066001344
2021-04-16T23:03:46.891+0200 E STORAGE  [conn2] This may be due to data corruption. Please read the documentation for starting MongoDB with --repair here: http://dochub.mongodb.org/core/repair
2021-04-16T23:03:46.925+0200 F -        [conn2] Fatal Assertion 50882 at src/mongo/db/storage/wiredtiger/wiredtiger_session_cache.cpp 143
2021-04-16T23:03:46.971+0200 F -        [conn2]

***aborting after fassert() failure 

Running repair gave no joy:

[mongodb@viten-adapt ~]$ /usr/local/bin/mongod --dbpath /var/db/mongodb --repair -vv
2021-04-20T13:42:50.112+0200 I CONTROL  [main] Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'
2021-04-20T13:42:50.120+0200 D NETWORK  [main] fd limit hard:1883169 soft:1883169 max conn: 1506535
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] MongoDB starting : pid=55015 port=27017 dbpath=/var/db/mongodb 64-bit host=viten-adapt.kunder.ravn.no
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] db version v4.0.19
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] git version: 7e28f4296a04d858a2e3dd84a1e79c9ba59a9568
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.2u-freebsd  20 Dec 2019
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] allocator: system
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] modules: none
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] build environment:
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten]     distarch: x86_64
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten]     target_arch: x86_64
2021-04-20T13:42:50.120+0200 I CONTROL  [initandlisten] options: { repair: true, storage: { dbPath: "/var/db/mongodb" }, systemLog: { verbosity: 2 } }
2021-04-20T13:42:50.120+0200 D NETWORK  [initandlisten] fd limit hard:1883169 soft:1883169 max conn: 1506535
2021-04-20T13:42:50.121+0200 W STORAGE  [initandlisten] Detected unclean shutdown - /var/db/mongodb/mongod.lock is not empty.
2021-04-20T13:42:50.129+0200 I STORAGE  [initandlisten] Detected data files in /var/db/mongodb created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2021-04-20T13:42:50.129+0200 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2021-04-20T13:42:50.129+0200 I STORAGE  [initandlisten] wiredtiger_open config: create,cache_size=32181M,cache_overflow=(file_max=0M),session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),
2021-04-20T13:42:51.033+0200 I STORAGE  [initandlisten] WiredTiger message [1618918971:33224][55015:0x809c16000], txn-recover: Main recovery loop: starting at 24/65924736 to 25/256
2021-04-20T13:42:51.033+0200 I STORAGE  [initandlisten] WiredTiger message [1618918971:33741][55015:0x809c16000], txn-recover: Recovering log 24 through 25
2021-04-20T13:42:51.071+0200 I STORAGE  [initandlisten] WiredTiger message [1618918971:71785][55015:0x809c16000], file:index-15-1736697557066001344.wt, txn-recover: Recovering log 25 through 25
2021-04-20T13:42:51.148+0200 I STORAGE  [initandlisten] WiredTiger message [1618918971:148821][55015:0x809c16000], file:index-15-1736697557066001344.wt, txn-recover: Set global recovery timestamp: 0
2021-04-20T13:42:51.210+0200 I RECOVERY [initandlisten] WiredTiger recoveryTimestamp. Ts: Timestamp(0, 0)
2021-04-20T13:42:51.211+0200 D COMMAND  [WTIdleSessionSweeper] BackgroundJob starting: WTIdleSessionSweeper
2021-04-20T13:42:51.211+0200 D STORAGE  [WTIdleSessionSweeper] starting WTIdleSessionSweeper thread
2021-04-20T13:42:51.211+0200 D COMMAND  [WTCheckpointThread] BackgroundJob starting: WTCheckpointThread
2021-04-20T13:42:51.211+0200 D STORAGE  [WTCheckpointThread] starting WTCheckpointThread thread
2021-04-20T13:42:51.211+0200 D COMMAND  [WTJournalFlusher] BackgroundJob starting: WTJournalFlusher
2021-04-20T13:42:51.211+0200 D STORAGE  [WTJournalFlusher] starting WTJournalFlusher thread
2021-04-20T13:42:51.218+0200 I STORAGE  [initandlisten] Repairing catalog metadata
2021-04-20T13:42:51.219+0200 I STORAGE  [initandlisten] Verify succeeded on uri table:_mdb_catalog. Not salvaging.
2021-04-20T13:42:51.219+0200 D STORAGE  [initandlisten] WiredTigerUtil::checkApplicationMetadataFormatVersion  uri: table:_mdb_catalog ok range 1 -> 1 current: 1
2021-04-20T13:42:51.219+0200 D STORAGE  [initandlisten] WiredTigerSizeStorer::load table:_mdb_catalog -> { numRecords: 24, dataSize: 11640 }
2021-04-20T13:42:51.219+0200 D RECOVERY [initandlisten] loadCatalog:

2021-04-20T13:42:51.220+0200 D RECOVERY [initandlisten] *(REMOVED STUFF)*

2021-04-20T13:55:38.269+0200 I STORAGE  [initandlisten] Storage engine is missing collection 'adapt-tenant-master.blocks' from its metadata. Attempting to locate and recover the data for collection-8-997216952784910218
2021-04-20T13:55:38.269+0200 I STORAGE  [initandlisten] Renaming data file /var/db/mongodb/collection-8-997216952784910218.wt to temporary file /var/db/mongodb/collection-8-997216952784910218.wt.tmp
2021-04-20T13:55:38.274+0200 I STORAGE  [initandlisten] Creating new RecordStore for collection adapt-tenant-master.blocks with UUID: 0d7f134b-433f-4276-b15d-3735467e8875
2021-04-20T13:55:38.274+0200 D STORAGE  [initandlisten] WiredTigerKVEngine::createRecordStore ns: adapt-tenant-master.blocks uri: table:collection-8-997216952784910218 config: type=file,memory_page_max=10m,split_pct=90,leaf_value_max=64MB,checksum=on,block_compressor=snappy,,key_format=q,value_format=u,app_metadata=(formatVersion=1),log=(enabled=true)
2021-04-20T13:55:38.278+0200 I STORAGE  [initandlisten] Moving orphaned data file back as /var/db/mongodb/collection-8-997216952784910218.wt
2021-04-20T13:55:38.283+0200 I STORAGE  [initandlisten] Salvaging ident collection-8-997216952784910218
2021-04-20T13:55:38.285+0200 I STORAGE  [initandlisten] Storage engine is missing collection 'adapt-tenant-master.roles' from its metadata. Attempting to locate and recover the data for collection-7-1736697557066001344
2021-04-20T13:55:38.285+0200 I STORAGE  [initandlisten] Renaming data file /var/db/mongodb/collection-7-1736697557066001344.wt to temporary file /var/db/mongodb/collection-7-1736697557066001344.wt.tmp
2021-04-20T13:55:38.290+0200 I STORAGE  [initandlisten] Creating new RecordStore for collection adapt-tenant-master.roles with UUID: 8bfe559c-4a88-4a76-a9c7-7fc748f5c441
2021-04-20T13:55:38.290+0200 D STORAGE  [initandlisten] WiredTigerKVEngine::createRecordStore ns: adapt-tenant-master.roles uri: table:collection-7-1736697557066001344 config: type=file,memory_page_max=10m,split_pct=90,leaf_value_max=64MB,checksum=on,block_compressor=snappy,,key_format=q,value_format=u,app_metadata=(formatVersion=1),log=(enabled=true)
2021-04-20T13:55:38.295+0200 I STORAGE  [initandlisten] Moving orphaned data file back as /var/db/mongodb/collection-7-1736697557066001344.wt
2021-04-20T13:55:38.299+0200 I STORAGE  [initandlisten] Salvaging ident collection-7-1736697557066001344
2021-04-20T13:55:38.304+0200 I CONTROL  [initandlisten] 
2021-04-20T13:55:38.304+0200 I CONTROL  [initandlisten] ** WARNING: Access control is not enabled for the database.
2021-04-20T13:55:38.304+0200 I CONTROL  [initandlisten] **          Read and write access to data and configuration is unrestricted.
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] 
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] ** WARNING: This server is bound to localhost.
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] **          Remote systems will be unable to connect to this server. 
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] **          Start the server with --bind_ip <address> to specify which IP 
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] **          addresses it should serve responses from, or with --bind_ip_all to
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] **          bind to all interfaces. If this behavior is desired, start the
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] **          server with --bind_ip 127.0.0.1 to disable this warning.
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] 
2021-04-20T13:55:38.305+0200 I CONTROL  [initandlisten] 
2021-04-20T13:55:38.307+0200 D STORAGE  [initandlisten]     Repairing database: adapt-tenant-master
2021-04-20T13:55:38.307+0200 I STORAGE  [initandlisten] repairDatabase adapt-tenant-master
2021-04-20T13:55:38.307+0200 I STORAGE  [initandlisten] Repairing collection adapt-tenant-master.articles
2021-04-20T13:55:38.307+0200 W STORAGE  [initandlisten] Data file is missing for table:collection-6-997216952784910218. Attempting to drop and re-create the collection.
2021-04-20T13:55:38.307+0200 W STORAGE  [initandlisten] Moving data file /var/db/mongodb/collection-6-997216952784910218.wt to backup as /var/db/mongodb/collection-6-997216952784910218.wt.corrupt
2021-04-20T13:55:38.311+0200 W STORAGE  [initandlisten] Rebuilding ident collection-6-997216952784910218
2021-04-20T13:55:38.311+0200 E STORAGE  [initandlisten] Failed to get metadata for table:collection-6-997216952784910218
2021-04-20T13:55:38.311+0200 F STORAGE  [initandlisten] Failed to repair database 'adapt-tenant-master': Unable to find metadata for table:collection-6-997216952784910218
2021-04-20T13:55:38.311+0200 F STORAGE  [initandlisten] Record store did not exist. Collection: adapt-tenant-master.articles UUID: 1d718eb1-1263-48a8-a80e-e052e580898e
2021-04-20T13:55:38.311+0200 F -        [initandlisten] Fatal Assertion 50936 at src/mongo/db/catalog/database_impl.cpp 228
2021-04-20T13:55:38.311+0200 F -        [initandlisten] 

***aborting after fassert() failure

So, the file in question was corrupt on Apr 1st also, but at that time it was timestamped elleven days earlier:

[mongodb@viten-adapt ~]$ ls -l /var/db/mongodb-backup/collection-6-997216952784910218*
-rw-------  1 mongodb  mongodb  49152 Mar 19 11:16 /var/db/mongodb-backup/collection-6-997216952784910218.wt

Running --repair on the older snapshot I have on disk, Mar 1st, gave the same result as earlier. Except the timestamp is now six days earlier:

[mongodb@viten-adapt ~]$ ls -l /var/db/mongodb-backup/collection-6-997216952784910218.wt 
-rw-------  1 mongodb  mongodb  53248 Feb 23 10:48 /var/db/mongodb-backup/collection-6-997216952784910218.wt

( END )

Answer 1

Starting with question 2:

I have found no clear answer, but it is now obvious to me that fs snapshots is not sufficient for MongoDB version 4.0.19. We'll upgrade MongoDB if we can and will start using mongodump in addition to the fs snapshots. We'll probably stop MongDB before snapshots are made. At this point I do not know how corrupt files goes undetected by MongoDB, or if a changed backup strategy will protect us. I hope starting MongoDB after backups will at lease expose corrupted files as soon as they appear.

Question 1 solved:

@Jjussi pointed us to a link that explained how to recover data using the wt-tool: https://www.fatalerrors.org/a/wiredtiger-tool-restores-mongodb-data.html

From docs and forums we initially thought the MongoDB 4.0+ could handle this with the --repair option, but that turned out to be wrong. We compiled the wt-tool and managed to repair the corrupted file. We still lost four days worth of data. All snapshots contained corrupted versions of the file in question, dated well before the snapshots own dates.

Matching collection names with filenames on disk was a challenge. The initial runs with the '--repair' option left log entries for most of the files. I discovered that field names could be found in clear text in the collection files, so thats how I identified the files not mentioned in the logs.

Please refer to the link a bow, but a quick recap would be:

1. Backup the directory of the corrupt database

2. Compile wt-tool and repair the corrupt file

3. Create a new database (delete content of the dbdir if you have a backup), and create the collections you need.

4. Make a list of collections and their corresponding filenames from the newly created database. I used the code snippet below.

5. Map collection names and filenames from the old database by checking logfile and/or grep -l for known field names.

6. Stop mongod, replace newly created files with files from the corrupt database and, of course, the file(s) fixed by wt-tool. Keeping the new filenames.

7. Run /usr/local/bin/mongod --dbpath /var/db/mongodb --repair -vv

8. Assuming aok so far, start mongodb and open the mongo shell.

9. Re-index all collections:

   db.getCollectionNames().forEach(function(coll_name) { var coll = db.getCollection(coll_name); coll.reIndex(); });

Code snippet listing collections and their filenames (without .wt):

   function findFileNames() {

      var adminDb = db.getSiblingDB("admin");
      var dbList = adminDb.runCommand({ "listDatabases": 1 }).databases;

      for (var i in dbList) {
    
        var dbToSearch = db.getSiblingDB(dbList[i].name);
        var collectionNames = dbToSearch.getCollectionNames();

        for(var i = 0; i < collectionNames.length; i++){
            var name = collectionNames[i];
            var stats = dbToSearch.getCollection(name).stats();
            print (dbToSearch + '.' + name + ' ' + stats.wiredTiger.uri);
        }
      }
   }

   print (findFileNames())