-
Type: Bug
-
Resolution: Duplicate
-
Priority: Critical - P2
-
None
-
Affects Version/s: None
-
Component/s: Replication
-
None
-
ALL
2016-11-16T03:15:17.815+0000 I CONTROL [main] ***** SERVER RESTARTED ***** 2016-11-16T03:15:18.931+0000 I CONTROL [main] ***** SERVER RESTARTED ***** 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] MongoDB starting : pid=3657 port=27218 dbpath=/data0/mongo-config/data/ 64-bit host=nlhypheap041.navitaire.com 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] db version v3.2.5 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] git version: 34e65e5383f7ea1726332cb175b73077ec4a1b02 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] allocator: tcmalloc 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] modules: enterprise 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] build environment: 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] distmod: rhel70 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] distarch: x86_64 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] target_arch: x86_64 2016-11-16T03:15:18.941+0000 I CONTROL [initandlisten] options: { net: { port: 27218 }, processManagement: { fork: true, pidFilePath: "/data0/mongo-config/logs/mongo.pid" }, replication: { replSet: "nl-con fig" }, sharding: { clusterRole: "configsvr" }, storage: { dbPath: "/data0/mongo-config/data/", directoryPerDB: true }, systemLog: { destination: "file", logAppend: true, logRotate: "reopen", path: "/data0/ mongo-config/logs/mongo.log" } } 2016-11-16T03:15:18.967+0000 I - [initandlisten] Detected data files in /data0/mongo-config/data/ created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'. 2016-11-16T03:15:18.968+0000 W - [initandlisten] Detected unclean shutdown - /data0/mongo-config/data/mongod.lock is not empty. 2016-11-16T03:15:18.968+0000 W STORAGE [initandlisten] Recovering data from the last clean checkpoint. 2016-11-16T03:15:18.968+0000 I STORAGE [initandlisten] wiredtiger_open config: create,cache_size=8G,session_max=20000,eviction=(threads_max=4),config_base=false,statistics=(fast),log=(enabled=true,archive= true,path=journal,compressor=snappy),file_manager=(close_idle_time=100000),checkpoint=(wait=60,log_size=2GB),statistics_log=(wait=0), 2016-11-16T03:15:19.312+0000 I STORAGE [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs 2016-11-16T03:15:19.312+0000 I STORAGE [initandlisten] The size storer reports that the oplog contains 20609664 records totaling to 4061406103 bytes 2016-11-16T03:15:19.312+0000 I STORAGE [initandlisten] Sampling from the oplog between May 19 14:47:21:1 and Oct 25 02:57:50:1 to determine where to place markers for truncation 2016-11-16T03:15:19.312+0000 I STORAGE [initandlisten] Taking 254 samples and assuming that each section of oplog contains approximately 809888 records totaling to 159599111 bytes 2016-11-16T03:15:19.368+0000 I STORAGE [initandlisten] Placing a marker at optime Jun 7 11:19:24:3 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jun 13 02:15:58:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jun 18 17:01:32:3 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jun 24 11:54:17:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jun 30 07:43:00:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jul 5 23:03:52:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jul 11 11:09:09:4 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jul 17 00:15:26:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Jul 23 21:23:32:3 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Aug 3 00:31:17:2 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Aug 8 16:23:12:4 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Aug 14 08:43:22:2 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Aug 19 10:08:03:2 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Aug 24 17:35:23:2 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Aug 29 23:49:29:3 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 4 08:40:28:7 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 9 19:07:06:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 15 02:15:51:2 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 20 17:42:11:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Sep 26 03:12:45:3 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Oct 1 10:07:27:4 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Oct 6 17:05:48:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Oct 11 19:52:32:5 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Oct 17 05:09:14:1 2016-11-16T03:15:19.369+0000 I STORAGE [initandlisten] Placing a marker at optime Oct 22 11:59:40:1 2016-11-16T03:15:19.410+0000 I CONTROL [initandlisten] 2016-11-16T03:15:19.410+0000 I CONTROL [initandlisten] ** WARNING: Insecure configuration, access control is not enabled and no --bind_ip has been specified. 2016-11-16T03:15:19.410+0000 I CONTROL [initandlisten] ** Read and write access to data and configuration is unrestricted, 2016-11-16T03:15:19.410+0000 I CONTROL [initandlisten] ** and the server listens on all available network interfaces. 2016-11-16T03:15:19.410+0000 I CONTROL [initandlisten] 2016-11-16T03:15:19.420+0000 I FTDC [initandlisten] Initializing full-time diagnostic data capture with directory '/data0/mongo-config/data/diagnostic.data' 2016-11-16T03:15:19.420+0000 I NETWORK [initandlisten] waiting for connections on port 27218 2016-11-16T03:15:19.420+0000 I NETWORK [HostnameCanonicalizationWorker] Starting hostname canonicalization worker 2016-11-16T03:15:19.440+0000 I REPL [ReplicationExecutor] New replica set config in use: { _id: "nl-config", version: 1, configsvr: true, protocolVersion: 1, members: [ { _id: 0, host: "nlhypseap041.navitaire.com:27218", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 4.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "nlhypheap041.navitaire.com:27218", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 3.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "nlhypseap040.navitaire.com:27218", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 2.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 3, host: "nlhypheap040.navitaire.com:27218", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 } ], settings: { chainingAllowed: true, heartbeatIntervalMillis: 2000, heartbeatTimeoutSecs: 10, electionTimeoutMillis: 10000, getLastErrorModes: {}, getLastErrorDefaults: { w: 1, wtimeout: 0 }, replicaSetId: ObjectId('573dd1f90c43e512f78a0eb1') } } 2016-11-16T03:15:19.440+0000 I REPL [ReplicationExecutor] This node is nlhypheap041.navitaire.com:27218 in the config 2016-11-16T03:15:19.440+0000 I REPL [ReplicationExecutor] transition to STARTUP2 2016-11-16T03:15:19.440+0000 I REPL [ReplicationExecutor] Starting replication applier threads 2016-11-16T03:15:19.440+0000 I REPL [ReplicationExecutor] transition to RECOVERING 2016-11-16T03:15:19.445+0000 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to nlhypheap040.navitaire.com:27218 2016-11-16T03:15:19.446+0000 I REPL [ReplicationExecutor] Member nlhypheap040.navitaire.com:27218 is now in state SECONDARY 2016-11-16T03:15:19.446+0000 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to nlhypseap041.navitaire.com:27218 2016-11-16T03:15:19.448+0000 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to nlhypseap040.navitaire.com:27218 2016-11-16T03:15:19.448+0000 I REPL [ReplicationExecutor] Member nlhypseap041.navitaire.com:27218 is now in state PRIMARY 2016-11-16T03:15:19.448+0000 I NETWORK [initandlisten] connection accepted from 10.213.26.71:45776 #1 (1 connection now open) 2016-11-16T03:15:19.450+0000 I REPL [ReplicationExecutor] Member nlhypseap040.navitaire.com:27218 is now in state SECONDARY 2016-11-16T03:15:20.130+0000 I NETWORK [initandlisten] connection accepted from 10.213.26.70:53168 #2 (2 connections now open) 2016-11-16T03:15:20.340+0000 I NETWORK [initandlisten] connection accepted from 10.212.26.71:35348 #3 (3 connections now open) 2016-11-16T03:15:21.110+0000 I NETWORK [initandlisten] connection accepted from 10.213.26.70:53169 #4 (4 connections now open) 2016-11-16T03:15:21.239+0000 I NETWORK [initandlisten] connection accepted from 10.212.26.70:41543 #5 (5 connections now open) 2016-11-16T03:15:22.237+0000 I NETWORK [initandlisten] connection accepted from 10.213.26.71:45782 #6 (6 connections now open) 2016-11-16T03:15:24.249+0000 I NETWORK [initandlisten] connection accepted from 10.212.26.70:41545 #7 (7 connections now open) 2016-11-16T03:15:24.249+0000 I NETWORK [initandlisten] connection accepted from 10.212.26.70:41546 #8 (8 connections now open) 2016-11-16T03:15:24.349+0000 I NETWORK [initandlisten] connection accepted from 10.212.26.71:35352 #9 (9 connections now open) 2016-11-16T03:15:24.350+0000 I NETWORK [initandlisten] connection accepted from 10.212.26.71:35351 #10 (10 connections now open) 2016-11-16T03:15:25.442+0000 I REPL [ReplicationExecutor] syncing from: nlhypheap040.navitaire.com:27218 2016-11-16T03:15:25.445+0000 I REPL [SyncSourceFeedback] setting syncSourceFeedback to nlhypheap040.navitaire.com:27218 2016-11-16T03:15:25.447+0000 I ASIO [NetworkInterfaceASIO-BGSync-0] Successfully connected to nlhypheap040.navitaire.com:27218 2016-11-16T03:15:25.449+0000 I REPL [rsBackgroundSync] Starting rollback due to OplogStartMissing: our last op time fetched: (term: 47, timestamp: Oct 25 02:57:50:1). source's GTE: (term: 48, timestamp: Oct 25 02:57:50:1) hashes: (502322552398015638/711015327143776815) 2016-11-16T03:15:25.449+0000 I - [rsBackgroundSync] Fatal assertion 18750 UnrecoverableRollbackError: need to rollback, but in inconsistent state. minvalid: (term: 48, timestamp: Oct 25 02:57:50:3) > our last optime: (term: 47, timestamp: Oct 25 02:57:50:1) 2016-11-16T03:15:25.449+0000 I - [rsBackgroundSync] ***aborting after fassert() failure
- duplicates
-
SERVER-7200 use oplog as op buffer on secondaries
- Closed