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

Fassert on mongod 4.0 startup after a snapshot restore

    • Type: Icon: Bug Bug
    • Resolution: Works as Designed
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Replication
    • Labels:
      None
    • ALL

      We're seeing this cloud provider snapshot restore problem only when using MongoDB 4.0.

      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] 
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] ** WARNING: mongod started without --replSet yet 1 documents are present in local.system.replset.
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] **          Database contents may appear inconsistent with the oplog and may appear to not contain
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] **          writes that were visible when this node was running as part of a replica set.
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] **          Restart with --replSet unless you are doing maintenance and no other clients are connected.
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] **          The TTL collection monitor will not start because of this.
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] **         
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten]  For more info see http://dochub.mongodb.org/core/ttlcollections
      2018-06-19T22:30:05.354+0000 I STORAGE  [initandlisten] 
      2018-06-19T22:30:05.354+0000 I NETWORK  [initandlisten] waiting for connections on port 37303
      2018-06-19T22:30:05.356+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:53694 #1 (1 connection now open)
      2018-06-19T22:30:05.363+0000 I NETWORK  [listener] connection accepted from 127.0.0.1:53696 #2 (2 connections now open)
      2018-06-19T22:30:05.365+0000 I COMMAND  [conn1] CMD: drop local.oplog.rs
      2018-06-19T22:30:05.365+0000 I STORAGE  [conn1] Finishing collection drop for local.oplog.rs (24733bdc-79a3-4aed-b55b-a9631d878412).
      2018-06-19T22:30:05.365+0000 I STORAGE  [WTOplogJournalThread] oplog journal thread loop shutting down
      2018-06-19T22:30:05.370+0000 I STORAGE  [conn2] createCollection: local.oplog.rs with generated UUID: 80ce55c5-5ea3-4801-aebc-066682250d20
      2018-06-19T22:30:05.394+0000 I STORAGE  [conn2] WiredTigerRecordStoreThread local.oplog.rs already started
      2018-06-19T22:30:05.394+0000 I STORAGE  [conn2] The size storer reports that the oplog contains 0 records totaling to 0 bytes
      2018-06-19T22:30:05.394+0000 I STORAGE  [conn2] Scanning the oplog to determine where to place markers for truncation
      2018-06-19T22:30:05.395+0000 E STORAGE  [conn1] WiredTiger error (22) [1529447405:395315][11099:0x7fb2e89e6700], WT_SESSION.timestamp_transaction: commit timestamp 495C078000000001 older than oldest timestamp 5b297d9000000001: Invalid argument Raw: [1529447405:395315][11099:0x7fb2e89e6700], WT_SESSION.timestamp_transaction: commit timestamp 495C078000000001 older than oldest timestamp 5b297d9000000001: Invalid argument
      2018-06-19T22:30:05.395+0000 F -        [conn1] Fatal assertion 39001 BadValue: timestamp_transaction 22: Invalid argument at src/mongo/db/storage/wiredtiger/wiredtiger_record_store.cpp 1243
      2018-06-19T22:30:05.395+0000 F -        [conn1] 
       
      ***aborting after fassert() failure
      

      We first saw this issue on the following E2E tests:

      However, we can reproduce the same problem when doing the cloud provider restore (w/ mongod 4.0) on cloud-qa env.

            Assignee:
            tess.avitabile@mongodb.com Tess Avitabile (Inactive)
            Reporter:
            lawrence.tan@mongodb.com Lawrence Tan (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            11 Start watching this issue

              Created:
              Updated:
              Resolved: