MongoDB -- 副本集故障恢复数据同步

Mongodb复制集里的Secondary会从Primary上同步数据，以保持副本集所有节点的数据保持一致，数据同步主要包含2个过程：
- initial sync
- replication （oplog sync）
先通过init sync同步全量数据，再通过replication不断重放Primary上的oplog同步增量数据。

上面描述来自：http://www.mongoing.com/archives/2369

initial sync

Secondary启动后，如果满足以下条件之一，会先进行initial sync
Secondary上oplog为空，比如新加入的空节点
local.replset.minvalid集合里_initialSyncFlag标记被设置。当initial sync开始时，同步线程会设置该标记，当initial sync结束时清除该标记，故如果initial sync过程中途失败，节点重启后发现该标记被设置，就知道应该重新进行initial sync。
BackgroundSync::_initialSyncRequestedFlag被设置。当向节点发送resync命令时，该标记会被设置，此时会强制重新initial sync。

replication (sync oplog)

initial sync结束后，Secondary会建立到Primary上local.oplog.rs的tailable cursor，不断从Primary上获取新写入的oplog，并应用到自身。

Tailable cursor每次会获取到一批oplog，Secondary采用多线程重放oplog以提高效率，通过将oplog按照所属的namespace进行分组，划分到多个线程里，保证同一个namespace的所有操作都由一个线程来replay，以保证统一namespace的操作时序跟primary上保持一致（如果引擎支持文档锁，只需保证同一个文档的操作时序与primary一致即可）。

---

那么在故障节点恢复后，是如何同步数据的呢？
我这里分析，采用的是replication，当故障节点恢复后，会拉取PRIMARY的IPLOG日志，然后和自己的日志比对，如果存在差异，则进行差异化处理，增量更改及执行MONGO脚本语句
都完事后，在根据优先级关系，判断是否重新仲裁选择新节点。

下面是MongoDB副本集，PRIMARY故障宕机重启后的日志

