Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-35645

Fassert when starting up mongod after a snapshot restore

    • Type: Icon: Bug Bug
    • Resolution: Won't Fix
    • Priority: Icon: Major - P3 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
      

            Assignee:
            judah.schvimer@mongodb.com Judah Schvimer
            Reporter:
            lawrence.tan@mongodb.com Lawrence Tan (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated:
              Resolved: