Database fails to start

MongoDB version: 5.0.6
System: Arch Linux kernel: 5.17.5-arch1-1

I have 400GB mongodb database on single host with a few collections. Before last weekend my friend started to transfer one of the collections from this db to another replica set. It seems all data was copied, but might be still running some background mongodb operation while the host was shut down . Because I did a system upgrade on Sunday. I use Arch Linux, so mongodb wasn’t upgraded as it is an external package there.

Right now mongo refuses to start.

{"t":{"$date":"2022-05-10T12:01:43.871+02:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"thread1","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2022-05-10T12:01:43.871+02:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"thread1","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
{"t":{"$date":"2022-05-10T12:01:43.871+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"thread1","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-05-10T12:01:43.871+02:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"thread1","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2022-05-10T12:01:43.872+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"thread1","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-05-10T12:01:43.872+02:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"thread1","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
{"t":{"$date":"2022-05-10T12:01:43.872+02:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"thread1","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
{"t":{"$date":"2022-05-10T12:01:43.872+02:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"thread1","msg":"Multi threading initialized"}
{"t":{"$date":"2022-05-10T12:01:43.873+02:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":2945870,"port":27017,"dbPath":"/var/lib/mongodb","architecture":"64-bit","host":"xxx"}}
{"t":{"$date":"2022-05-10T12:01:43.873+02:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.6","gitVersion":"212a8dbb47f07427dae194a9c75baec1d81d9259","openSSLVersion":"OpenSSL 1.1.1o  3 May 2022","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2022-05-10T12:01:43.873+02:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"NAME=\"Arch Linux\"","version":"Kernel 5.17.5-arch1-1"}}}
{"t":{"$date":"2022-05-10T12:01:43.873+02:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"config":"/etc/mongodb.conf","net":{"bindIp":"0.0.0.0"},"security":{"authorization":"enabled"},"storage":{"dbPath":"/var/lib/mongodb","wiredTiger":{"engineConfig":{"cacheSizeGB":8}}},"systemLog":{"destination":"file","logAppend":true,"path":"/var/log/mongodb/mongod.log","quiet":true}}}}
{"t":{"$date":"2022-05-10T12:01:43.873+02:00"},"s":"I",  "c":"STORAGE",  "id":22270,   "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongodb","storageEngine":"wiredTiger"}}
{"t":{"$date":"2022-05-10T12:01:43.874+02:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=8192M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
{"t":{"$date":"2022-05-10T12:01:44.717+02:00"},"s":"F",  "c":"STORAGE",  "id":4671205, "ctx":"initandlisten","msg":"This version of MongoDB is too recent to start up on the existing data files. Try MongoDB 4.2 or earlier."}
{"t":{"$date":"2022-05-10T12:01:44.717+02:00"},"s":"F",  "c":"-",        "id":23091,   "ctx":"initandlisten","msg":"Fatal assertion","attr":{"msgid":4671205,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp","line":653}}
{"t":{"$date":"2022-05-10T12:01:44.717+02:00"},"s":"F",  "c":"-",        "id":23092,   "ctx":"initandlisten","msg":"\n\n***aborting after fassert() failure\n\n"}

I tried to make --rapair, but it fails:

{"t":{"$date":"2022-05-10T12:05:00.006+02:00"},"s":"I",  "c":"CONTROL",  "id":23285,   "ctx":"-","msg":"Automatically disabling TLS 1.0, to force-enable TLS 1.0 specify --sslDisabledProtocols 'none'"}
{"t":{"$date":"2022-05-10T12:05:00.007+02:00"},"s":"I",  "c":"NETWORK",  "id":4915701, "ctx":"main","msg":"Initialized wire specification","attr":{"spec":{"incomingExternalClient":{"minWireVersion":0,"maxWireVersion":13},"incomingInternalClient":{"minWireVersion":0,"maxWireVersion":13},"outgoing":{"minWireVersion":0,"maxWireVersion":13},"isInternalClient":true}}}
{"t":{"$date":"2022-05-10T12:05:00.007+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-05-10T12:05:00.007+02:00"},"s":"I",  "c":"NETWORK",  "id":4648601, "ctx":"main","msg":"Implicit TCP FastOpen unavailable. If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, and tcpFastOpenQueueSize."}
{"t":{"$date":"2022-05-10T12:05:00.008+02:00"},"s":"W",  "c":"ASIO",     "id":22601,   "ctx":"main","msg":"No TransportLayer configured during NetworkInterface startup"}
{"t":{"$date":"2022-05-10T12:05:00.008+02:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationDonorService","ns":"config.tenantMigrationDonors"}}
{"t":{"$date":"2022-05-10T12:05:00.008+02:00"},"s":"I",  "c":"REPL",     "id":5123008, "ctx":"main","msg":"Successfully registered PrimaryOnlyService","attr":{"service":"TenantMigrationRecipientService","ns":"config.tenantMigrationRecipients"}}
{"t":{"$date":"2022-05-10T12:05:00.008+02:00"},"s":"I",  "c":"CONTROL",  "id":5945603, "ctx":"main","msg":"Multi threading initialized"}
{"t":{"$date":"2022-05-10T12:05:00.009+02:00"},"s":"I",  "c":"CONTROL",  "id":4615611, "ctx":"initandlisten","msg":"MongoDB starting","attr":{"pid":2945898,"port":27017,"dbPath":"/var/lib/mongodb/","architecture":"64-bit","host":"epyc"}}
{"t":{"$date":"2022-05-10T12:05:00.009+02:00"},"s":"I",  "c":"CONTROL",  "id":23403,   "ctx":"initandlisten","msg":"Build Info","attr":{"buildInfo":{"version":"5.0.6","gitVersion":"212a8dbb47f07427dae194a9c75baec1d81d9259","openSSLVersion":"OpenSSL 1.1.1o  3 May 2022","modules":[],"allocator":"tcmalloc","environment":{"distmod":"ubuntu2004","distarch":"x86_64","target_arch":"x86_64"}}}}
{"t":{"$date":"2022-05-10T12:05:00.009+02:00"},"s":"I",  "c":"CONTROL",  "id":51765,   "ctx":"initandlisten","msg":"Operating System","attr":{"os":{"name":"NAME=\"Arch Linux\"","version":"Kernel 5.17.5-arch1-1"}}}
{"t":{"$date":"2022-05-10T12:05:00.009+02:00"},"s":"I",  "c":"CONTROL",  "id":21951,   "ctx":"initandlisten","msg":"Options set by command line","attr":{"options":{"repair":true,"storage":{"dbPath":"/var/lib/mongodb/"}}}}
{"t":{"$date":"2022-05-10T12:05:00.075+02:00"},"s":"I",  "c":"STORAGE",  "id":22270,   "ctx":"initandlisten","msg":"Storage engine to use detected by data files","attr":{"dbpath":"/var/lib/mongodb/","storageEngine":"wiredTiger"}}
{"t":{"$date":"2022-05-10T12:05:00.075+02:00"},"s":"I",  "c":"STORAGE",  "id":22315,   "ctx":"initandlisten","msg":"Opening WiredTiger","attr":{"config":"create,cache_size=128314M,session_max=33000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive=true,path=journal,compressor=snappy),builtin_extension_config=(zstd=(compression_level=6)),file_manager=(close_idle_time=600,close_scan_interval=10,close_handle_minimum=250),statistics_log=(wait=0),verbose=[recovery_progress,checkpoint_progress,compact_progress],"}}
{"t":{"$date":"2022-05-10T12:05:00.990+02:00"},"s":"F",  "c":"STORAGE",  "id":4671205, "ctx":"initandlisten","msg":"This version of MongoDB is too recent to start up on the existing data files. Try MongoDB 4.2 or earlier."}
{"t":{"$date":"2022-05-10T12:05:00.990+02:00"},"s":"F",  "c":"-",        "id":23091,   "ctx":"initandlisten","msg":"Fatal assertion","attr":{"msgid":4671205,"file":"src/mongo/db/storage/wiredtiger/wiredtiger_kv_engine.cpp","line":653}}
{"t":{"$date":"2022-05-10T12:05:00.990+02:00"},"s":"F",  "c":"-",        "id":23092,   "ctx":"initandlisten","msg":"\n\n***aborting after fassert() failure\n\n"}

It seems to me this ticket should not apply to our use case as mongodb was not upgraded.

Will appreciate any kind of help.

Ok, it seems a bit worse. Probably mongodb was unexpectedly updated a few months back, but it was not reloaded. This is why right now this bug occurs.

I went in my logs back to previous mongodb restart and it seems it was on db version 4.0.6

2021-12-29T18:43:36.040+0100 I CONTROL  [initandlisten] db version v4.0.6
2021-12-29T18:43:36.040+0100 I CONTROL  [initandlisten] git version: caa42a1f75a56c7643d0b68d3880444375ec42e3

Then after upgrading to 5.0.6 I guess ticket might be relevant (This version of MongoDB is too recent to start up on the existing data files. Try MongoDB 4.2 or earlier.). The thing is, it was stated the bug is resolved for 5.0.6. So what are your recommendations right now?

Seems to be fixed. Downgraded mongodb to 4.0.6. No data loss. So now I can prepare data for safe migration.

1 Like

Hi @kriestof welcome to the community!

I’m glad that you’re able to get the deployment going again. However I wanted to add a couple of things:

  1. The log message This version of MongoDB is too recent to start up on the existing data files. Try MongoDB 4.2 or earlier. says that for some reason, the content of your dbpath is from an older MongoDB version, and you’re trying to use that old dbpath with a MongoDB binary that is newer than 4.2 (perhaps 5.0.6 in your case). What I’m guessing happened is that the copy is a file copy instead of a mongodump followed by mongorestore. Please avoid manually editing the content of the dbpath as it can lead to unrecoverable issues.
  2. MongoDB 4.0 series was out of support since April 2022, so it will receive no further updates. Please upgrade to a supported versions as soon as convenient. Note that MongoDB only allow in-place binary upgrades between major versions, so to go from 4.0 to 5.0, you’ll need to do 4.0 → 4.2 → 4.4 → 5.0. There are more information in the docs, e.g. Upgrade a Replica Set to 4.2.

Best regards
Kevin

This topic was automatically closed 5 days after the last reply. New replies are no longer allowed.