2017-12-04T13:57:07.845+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54070 #72267 (12 connections now open)
|
2017-12-04T13:57:07.859+0330 I ACCESS [conn72267] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:57:07.870+0330 I - [conn72267] end connection 127.0.0.1:54070 (12 connections now open)
|
2017-12-04T13:57:17.848+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54072 #72268 (12 connections now open)
|
2017-12-04T13:57:17.883+0330 I ACCESS [conn72268] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:57:17.896+0330 I - [conn72268] end connection 127.0.0.1:54072 (12 connections now open)
|
2017-12-04T13:57:27.846+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54074 #72269 (12 connections now open)
|
2017-12-04T13:57:27.862+0330 I ACCESS [conn72269] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:57:27.869+0330 I - [conn72269] end connection 127.0.0.1:54074 (12 connections now open)
|
2017-12-04T13:57:37.846+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54076 #72270 (12 connections now open)
|
2017-12-04T13:57:37.862+0330 I ACCESS [conn72270] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:57:37.870+0330 I - [conn72270] end connection 127.0.0.1:54076 (12 connections now open)
|
2017-12-04T13:58:36.305+0330 I COMMAND [conn72244] command local.oplog.rs command: getMore { getMore: 14640453418, collection: "oplog.rs", maxTimeMS: 5000, term: 135, lastKnownCommittedOpTime: { ts: Timestamp 1512383285000|1, t: 135 } } originatingCommand: { find: "oplog.rs", filter: { ts: { $gte: Timestamp 1512383020000|1 } }, tailable: true, oplogReplay: true, awaitData: true, maxTimeMS: 60000, term: 135, readConcern: { afterOpTime: { ts: Timestamp 1512383020000|1, t: 134 } } } planSummary: COLLSCAN cursorid:14640453418 keysExamined:0 docsExamined:0 numYields:1 nreturned:0 reslen:451 locks:{ Global: { acquireCount: { r: 6 } }, Database: { acquireCount: { r: 3 } }, oplog: { acquireCount: { r: 3 } } } protocol:op_command 54138ms
|
2017-12-04T13:58:36.306+0330 I REPL [ReplicationExecutor] Starting an election, since we've seen no PRIMARY in the past 10000ms
|
2017-12-04T13:58:36.306+0330 I REPL [ReplicationExecutor] conducting a dry run election to see if we could be elected
|
2017-12-04T13:58:36.307+0330 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.16.12.166:27017
|
2017-12-04T13:58:36.307+0330 I ASIO [NetworkInterfaceASIO-Replication-0] Connecting to 172.16.12.167:27017
|
2017-12-04T13:58:36.309+0330 I REPL [ReplicationExecutor] VoteRequester(term 135 dry run) received a yes vote from 172.16.12.167:27017; response message: { term: 135, voteGranted: true, reason: "", ok: 1.0 }
|
2017-12-04T13:58:36.309+0330 I REPL [ReplicationExecutor] dry election run succeeded, running for election
|
2017-12-04T13:58:36.318+0330 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.16.12.167:27017, took 12ms (2 connections now open to 172.16.12.167:27017)
|
2017-12-04T13:58:36.318+0330 I REPL [ReplicationExecutor] VoteRequester(term 136) received a yes vote from 172.16.12.166:27017; response message: { term: 136, voteGranted: true, reason: "", ok: 1.0 }
|
2017-12-04T13:58:36.318+0330 I REPL [ReplicationExecutor] election succeeded, assuming primary role in term 136
|
2017-12-04T13:58:36.318+0330 I REPL [ReplicationExecutor] transition to PRIMARY
|
2017-12-04T13:58:36.319+0330 I REPL [ReplicationExecutor] Entering primary catch-up mode.
|
2017-12-04T13:58:36.319+0330 I ASIO [NetworkInterfaceASIO-Replication-0] Ending connection to host 172.16.12.167:27017 due to bad connection status; 1 connections to that host remain open
|
2017-12-04T13:58:36.320+0330 I REPL [ReplicationExecutor] Member 172.16.12.167:27017 is now in state SECONDARY
|
2017-12-04T13:58:36.320+0330 I REPL [ReplicationExecutor] Caught up to the latest optime known via heartbeats after becoming primary.
|
2017-12-04T13:58:36.320+0330 I REPL [ReplicationExecutor] Exited primary catch-up mode.
|
2017-12-04T13:58:36.320+0330 I ASIO [NetworkInterfaceASIO-RS-0] Ending connection to host 172.16.12.167:27017 due to bad connection status; 1 connections to that host remain open
|
2017-12-04T13:58:36.320+0330 I REPL [rsBackgroundSync] Replication producer stopped after oplog fetcher finished returning a batch from our sync source. Abandoning this batch of oplog entries and re-evaluating our sync source.
|
2017-12-04T13:58:36.321+0330 I ASIO [NetworkInterfaceASIO-Replication-0] Successfully connected to 172.16.12.166:27017, took 15ms (2 connections now open to 172.16.12.166:27017)
|
2017-12-04T13:58:36.620+0330 I REPL [SyncSourceFeedback] SyncSourceFeedback error sending update to 172.16.12.167:27017: InvalidSyncSource: Sync source was cleared. Was 172.16.12.167:27017
|
2017-12-04T13:58:37.749+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54082 #72271 (12 connections now open)
|
2017-12-04T13:58:37.775+0330 I ACCESS [conn72271] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:58:37.787+0330 I - [conn72271] end connection 127.0.0.1:54082 (12 connections now open)
|
2017-12-04T13:58:38.311+0330 I REPL [rsSync] transition to primary complete; database writes are now permitted
|
2017-12-04T13:58:42.884+0330 I NETWORK [thread1] connection accepted from 172.16.12.167:60834 #72272 (12 connections now open)
|
2017-12-04T13:58:42.885+0330 I NETWORK [conn72272] received client metadata from 172.16.12.167:60834 conn72272: { driver: { name: "NetworkInterfaceASIO-RS", version: "3.4.10" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
|
2017-12-04T13:58:42.890+0330 I ACCESS [conn72272] Successfully authenticated as principal __system on local
|
2017-12-04T13:58:47.751+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54084 #72273 (13 connections now open)
|
2017-12-04T13:58:47.776+0330 I ACCESS [conn72273] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:58:47.791+0330 I - [conn72273] end connection 127.0.0.1:54084 (13 connections now open)
|
2017-12-04T13:58:57.753+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54086 #72274 (13 connections now open)
|
2017-12-04T13:58:57.782+0330 I ACCESS [conn72274] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:58:57.795+0330 I - [conn72274] end connection 127.0.0.1:54086 (13 connections now open)
|
2017-12-04T13:59:07.749+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54088 #72275 (13 connections now open)
|
2017-12-04T13:59:07.763+0330 I ACCESS [conn72275] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:59:07.769+0330 I - [conn72275] end connection 127.0.0.1:54088 (13 connections now open)
|
2017-12-04T13:59:14.081+0330 I NETWORK [thread1] connection accepted from 172.16.12.166:46350 #72276 (13 connections now open)
|
2017-12-04T13:59:14.081+0330 I NETWORK [conn72276] received client metadata from 172.16.12.166:46350 conn72276: { driver: { name: "NetworkInterfaceASIO-Replication", version: "3.4.10" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
|
2017-12-04T13:59:14.081+0330 I - [conn72156] end connection 172.16.12.166:46126 (13 connections now open)
|
2017-12-04T13:59:14.086+0330 I NETWORK [thread1] connection accepted from 172.16.12.166:46352 #72277 (13 connections now open)
|
2017-12-04T13:59:14.086+0330 I ACCESS [conn72276] Successfully authenticated as principal __system on local
|
2017-12-04T13:59:14.086+0330 I NETWORK [conn72277] received client metadata from 172.16.12.166:46352 conn72277: { driver: { name: "NetworkInterfaceASIO-Replication", version: "3.4.10" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
|
2017-12-04T13:59:14.089+0330 I ACCESS [conn72277] Successfully authenticated as principal __system on local
|
2017-12-04T13:59:14.100+0330 I REPL [ReplicationExecutor] stepping down from primary, because a new term has begun: 137
|
2017-12-04T13:59:14.100+0330 I REPL [ReplicationExecutor] stepping down from primary, because a new term has begun: 137
|
2017-12-04T13:59:14.100+0330 I REPL [ReplicationExecutor] stepping down from primary, because a new term has begun: 137
|
2017-12-04T13:59:14.100+0330 I REPL [ReplicationExecutor] stepping down from primary, because a new term has begun: 137
|
2017-12-04T13:59:14.100+0330 I REPL [ReplicationExecutor] Member 172.16.12.166:27017 is now in state PRIMARY
|
2017-12-04T13:59:14.101+0330 I REPL [replExecDBWorker-2] transition to SECONDARY
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] legacy transport layer closing all connections
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] Skip closing connection for connection # 72277
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] Skip closing connection for connection # 72276
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] Skip closing connection for connection # 72272
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] Skip closing connection for connection # 72246
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] Skip closing connection for connection # 72244
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] Skip closing connection for connection # 72243
|
2017-12-04T13:59:14.101+0330 I NETWORK [replExecDBWorker-2] Skip closing connection for connection # 72158
|
2017-12-04T13:59:14.101+0330 I - [conn72173] end connection 172.16.132.145:60559 (13 connections now open)
|
2017-12-04T13:59:14.101+0330 I - [conn72172] end connection 172.16.132.145:60560 (13 connections now open)
|
2017-12-04T13:59:14.101+0330 I - [conn72171] end connection 172.16.132.145:60558 (11 connections now open)
|
2017-12-04T13:59:14.101+0330 I - [conn72164] end connection 172.16.132.145:60556 (10 connections now open)
|
2017-12-04T13:59:14.101+0330 I - [conn72163] end connection 172.16.132.145:60557 (10 connections now open)
|
2017-12-04T13:59:14.101+0330 I - [conn72162] end connection 172.16.132.145:60555 (8 connections now open)
|
2017-12-04T13:59:16.882+0330 I REPL [rsBackgroundSync] sync source candidate: 172.16.12.166:27017
|
2017-12-04T13:59:16.883+0330 I ASIO [NetworkInterfaceASIO-RS-0] Connecting to 172.16.12.166:27017
|
2017-12-04T13:59:16.890+0330 I ASIO [NetworkInterfaceASIO-RS-0] Successfully connected to 172.16.12.166:27017, took 7ms (1 connections now open to 172.16.12.166:27017)
|
2017-12-04T13:59:16.894+0330 I ASIO [NetworkInterfaceASIO-RS-0] Connecting to 172.16.12.166:27017
|
2017-12-04T13:59:16.898+0330 I - [conn72246] end connection 172.16.12.166:46290 (7 connections now open)
|
2017-12-04T13:59:16.903+0330 I ASIO [NetworkInterfaceASIO-RS-0] Successfully connected to 172.16.12.166:27017, took 9ms (2 connections now open to 172.16.12.166:27017)
|
2017-12-04T13:59:21.308+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54094 #72278 (7 connections now open)
|
2017-12-04T13:59:21.332+0330 I ACCESS [conn72278] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:59:21.338+0330 I - [conn72278] end connection 127.0.0.1:54094 (7 connections now open)
|
2017-12-04T13:59:32.130+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54096 #72279 (7 connections now open)
|
2017-12-04T13:59:32.162+0330 I ACCESS [conn72279] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:59:32.174+0330 I - [conn72279] end connection 127.0.0.1:54096 (7 connections now open)
|
2017-12-04T13:59:36.320+0330 I ASIO [NetworkInterfaceASIO-Replication-0] Ending idle connection to host 172.16.12.166:27017 because the pool meets constraints; 1 connections to that host remain open
|
2017-12-04T13:59:36.653+0330 I NETWORK [thread1] connection accepted from 172.16.12.167:60846 #72280 (7 connections now open)
|
2017-12-04T13:59:36.654+0330 I NETWORK [conn72280] received client metadata from 172.16.12.167:60846 conn72280: { driver: { name: "NetworkInterfaceASIO-Replication", version: "3.4.10" }, os: { type: "Linux", name: "Ubuntu", architecture: "x86_64", version: "16.04" } }
|
2017-12-04T13:59:36.659+0330 I ACCESS [conn72280] Successfully authenticated as principal __system on local
|
2017-12-04T13:59:37.115+0330 I REPL [ReplicationExecutor] Member 172.16.12.166:27017 is now in state SECONDARY
|
2017-12-04T13:59:37.117+0330 I REPL [ReplicationExecutor] Member 172.16.12.167:27017 is now in state PRIMARY
|
2017-12-04T13:59:37.443+0330 I REPL [replication-133] Choosing new sync source because our current sync source, 172.16.12.166:27017, has an OpTime ({ ts: Timestamp 1512383366000|1, t: 137 }) which is not ahead of ours ({ ts: Timestamp 1512383366000|1, t: 137 }), it does not have a sync source, and it's not the primary (sync source does not know the primary)
|
2017-12-04T13:59:37.443+0330 I REPL [replication-133] Canceling oplog query due to OplogQueryMetadata. We have to choose a new sync source. Current source: 172.16.12.166:27017, OpTime { ts: Timestamp 1512383366000|1, t: 137 }, its sync source index:-1
|
2017-12-04T13:59:37.443+0330 W REPL [rsBackgroundSync] Fetcher stopped querying remote oplog with error: InvalidSyncSource: sync source 172.16.12.166:27017 (config version: 1; last applied optime: { ts: Timestamp 1512383366000|1, t: 137 }; sync source index: -1; primary index: -1) is no longer valid
|
2017-12-04T13:59:37.444+0330 I REPL [rsBackgroundSync] could not find member to sync from
|
2017-12-04T13:59:41.333+0330 I - [conn72272] end connection 172.16.12.167:60834 (7 connections now open)
|
2017-12-04T13:59:41.888+0330 I REPL [SyncSourceFeedback] SyncSourceFeedback error sending update to 172.16.12.166:27017: InvalidSyncSource: Sync source was cleared. Was 172.16.12.166:27017
|
2017-12-04T13:59:43.240+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54098 #72281 (7 connections now open)
|
2017-12-04T13:59:43.273+0330 I ACCESS [conn72281] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:59:43.289+0330 I - [conn72281] end connection 127.0.0.1:54098 (7 connections now open)
|
2017-12-04T13:59:43.446+0330 I REPL [rsBackgroundSync] sync source candidate: 172.16.12.167:27017
|
2017-12-04T13:59:43.450+0330 I ASIO [NetworkInterfaceASIO-RS-0] Connecting to 172.16.12.167:27017
|
2017-12-04T13:59:43.461+0330 I ASIO [NetworkInterfaceASIO-RS-0] Connecting to 172.16.12.167:27017
|
2017-12-04T13:59:43.462+0330 I ASIO [NetworkInterfaceASIO-RS-0] Successfully connected to 172.16.12.167:27017, took 12ms (3 connections now open to 172.16.12.167:27017)
|
2017-12-04T13:59:43.468+0330 I ASIO [NetworkInterfaceASIO-RS-0] Successfully connected to 172.16.12.167:27017, took 13ms (3 connections now open to 172.16.12.167:27017)
|
2017-12-04T13:59:45.668+0330 I COMMAND [ftdc] serverStatus was very slow: { after basic: 0, after asserts: 0, after backgroundFlushing: 0, after connections: 0, after dur: 0, after extra_info: 0, after globalLock: 0, after locks: 0, after network: 0, after opLatencies: 0, after opcounters: 0, after opcountersRepl: 0, after repl: 0, after security: 0, after storageEngine: 0, after tcmalloc: 0, after wiredTiger: 1306, at end: 1306 }
|
2017-12-04T13:59:55.651+0330 I NETWORK [thread1] connection accepted from 127.0.0.1:54104 #72282 (7 connections now open)
|
2017-12-04T13:59:55.668+0330 I ACCESS [conn72282] Successfully authenticated as principal mongodb_exporter on admin
|
2017-12-04T13:59:55.674+0330 I - [conn72282] end connection 127.0.0.1:54104 (7 connections now open)
|