-
Type: Bug
-
Resolution: Cannot Reproduce
-
Priority: Major - P3
-
None
-
Affects Version/s: 3.0.7
-
Component/s: Replication
-
None
-
ALL
I recently added a new node to our replica set. It caused errors in our application, because it finished the initialSync and switched to a valid SECONDARY before its indexes finished building. Since we send some of the queries to our secondary, that resulted with a) really slow queries, and b) errors (since we rely on hints in some scenarios)
Below is a short excerpt from our logs showing the issue. Let me know if you need the whole log.
2015-10-23T05:23:45.533+0000 I - [repl index builder 9] Index Build (background): 2787300/32715281 8% 2015-10-23T05:23:47.133+0000 I REPL [rsSync] initial sync finishing up 2015-10-23T05:23:47.133+0000 I REPL [rsSync] replSet set minValid=5629c44b:6 2015-10-23T05:23:47.133+0000 I REPL [rsSync] initial sync done 2015-10-23T05:23:47.153+0000 I REPL [ReplicationExecutor] transition to RECOVERING 2015-10-23T05:23:47.160+0000 I REPL [ReplicationExecutor] transition to SECONDARY 2015-10-23T05:23:47.754+0000 I REPL [ReplicationExecutor] could not find member to sync from 2015-10-23T05:23:48.008+0000 I - [repl index builder 11] Index Build (background): 2792400/32715290 8%(...) (...) 2015-10-23T05:48:19.019+0000 I - [repl index builder 10] Index Build (background): 5575800/32715628 17% 2015-10-23T05:48:19.020+0000 I - [repl index builder 16] Index Build (background): 5575800/32715628 17% 2015-10-23T05:48:19.885+0000 I NETWORK [initandlisten] connection accepted from 10.21.16.41:43272 #3573 (40 connections now open) 2015-10-23T05:48:19.898+0000 I ACCESS [conn3573] Successfully authenticated as principal __system on local 2015-10-23T05:48:19.908+0000 I QUERY [conn3573] assertion 17007 Unable to execute query: error processing query: ns=closeio.activity limit=50 skip=0 Tree: $and _cls == "Activity.Call" direction == "inbound" organization == { $ref: "organization", $id: "orga_alksjdfalksjdfklajc" } phone == "+6503334444" plivo_number $in [ { $ref: "plivo_number", $id: ObjectId('aklsjdfljsdfklajsdf') } ] Sort: { date_created: -1 } Proj: {} planner returned error: bad hint ns:closeio.activity query:{ $query: { plivo_number: { $in: [ { $ref: "plivo_number", $id: ObjectId('aklsjdfljsdfklajsdf') } ] }, organization: { $ref: "organization", $id: "orga_alksjdfalksjdfklajc" }, direction: "inbound", _cls: "Activity.Call", phone: "+6503334444" }, $readPreference: { mode: "secondary" }, $hint: { _cls: 1, organization: 1, phone: 1, lead: 1 }, $orderby: { date_created: -1 } } 2015-10-23T05:48:19.908+0000 I QUERY [conn3573] ntoskip:0 ntoreturn:50 2015-10-23T05:48:20.007+0000 I - [repl index builder 4] Index Build (background): 5577900/32715629 17% 2015-10-23T05:48:20.009+0000 I - [repl index builder 17] Index Build (background): 5577900/32715629 17% 2015-10-23T05:48:20.011+0000 I - [repl index builder 12] Index Build (background): 5577900/32715629 17% (...) 2015-10-23T12:04:08.042+0000 I - [repl index builder 13] Index Build (background): 32749400/32752875 99% 2015-10-23T12:04:08.046+0000 I - [repl index builder 16] Index Build (background): 32749400/32752875 99% 2015-10-23T12:04:08.965+0000 I INDEX [repl index builder 4] build index done. scanned 32752154 total records. 34423 secs 2015-10-23T12:04:08.966+0000 I INDEX [repl index builder 3] build index done. scanned 32752154 total records. 34423 secs 2015-10-23T12:04:08.967+0000 I INDEX [repl index builder 8] build index done. scanned 32752154 total records. 25852 secs 2015-10-23T12:04:08.969+0000 I INDEX [repl index builder 12] build index done. scanned 32752154 total records. 25851 secs 2015-10-23T12:04:08.969+0000 I INDEX [repl index builder 14] build index done. scanned 32752154 total records. 25851 secs 2015-10-23T12:04:08.970+0000 I INDEX [repl index builder 5] build index done. scanned 32752154 total records. 34423 secs 2015-10-23T12:04:08.974+0000 I INDEX [repl index builder 13] build index done. scanned 32752154 total records. 25851 secs 2015-10-23T12:04:08.975+0000 I INDEX [repl index builder 16] build index done. scanned 32752154 total records. 25851 secs 2015-10-23T12:04:08.976+0000 I INDEX [repl index builder 10] build index done. scanned 32752154 total records. 25852 secs 2015-10-23T12:04:08.977+0000 I INDEX [repl index builder 15] build index done. scanned 32752154 total records. 25851 secs 2015-10-23T12:04:08.978+0000 I INDEX [repl index builder 17] build index done. scanned 32752154 total records. 25851 secs 2015-10-23T12:04:08.978+0000 I INDEX [repl index builder 9] build index done. scanned 32752154 total records. 25852 secs 2015-10-23T12:04:08.979+0000 I INDEX [repl index builder 11] build index done. scanned 32752154 total records. 25851 secs
- is related to
-
SERVER-14737 Initial sync uses background index building
- Closed