2016-03-30T04:24:14.635+0000 D EXECUTOR [repl writer worker 11] waiting for work; I am one of 16 thread(s); the minimum number of threads is 16
2016-03-30T04:24:14.635+0000 D STORAGE  [repl writer worker 9] WT commit_transaction
2016-03-30T04:24:14.635+0000 D QUERY    [repl writer worker 13] Using idhack: { _id: ObjectId('56faac1bb91f4a5db810ec2d') }
2016-03-30T04:24:14.634+0000 I NETWORK  [conn37] end connection 10.2.35.14:41450 (61 connections now open)
2016-03-30T04:24:14.635+0000 D STORAGE  [repl writer worker 9] WT begin_transaction
2016-03-30T04:24:14.635+0000 D STORAGE  [repl writer worker 5] WT commit_transaction
2016-03-30T04:24:14.635+0000 D EXECUTOR [rsBackgroundSync-0] Scheduling remote command request: RemoteCommand 25947 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:24.635+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:14.635+0000 D STORAGE  [repl writer worker 5] WT begin_transaction
2016-03-30T04:24:14.635+0000 D ASIO     [rsBackgroundSync-0] startCommand: RemoteCommand 25947 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:24.635+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:14.635+0000 D STORAGE  [repl writer worker 13] WT begin_transaction
2016-03-30T04:24:14.635+0000 D EXECUTOR [rsBackgroundSync-0] waiting for work; I am one of 1 thread(s); the minimum number of threads is 1
2016-03-30T04:24:14.635+0000 D WRITE    [repl writer worker 5] UpdateResult --  upserted: {} modifiers: 1 existing: 1 numDocsModified: 1 numMatched: 1
2016-03-30T04:24:14.635+0000 D WRITE    [repl writer worker 9] UpdateResult --  upserted: {} modifiers: 1 existing: 1 numDocsModified: 1 numMatched: 1
2016-03-30T04:24:14.635+0000 D ASIO     [NetworkInterfaceASIO-BGSync-0] Initiating asynchronous command: RemoteCommand 25947 -- target:AMZ-SIN-WallE-35-15:27017 db:l...skipping...
2016-03-30T04:24:15.776+0000 D NETWORK  [conn14] SocketException: remote: 10.2.35.13:29841 error: 9001 socket exception [CLOSED] server [10.2.35.13:29841] 
2016-03-30T04:24:15.776+0000 I NETWORK  [conn14] end connection 10.2.35.13:29841 (58 connections now open)
2016-03-30T04:24:15.776+0000 D NETWORK  [conn13] SocketException: remote: 10.2.35.13:29840 error: 9001 socket exception [CLOSED] server [10.2.35.13:29840] 
2016-03-30T04:24:15.777+0000 I NETWORK  [conn13] end connection 10.2.35.13:29840 (58 connections now open)
2016-03-30T04:24:15.777+0000 D NETWORK  [conn33] Socket recv() conn closed? 10.2.35.13:29867
2016-03-30T04:24:15.777+0000 D NETWORK  [conn34] Socket recv() conn closed? 10.2.35.13:29868
2016-03-30T04:24:15.777+0000 D NETWORK  [conn43] Socket recv() conn closed? 10.2.35.13:29871
2016-03-30T04:24:15.777+0000 D NETWORK  [conn34] SocketException: remote: 10.2.35.13:29868 error: 9001 socket exception [CLOSED] server [10.2.35.13:29868] 
2016-03-30T04:24:15.777+0000 D NETWORK  [conn33] SocketException: remote: 10.2.35.13:29867 error: 9001 socket exception [CLOSED] server [10.2.35.13:29867] 
2016-03-30T04:24:15.777+0000 I NETWORK  [conn34] end connection 10.2.35.13:29868 (56 connections now open)
2016-03-30T04:24:15.777+0000 I NETWORK  [conn33] end connection 10.2.35.13:29867 (56 connections now open)
2016-03-30T04:24:15.777+0000 D NETWORK  [conn43] SocketException: remote: 10.2.35.13:29871 error: 9001 socket exception [CLOSED] server [10.2.35.13:29871] 
2016-03-30T04:24:15.777+0000 D NETWORK  [conn42] Socket recv() conn closed? 10.2.35.13:29870
2016-03-30T04:24:15.777+0000 I NETWORK  [conn43] end connection 10.2.35.13:29871 (55 connections now open)
2016-03-30T04:24:15.777+0000 D NETWORK  [conn42] SocketException: remote: 10.2.35.13:29870 error: 9001 socket exception [CLOSED] server [10.2.35.13:29870] 
2016-03-30T04:24:15.777+0000 I NETWORK  [conn42] end connection 10.2.35.13:29870 (53 connections now open)
2016-03-30T04:24:15.783+0000 D EXECUTOR [NetworkInterfaceASIO-BGSync-0] Received remote response: RemoteResponse --  cmd:{ cursor: { nextBatch: [], id: 102312238058, ns: "local.oplog.rs" }, ok: 1.0 }
2016-03-30T04:24:15.783+0000 D EXECUTOR [rsBackgroundSync-0] Executing a task on behalf of pool rsBackgroundSync
2016-03-30T04:24:15.783+0000 D ASIO     [NetworkInterfaceASIO-BGSync-0] Failed to time operation 26397 out: Operation aborted.
2016-03-30T04:24:15.783+0000 D REPL     [rsBackgroundSync-0] fetcher read 0 operations from remote oplog
2016-03-30T04:24:15.783+0000 D EXECUTOR [rsBackgroundSync-0] Scheduling remote command request: RemoteCommand 26399 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:25.783+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:15.783+0000 D ASIO     [rsBackgroundSync-0] startCommand: RemoteCommand 26399 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:25.783+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:15.784+0000 D EXECUTOR [rsBackgroundSync-0] waiting for work; I am one of 1 thread(s); the minimum number of threads is 1
2016-03-30T04:24:15.784+0000 D ASIO     [NetworkInterfaceASIO-BGSync-0] Initiating asynchronous command: RemoteCommand 26399 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:25.783+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:15.784+0000 D ASIO     [NetworkInterfaceASIO-BGSync-0] Starting asynchronous command 26399 on host AMZ-SIN-WallE-35-15:27017
2016-03-30T04:24:15.806+0000 D STORAGE  [WTJournalFlusher] flushed journal
2016-03-30T04:24:15.870+0000 D NETWORK  [conn30] Socket recv() conn closed? 10.2.35.16:38778
2016-03-30T04:24:15.870+0000 D NETWORK  [conn7] Socket recv() conn closed? 10.2.35.16:38748
2016-03-30T04:24:15.870+0000 D NETWORK  [conn30] SocketException: remote: 10.2.35.16:38778 error: 9001 socket exception [CLOSED] server [10.2.35.16:38778] 
2016-03-30T04:24:15.870+0000 D NETWORK  [conn7] SocketException: remote: 10.2.35.16:38748 error: 9001 socket exception [CLOSED] server [10.2.35.16:38748] 
2016-03-30T04:24:15.870+0000 I NETWORK  [conn30] end connection 10.2.35.16:38778 (52 connections now open)
2016-03-30T04:24:15.870+0000 I NETWORK  [conn7] end connection 10.2.35.16:38748 (52 connections now open)
2016-03-30T04:24:15.872+0000 D NETWORK  [conn48] Socket recv() conn closed? 10.2.35.16:38813
2016-03-30T04:24:15.872+0000 D NETWORK  [conn48] SocketException: remote: 10.2.35.16:38813 error: 9001 socket exception [CLOSED] server [10.2.35.16:38813] 
2016-03-30T04:24:15.872+0000 I NETWORK  [conn48] end connection 10.2.35.16:38813 (50 connections now open)
2016-03-30T04:24:15.906+0000 D STORAGE  [WTJournalFlusher] flushed journal
2016-03-30T04:24:16.000+0000 D STORAGE  [ftdc] WT begin_transaction
2016-03-30T04:24:16.001+0000 D STORAGE  [ftdc] WT rollback_transaction
2016-03-30T04:24:16.006+0000 D STORAGE  [WTJournalFlusher] flushed journal
2016-03-30T04:24:16.019+0000 D EXECUTOR [NetworkInterfaceASIO-BGSync-0] Received remote response: RemoteResponse --  cmd:{ cursor: { nextBatch: [ { ts: Timestamp 1459311856000|1, h: -5058317734524174104, v: 2, op: "u", ns: "cstore.adgroupstatsbyday", o2: { _id: ObjectId('56faae64b91f4a5db8110c33') }, o: { $set: { costPerUniqueClick: 1, cpm: 19.607843137255, cpp: 19.736842105263, ctr: 0.058823529411765, frequency: 1.0065789473684, impressions: 153, processEndTime: new Date(1459311988366), processStartTime: new Date(1459311793000), reach: 152, socialImpressions: 93, socialReach: 92, socialUniqueImpressions: 92, uniqueClicks: 3, uniqueCtr: 0.019736842105263, uniqueImpressions: 152, websiteCtr: [ { action_type: "link_click", value: 2.6143790849673 } ], convertedArray: { link_click: { actions: { action_type: "link_click", 1d_click: 4, value: 4 }, costPerActionType: { action_type: "link_click", 1d_click: 0.75, value: 0.75 }, costPerUniqueActionType: { action_type: "link_click", value: 1.0 }, uniqueActions: { action_type: "link_click", 1d_click: 3, value: 3 }, websiteCtr: { action_type: "link_click", value: 2.6143790849673 } }, page_engagement: { actions: { action_type: "page_engagement", 1d_click: 4, value: 4 }, costPerActionType: { action_type: "page_engagement", 1d_click: 0.75, value: 0.75 }, costPerUniqueActionType: { action_type: "page_engagement", value: 1.0 }, uniqueActions: { action_type: "page_engagement", 1d_click: 3, value: 3 } }, post_engagement: { actions: { action_type: "post_engagement", 1d_click: 4, value: 4 }, costPerActionType: { action_type: "post_engagement", 1d_click: 0.75, value: 0.75 }, costPerUniqueActionType: { action_type: "post_engagement", value: 1.0 }, uniqueActions: { action_type: "post_engagement", 1d_click: 3, value: 3 } } }, dataUpdateTime: new Date(1459311856026) } } } ], id: 102312238058, ns: "local.oplog.rs" }, ok: 1.0 }
2016-03-30T04:24:16.019+0000 D EXECUTOR [rsBackgroundSync-0] Executing a task on behalf of pool rsBackgroundSync
2016-03-30T04:24:16.019+0000 D ASIO     [NetworkInterfaceASIO-BGSync-0] Failed to time operation 26399 out: Operation aborted.
2016-03-30T04:24:16.019+0000 D REPL     [rsBackgroundSync-0] fetcher read 1 operations from remote oplog starting at ts: Timestamp 1459311856000|1 and ending at ts: Timestamp 1459311856000|1
2016-03-30T04:24:16.019+0000 D REPL     [rsBackgroundSync-0] batch resetting _lastOpTimeFetched: (term: -1, timestamp: Mar 30 04:24:16:1)
2016-03-30T04:24:16.019+0000 D QUERY    [rsSync] Beginning planning...
=============================
Options = INDEX_INTERSECTION 
Canonical query:
ns=local.replset.minvalidTree: $and
Sort: {}
Proj: {}
=============================
2016-03-30T04:24:16.020+0000 D QUERY    [rsSync] Index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.replset.minvalid" }
2016-03-30T04:24:16.020+0000 D QUERY    [rsSync] Rated tree:
$and
2016-03-30T04:24:16.020+0000 D QUERY    [rsSync] Planner: outputted 0 indexed solutions.
2016-03-30T04:24:16.020+0000 D QUERY    [rsSync] Planner: outputting a collscan:
COLLSCAN
---ns = local.replset.minvalid
---filter = $and
---fetched = 1
...skipping...
2016-03-30T04:24:16.462+0000 D NETWORK  [conn2] SocketException: remote: 127.0.0.1:38143 error: 9001 socket exception [CLOSED] server [127.0.0.1:38143] 
2016-03-30T04:24:16.462+0000 D STORAGE  [rsSync] WT commit_transaction
2016-03-30T04:24:16.462+0000 I NETWORK  [conn2] end connection 127.0.0.1:38143 (49 connections now open)
2016-03-30T04:24:16.462+0000 D EXECUTOR [repl writer worker 5] Executing a task on behalf of pool repl writer worker Pool
2016-03-30T04:24:16.462+0000 D COMMAND  [conn11] run command admin.$cmd { replSetHeartbeat: "yeahmobi_2", pv: 1, v: 13, from: "AMZ-SIN-WallE-35-15:27017", fromId: 0, checkEmpty: false }
2016-03-30T04:24:16.462+0000 D COMMAND  [conn11] command: replSetHeartbeat
2016-03-30T04:24:16.462+0000 D REPL     [repl writer worker 5] applying op: { ts: Timestamp 1459311856000|135, h: -5737183515388900390, v: 2, op: "u", ns: "cstore.adgroupstatsbyday", o2: { _id: ObjectId('56fab32cb91f4a5db811438c') }, o: { $set: { processEndTime: new Date(1459311988817), processStartTime: new Date(1459311802000), dataUpdateTime: new Date(1459311856458) } } }
2016-03-30T04:24:16.462+0000 D QUERY    [repl writer worker 5] Using idhack: { _id: ObjectId('56fab32cb91f4a5db811438c') }
2016-03-30T04:24:16.463+0000 I COMMAND  [conn11] command admin.$cmd command: replSetHeartbeat { replSetHeartbeat: "yeahmobi_2", pv: 1, v: 13, from: "AMZ-SIN-WallE-35-15:27017", fromId: 0, checkEmpty: false } keyUpdates:0 writeConflicts:0 numYields:0 reslen:513 locks:{} protocol:op_command 0ms
2016-03-30T04:24:16.463+0000 D NETWORK  [conn26] Socket recv() conn closed? 127.0.0.1:38247
2016-03-30T04:24:16.463+0000 D NETWORK  [conn26] SocketException: remote: 127.0.0.1:38247 error: 9001 socket exception [CLOSED] server [127.0.0.1:38247] 
2016-03-30T04:24:16.464+0000 I NETWORK  [conn26] end connection 127.0.0.1:38247 (48 connections now open)
2016-03-30T04:24:16.464+0000 D STORAGE  [repl writer worker 5] WT begin_transaction
2016-03-30T04:24:16.464+0000 D EXECUTOR [rsBackgroundSync-0] Scheduling remote command request: RemoteCommand 26545 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:26.464+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:16.464+0000 D ASIO     [rsBackgroundSync-0] startCommand: RemoteCommand 26545 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:26.464+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:16.464+0000 D STORAGE  [repl writer worker 5] WT commit_transaction
2016-03-30T04:24:16.464+0000 D STORAGE  [repl writer worker 5] WT begin_transaction
2016-03-30T04:24:16.464+0000 D EXECUTOR [rsBackgroundSync-0] waiting for work; I am one of 1 thread(s); the minimum number of threads is 1
2016-03-30T04:24:16.464+0000 D ASIO     [NetworkInterfaceASIO-BGSync-0] Initiating asynchronous command: RemoteCommand 26545 -- target:AMZ-SIN-WallE-35-15:27017 db:local expDate:2016-03-30T04:24:26.464+0000 cmd:{ getMore: 102312238058, collection: "oplog.rs", maxTimeMS: 2000 }
2016-03-30T04:24:16.464+0000 D WRITE    [repl writer worker 5] UpdateResult --  upserted: {} modifiers: 1 existing: 1 numDocsModified: 1 numMatched: 1
2016-03-30T04:24:16.464+0000 D ASIO     [NetworkInterfaceASIO-BGSync-0] Starting asynchronous command 26545 on host AMZ-SIN-WallE-35-15:27017
2016-03-30T04:24:16.464+0000 D STORAGE  [repl writer worker 5] WT commit_transaction
2016-03-30T04:24:16.464+0000 D EXECUTOR [repl writer worker 5] waiting for work; I am one of 16 thread(s); the minimum number of threads is 16
2016-03-30T04:24:16.464+0000 D QUERY    [rsSync] Beginning planning...
=============================
Options = INDEX_INTERSECTION 
Canonical query:
ns=local.replset.minvalidTree: $and
Sort: {}
Proj: {}
=============================
2016-03-30T04:24:16.464+0000 D QUERY    [rsSync] Index 0 is kp: { _id: 1 } unique name: '_id_' io: { v: 1, key: { _id: 1 }, name: "_id_", ns: "local.replset.minvalid" }
2016-03-30T04:24:16.464+0000 D QUERY    [rsSync] Rated tree:
$and
2016-03-30T04:24:16.464+0000 D QUERY    [rsSync] Planner: outputted 0 indexed solutions.
2016-03-30T04:24:16.464+0000 D QUERY    [rsSync] Planner: outputting a collscan:
COLLSCAN
---ns = local.replset.minvalid
---filter = $and
---fetched = 1
---sortedByDiskLoc = 0
---getSort = []
2016-03-30T04:24:16.464+0000 D QUERY    [rsSync] Only one plan is available; it will be run but will not be cached. query: {} sort: {} projection: {}, planSummary: COLLSCAN
2016-03-30T04:24:16.464+0000 D STORAGE  [rsSync] WT begin_transaction
2016-03-30T04:24:16.464+0000 D WRITE    [rsSync] update validate options --  updatedFields: Fields:[ begin,t,ts,] immutableAndSingleValueFields.size:0 validate:1
2016-03-30T04:24:16.464+0000 D STORAGE  [rsSync] WT commit_transaction
: