-
Type: Bug
-
Resolution: Won't Fix
-
Priority: Major - P3
-
None
-
Affects Version/s: None
-
Component/s: None
-
None
-
ALL
We were QA’ing cloud provider snapshot restore and saw this fassert error on the mongod logs of the target cluster being restored to:
2018-06-15T21:01:50.330+0000 I CONTROL [main] ***** SERVER RESTARTED ***** 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] MongoDB starting : pid=52437 port=27017 dbpath=/srv/mongodb/Cluster0-shard-0-node-0 64-bit host=cluster0-shard-00-00-kpnvd.mongodb-qa.net 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] db version v3.6.5 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] git version: a20ecd3e3a174162052ff99913bc2ca9a839d618 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] allocator: tcmalloc 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] modules: enterprise 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] build environment: 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] distmod: rhel70 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] distarch: x86_64 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] target_arch: x86_64 2018-06-15T21:01:50.378+0000 I CONTROL [initandlisten] options: { config: "/srv/mongodb/Cluster0-shard-0-node-0/automation-mongod.conf", net: { bindIp: "0.0.0.0", compression: { compressors: "snappy,zlib" }, maxIncomingConnections: 350, port: 27017, ssl: { CAFile: "/etc/pki/tls/certs/atlas-bundle.crt", PEMKeyFile: "/etc/pki/tls/private/mongod.pem", mode: "requireSSL", weakCertificateValidation: true } }, processManagement: { fork: true }, replication: { replSetName: "Cluster0-shard-0" }, security: { authorization: "enabled", enableEncryption: true, keyFile: "/var/lib/mongodb-mms-automation/keyfile", kmip: { clientCertificateFile: "/tmp/kmipClient.pem", port: 35696, serverCAFile: "/tmp/kmipCA.pem", serverName: "127.0.0.1" } }, setParameter: { honorSystemUmask: "true", ttlMonitorEnabled: "true", watchdogPeriodSeconds: "60" }, storage: { dbPath: "/srv/mongodb/Cluster0-shard-0-node-0", engine: "wiredTiger", wiredTiger: { engineConfig: { configString: "cache_size=512MB" } } }, systemLog: { destination: "file", logAppend: true, path: "/srv/mongodb/Cluster0-shard-0-node-0/mongodb.log" } } 2018-06-15T21:01:50.379+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=406M,session_max=20000,eviction=(threads_min=4,threads_max=4),config_base=false,statistics=(fast),cache_cursors=false,log=(enabled=true,archive=true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),statistics_log=(wait=0),verbose=(recovery_progress),encryption=(name=AES256-CBC,keyid=".system"),extensions=[local={entry=mongo_addWiredTigerEncryptors,early_load=true},,],cache_size=512MB 2018-06-15T21:01:51.090+0000 I STORAGE [initandlisten] Opening WiredTiger keystore. Config: create,compatibility=(release=2.9),config_base=false,log=(enabled,file_max=3MB),transaction_sync=(enabled=true,method=fsync),extensions=[local={entry=mongo_addWiredTigerEncryptors,early_load=true},],encryption=(name=AES256-CBC,keyid=.master), 2018-06-15T21:01:51.256+0000 I STORAGE [initandlisten] WiredTiger message [1529096511:256657][52437:0x7f2e70bf6b00], txn-recover: Main recovery loop: starting at 8/15744 2018-06-15T21:01:51.359+0000 I STORAGE [initandlisten] WiredTiger message [1529096511:359676][52437:0x7f2e70bf6b00], txn-recover: Recovering log 8 through 9 2018-06-15T21:01:51.421+0000 I STORAGE [initandlisten] WiredTiger message [1529096511:421326][52437:0x7f2e70bf6b00], txn-recover: Recovering log 9 through 9 2018-06-15T21:01:51.472+0000 I STORAGE [initandlisten] WiredTiger message [1529096511:472347][52437:0x7f2e70bf6b00], txn-recover: Set global recovery timestamp: 0 2018-06-15T21:01:51.490+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs 2018-06-15T21:01:51.490+0000 I STORAGE [initandlisten] The size storer reports that the oplog contains 1 records totaling to 122 bytes 2018-06-15T21:01:51.490+0000 I STORAGE [initandlisten] Scanning the oplog to determine where to place markers for truncation 2018-06-15T21:01:51.494+0000 I STORAGE [initandlisten] Encryption key manager initialized using KMIP key with id: f8a72ac8-98d9-4e4c-b2bc-353ab83652a9. 2018-06-15T21:01:51.494+0000 I CONTROL [initandlisten] Starting Watchdog Monitor 2018-06-15T21:01:51.520+0000 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/srv/mongodb/Cluster0-shard-0-node-0/diagnostic.data' 2018-06-15T21:01:51.520+0000 I REPL [initandlisten] Did not find local voted for document at startup. 2018-06-15T21:01:51.521+0000 I REPL [initandlisten] Rollback ID is 1 2018-06-15T21:01:51.521+0000 I REPL [initandlisten] Starting recovery oplog application at the appliedThrough: { ts: Timestamp(1529078763, 1), t: 2 } 2018-06-15T21:01:51.521+0000 F REPL [initandlisten] Applied op { : Timestamp(1529078763, 1) } not found. Top of oplog is { : Timestamp(1230768000, 1) }. 2018-06-15T21:01:51.521+0000 F - [initandlisten] Fatal Assertion 40313 at src/mongo/db/repl/replication_recovery.cpp 188 2018-06-15T21:01:51.521+0000 F - [initandlisten] ***aborting after fassert() failure