2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] MongoDB starting : pid=24218 port=27001 dbpath=/www/mongo/mongo1/data/ 64-bit host=test_service.1001.co
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] db version v3.2.8
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] git version: ed70e33130c977bda0024c125b56d159573dbaf0
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] OpenSSL version: OpenSSL 1.0.1e-fips 11 Feb 2013
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] allocator: tcmalloc
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] modules: none
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] build environment:
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten]     distmod: rhel62
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten]     distarch: x86_64
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten]     target_arch: x86_64
2018-01-08T14:30:15.765+0800 I CONTROL  [initandlisten] options: { config: "/usr/local/mongo/conf/mongo1.conf", net: { bindIp: "192.168.15.32", http: { enabled: false }, port: 27001 }, processManagement: { fork: true }, replication: { replSet: "dxgj" }, security: { authorization: "enabled", keyFile: "/usr/local/mongo/keyfile/replSet_key" }, storage: { dbPath: "/www/mongo/mongo1/data/" }, systemLog: { destination: "file", path: "/www/mongo/mongo1/log/mongo.log" } }
2018-01-08T14:30:15.782+0800 I -        [initandlisten] Detected data files in /www/mongo/mongo1/data/ created by the 'wiredTiger' storage engine, so setting the active storage engine to 'wiredTiger'.
2018-01-08T14:30:15.782+0800 W -        [initandlisten] Detected unclean shutdown - /www/mongo/mongo1/data/mongod.lock is not empty.
2018-01-08T14:30:15.782+0800 W STORAGE  [initandlisten] Recovering data from the last clean checkpoint.
2018-01-08T14:30:15.782+0800 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),
2018-01-08T14:30:16.498+0800 I STORAGE  [initandlisten] Starting WiredTigerRecordStoreThread local.oplog.rs
2018-01-08T14:30:16.498+0800 I STORAGE  [initandlisten] The size storer reports that the oplog contains 54713203 records totaling to 9738946595 bytes
2018-01-08T14:30:16.498+0800 I STORAGE  [initandlisten] Sampling from the oplog between Dec 27 14:21:23:1 and Jan  8 14:25:45:1 to determine where to place markers for truncation
2018-01-08T14:30:16.498+0800 I STORAGE  [initandlisten] Taking 778 samples and assuming that each section of oplog contains approximately 702545 records totaling to 125052964 bytes
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 14:46:54:fb1
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 14:48:50:411
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 14:51:29:6fd
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 14:57:11:104
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 14:59:51:48e
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:03:22:7ca
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:06:18:79f
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:08:12:4e8
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:10:07:8c0
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:12:38:c5e
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:15:50:ee1
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:20:07:202
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:24:33:440
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 15:29:54:e3e
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:20:30:50f
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:23:45:321
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:28:37:5de
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:34:09:3fc
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:38:25:a82
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:41:34:cd7
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:45:07:b85
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 16:58:45:999
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:02:06:c40
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:08:33:2ba
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:13:11:94c
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:17:38:bb0
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:20:50:215
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:34:20:864
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:37:37:2c8
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:43:18:d0
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:48:07:b6d
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:52:54:9ef
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:56:08:468
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 17:59:36:120e
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:14:42:ca2
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:17:54:91a
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:21:10:1d3
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:27:24:56
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:31:00:657
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:35:15:8a6
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:39:30:6e7
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:42:45:164
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:45:50:17
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 18:48:55:c40
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:08:42:c87
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:11:00:373
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:13:10:1dd
2018-01-08T14:30:16.580+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:16:26:5e8
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:21:38:a35
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:24:00:14d6
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:26:23:129e
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:28:28:5ce
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:30:34:7fd
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:32:39:11b9
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:34:46:bc
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:45:15:728
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:46:56:86e
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:48:39:fe3
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:50:13:19d8
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:52:01:7f
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:55:25:ab3
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 19:58:32:15c
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:00:05:f9e
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:02:00:2dc
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:04:17:209a
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:05:43:268e
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:07:14:3c3
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:15:54:2af2
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:17:02:2985
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:18:08:196e
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:19:26:f27
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:20:46:20f8
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:21:58:440
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:23:02:1277
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:24:06:537
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Dec 27 20:25:10:324
2018-01-08T14:30:16.581+0800 I STORAGE  [initandlisten] Placing a marker at optime Jan  5 01:10:03:22ce
2018-01-08T14:30:16.639+0800 I FTDC     [initandlisten] Initializing full-time diagnostic data capture with directory '/www/mongo/mongo1/data/diagnostic.data'
2018-01-08T14:30:16.639+0800 I NETWORK  [HostnameCanonicalizationWorker] Starting hostname canonicalization worker
2018-01-08T14:30:16.639+0800 I NETWORK  [initandlisten] waiting for connections on port 27001
2018-01-08T14:30:16.699+0800 I REPL     [ReplicationExecutor] New replica set config in use: { _id: "dxgj", version: 7, protocolVersion: 1, members: [ { _id: 0, host: "192.168.15.32:27001", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 3.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 1, host: "192.168.15.32:27002", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 2, host: "192.168.15.32:27003", arbiterOnly: false, buildIndexes: true, hidden: false, priority: 1.0, tags: {}, slaveDelay: 0, votes: 1 }, { _id: 3, host: "192.168.15.32:27000", arbiterOnly: true, 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('5a433be2e45a5ddb2a6bdeed') } }
2018-01-08T14:30:16.699+0800 I REPL     [ReplicationExecutor] This node is 192.168.15.32:27001 in the config
2018-01-08T14:30:16.699+0800 I REPL     [ReplicationExecutor] transition to STARTUP2
2018-01-08T14:30:16.699+0800 I REPL     [ReplicationExecutor] Starting replication applier threads
2018-01-08T14:30:16.783+0800 I REPL     [ReplicationExecutor] transition to RECOVERING
2018-01-08T14:30:16.785+0800 I REPL     [ReplicationExecutor] transition to SECONDARY
2018-01-08T14:30:16.819+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27002
2018-01-08T14:30:16.820+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27003
2018-01-08T14:30:16.820+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27000
2018-01-08T14:30:16.820+0800 I REPL     [ReplicationExecutor] Member 192.168.15.32:27002 is now in state PRIMARY
2018-01-08T14:30:16.820+0800 I REPL     [ReplicationExecutor] Scheduling priority takeover at 2018-01-08T14:30:26.820+0800
2018-01-08T14:30:16.820+0800 I REPL     [ReplicationExecutor] Member 192.168.15.32:27003 is now in state SECONDARY
2018-01-08T14:30:16.820+0800 I REPL     [ReplicationExecutor] Member 192.168.15.32:27000 is now in state ARBITER
2018-01-08T14:30:17.018+0800 I FTDC     [ftdc] Unclean full-time diagnostic data capture shutdown detected, found interim file, some metrics may have been lost. OK
2018-01-08T14:30:17.147+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.32:53876 #1 (1 connection now open)
2018-01-08T14:30:17.171+0800 I ACCESS   [conn1] Successfully authenticated as principal __system on local
2018-01-08T14:30:17.220+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.32:53877 #2 (2 connections now open)
2018-01-08T14:30:17.242+0800 I ACCESS   [conn2] Successfully authenticated as principal __system on local
2018-01-08T14:30:18.021+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.32:53878 #3 (3 connections now open)
2018-01-08T14:30:18.046+0800 I ACCESS   [conn3] Successfully authenticated as principal dx on dx
2018-01-08T14:30:19.209+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.32:53879 #4 (4 connections now open)
2018-01-08T14:30:19.232+0800 I ACCESS   [conn4] Successfully authenticated as principal __system on local
2018-01-08T14:30:20.783+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.31:39937 #5 (5 connections now open)
2018-01-08T14:30:20.801+0800 I ACCESS   [conn5] Successfully authenticated as principal dx on dx
2018-01-08T14:30:22.292+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.31:39938 #6 (6 connections now open)
2018-01-08T14:30:22.310+0800 I ACCESS   [conn6] Successfully authenticated as principal dx on dx
2018-01-08T14:30:22.784+0800 I REPL     [ReplicationExecutor] syncing from: 192.168.15.32:27003
2018-01-08T14:30:22.803+0800 I REPL     [SyncSourceFeedback] setting syncSourceFeedback to 192.168.15.32:27003
2018-01-08T14:30:22.824+0800 I ASIO     [NetworkInterfaceASIO-BGSync-0] Successfully connected to 192.168.15.32:27003
2018-01-08T14:30:24.022+0800 I NETWORK  [initandlisten] connection accepted from 192.168.9.10:55709 #7 (7 connections now open)
2018-01-08T14:30:24.088+0800 I ACCESS   [conn7] Successfully authenticated as principal dx on dx
2018-01-08T14:30:26.820+0800 I REPL     [ReplicationExecutor] Canceling priority takeover callback
2018-01-08T14:30:26.820+0800 I REPL     [ReplicationExecutor] Starting an election for a priority takeover
2018-01-08T14:30:26.820+0800 I REPL     [ReplicationExecutor] conducting a dry run election to see if we could be elected
2018-01-08T14:30:26.821+0800 I REPL     [ReplicationExecutor] dry election run succeeded, running for election
2018-01-08T14:30:26.824+0800 I REPL     [ReplicationExecutor] election succeeded, assuming primary role in term 37
2018-01-08T14:30:26.824+0800 I REPL     [ReplicationExecutor] transition to PRIMARY
2018-01-08T14:30:26.824+0800 I REPL     [rsSync] transition to primary complete; database writes are now permitted
2018-01-08T14:30:26.861+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27000
2018-01-08T14:30:26.871+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27000
2018-01-08T14:30:26.871+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27003
2018-01-08T14:30:26.881+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27002
2018-01-08T14:30:26.881+0800 I ASIO     [NetworkInterfaceASIO-Replication-0] Successfully connected to 192.168.15.32:27000
2018-01-08T14:30:26.882+0800 I REPL     [ReplicationExecutor] Member 192.168.15.32:27002 is now in state SECONDARY
2018-01-08T14:30:27.584+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.32:53890 #8 (8 connections now open)
2018-01-08T14:30:27.604+0800 I ACCESS   [conn8] Successfully authenticated as principal __system on local
2018-01-08T14:30:27.605+0800 I NETWORK  [conn8] end connection 192.168.15.32:53890 (7 connections now open)
2018-01-08T14:30:27.605+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.32:53891 #9 (9 connections now open)
2018-01-08T14:30:27.605+0800 I NETWORK  [initandlisten] connection accepted from 192.168.15.32:53892 #10 (9 connections now open)
2018-01-08T14:30:27.620+0800 I ACCESS   [conn10] Successfully authenticated as principal __system on local
2018-01-08T14:30:27.620+0800 I ACCESS   [conn9] Successfully authenticated as principal __system on local
2018-01-08T14:30:37.988+0800 I NETWORK  [initandlisten] connection accepted from 192.168.9.10:55715 #11 (10 connections now open)
2018-01-08T14:30:38.041+0800 I ACCESS   [conn11] Successfully authenticated as principal dx on dx
2018-01-08T14:30:38.095+0800 I NETWORK  [initandlisten] connection accepted from 192.168.9.10:55716 #12 (11 connections now open)
2018-01-08T14:30:38.175+0800 I ACCESS   [conn12] Successfully authenticated as principal dx on dx