[SERVER-15308] Stepdown does not cancel active (background) index builds causing shutdown on completion Created: 18/Sep/14  Updated: 18/Sep/15  Resolved: 05/Feb/15

Status: Closed
Project: Core Server
Component/s: Index Maintenance, Replication
Affects Version/s: None
Fix Version/s: 3.0.0-rc8

Type: Bug Priority: Major - P3
Reporter: Adam Comerford Assignee: Benety Goh
Resolution: Done Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Related
related to SERVER-17205 logOp fassert when creating namespace... Closed
related to SERVER-17208 logOp fassert when creating namespace... Closed
is related to SERVER-14186 rs.stepDown during mapReduce causes f... Closed
is related to SERVER-17150 logOp fassert when dropping collectio... Closed
is related to SERVER-15310 kill all operations before attempting... Closed
Tested
Backwards Compatibility: Fully Compatible
Operating System: ALL
Steps To Reproduce:

start up a 2 node + arb replica set

./mongo --nodb
rst = new ReplSetTest({nodes : [{}, {}, {arbiter: true}], startPort : 27017 });
rst.startSet();
rst.initiate();
 
// connect to the primary and insert 1GB of data (https://github.com/comerford/mongodb-scripts/blob/master/crud.js)
./mongo
load('/Users/adam/git/mongodb-scripts/crud.js');
createData(1, "indexTest", true)
 
// might need to wait for secondary to catch up.  Once currenct, build a background index on the primary
use indexTest;
db.data.ensureIndex( { ranDate : 1 }, { background: true } )
 
// connect to primary with a different shell, step it down
./mongo
rs.stepDown(10);
 
// Here's what the logs look like (m27017 starts as primary)
 
m27017| 2014-09-18T17:13:07.635+0100 [conn6] build index on: indexTest.data properties: { v: 1, key: { ranDate: 1.0 }, name: "ranDate_1", ns: "indexTest.data", background: true }
m27017| 2014-09-18T17:13:07.636+0100 [conn6] 	 building index in background
m27018| 2014-09-18T17:13:08.944+0100 [conn44] end connection 10.7.1.80:49638 (2 connections now open)
m27018| 2014-09-18T17:13:08.945+0100 [initandlisten] connection accepted from 10.7.1.80:49649 #46 (3 connections now open)
m27017| 2014-09-18T17:13:09.584+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._28
m27017| 2014-09-18T17:13:09.585+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._29
m27017| 2014-09-18T17:13:10.000+0100 [conn6] 		Index Build(background): 251200/4515200	5%
m27017| 2014-09-18T17:13:11.320+0100 [conn50] end connection 10.7.1.80:49639 (6 connections now open)
m27017| 2014-09-18T17:13:11.321+0100 [initandlisten] connection accepted from 10.7.1.80:49650 #52 (7 connections now open)
m27017| 2014-09-18T17:13:11.819+0100 [conn51] end connection 10.7.1.80:49640 (6 connections now open)
m27017| 2014-09-18T17:13:11.819+0100 [initandlisten] connection accepted from 10.7.1.80:49651 #53 (7 connections now open)
m27017| 2014-09-18T17:13:13.000+0100 [conn6] 		Index Build(background): 463400/4515200	10%
m27017| 2014-09-18T17:13:13.310+0100 [conn17] adamc-mbp.10gen.cc:27018 is now closest at 541b0418:125c
m27017| 2014-09-18T17:13:16.022+0100 [conn6] 		Index Build(background): 629600/4515200	13%
m27017| 2014-09-18T17:13:18.851+0100 [conn17] adamc-mbp.10gen.cc:27018 is now closest at 541b041b:21ad
m27017| 2014-09-18T17:13:19.023+0100 [conn6] 		Index Build(background): 789400/4515200	17%
m27017| 2014-09-18T17:13:20.139+0100 [conn17] adamc-mbp.10gen.cc:27018 is now closest at 541b041d:1c13
m27017| 2014-09-18T17:13:22.000+0100 [conn6] 		Index Build(background): 948500/4515200	21%
m27019| 2014-09-18T17:13:22.943+0100 [conn44] end connection 10.7.1.80:49646 (2 connections now open)
m27019| 2014-09-18T17:13:22.944+0100 [initandlisten] connection accepted from 10.7.1.80:49652 #46 (3 connections now open)
m27017| 2014-09-18T17:13:24.352+0100 [clientcursormon] mem (MB) res:1718 virt:6946
m27017| 2014-09-18T17:13:24.352+0100 [clientcursormon]  mapped (incl journal view):4350
m27017| 2014-09-18T17:13:24.352+0100 [clientcursormon]  connections:7
m27017| 2014-09-18T17:13:24.352+0100 [clientcursormon]  replication threads:32
m27017| 2014-09-18T17:13:25.009+0100 [conn6] 		Index Build(background): 1106300/4515200	24%
m27019| 2014-09-18T17:13:25.326+0100 [conn45] end connection 10.7.1.80:49647 (2 connections now open)
m27019| 2014-09-18T17:13:25.326+0100 [initandlisten] connection accepted from 10.7.1.80:49653 #47 (3 connections now open)
m27018| 2014-09-18T17:13:25.823+0100 [conn45] end connection 10.7.1.80:49648 (2 connections now open)
m27018| 2014-09-18T17:13:25.824+0100 [initandlisten] connection accepted from 10.7.1.80:49654 #47 (3 connections now open)
m27017| 2014-09-18T17:13:28.065+0100 [conn6] 		Index Build(background): 1245200/4515200	27%
m27017| 2014-09-18T17:13:31.051+0100 [conn6] 		Index Build(background): 1372900/4515200	30%
m27017| 2014-09-18T17:13:34.000+0100 [conn6] 		Index Build(background): 1495300/4515200	33%
m27018| 2014-09-18T17:13:34.757+0100 [FileAllocator] allocating new datafile /data/db/testReplSet-1/foo.ns, filling with zeroes...
m27018| 2014-09-18T17:13:34.797+0100 [FileAllocator] done allocating datafile /data/db/testReplSet-1/foo.ns, size: 16MB,  took 0.039 secs
m27018| 2014-09-18T17:13:34.850+0100 [FileAllocator] allocating new datafile /data/db/testReplSet-1/foo.0, filling with zeroes...
m27018| 2014-09-18T17:13:34.881+0100 [FileAllocator] done allocating datafile /data/db/testReplSet-1/foo.0, size: 16MB,  took 0.031 secs
m27018| 2014-09-18T17:13:34.990+0100 [repl writer worker 1] build index on: foo.test properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "foo.test" }
m27018| 2014-09-18T17:13:34.991+0100 [repl writer worker 1] 	 added index to empty collection
m27017| 2014-09-18T17:13:37.044+0100 [conn6] 		Index Build(background): 1611700/4515200	35%
m27018| 2014-09-18T17:13:38.954+0100 [conn46] end connection 10.7.1.80:49649 (2 connections now open)
m27018| 2014-09-18T17:13:38.955+0100 [initandlisten] connection accepted from 10.7.1.80:49655 #48 (3 connections now open)
m27017| 2014-09-18T17:13:39.500+0100 [conn17] build index on: foo.foo properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "foo.foo" }
m27017| 2014-09-18T17:13:39.500+0100 [conn17] 	 added index to empty collection
m27018| 2014-09-18T17:13:39.514+0100 [repl writer worker 2] build index on: foo.foo properties: { v: 1, key: { _id: 1 }, name: "_id_", ns: "foo.foo" }
m27018| 2014-09-18T17:13:39.514+0100 [repl writer worker 2] 	 added index to empty collection
m27017| 2014-09-18T17:13:40.034+0100 [conn6] 		Index Build(background): 1743400/4515200	38%
m27017| 2014-09-18T17:13:41.334+0100 [conn52] end connection 10.7.1.80:49650 (6 connections now open)
m27017| 2014-09-18T17:13:41.334+0100 [initandlisten] connection accepted from 10.7.1.80:49656 #54 (7 connections now open)
m27017| 2014-09-18T17:13:41.829+0100 [conn53] end connection 10.7.1.80:49651 (6 connections now open)
m27017| 2014-09-18T17:13:41.830+0100 [initandlisten] connection accepted from 10.7.1.80:49657 #55 (7 connections now open)
m27017| 2014-09-18T17:13:43.133+0100 [conn6] 		Index Build(background): 1877300/4515200	41%
m27017| 2014-09-18T17:13:43.930+0100 [conn17] adamc-mbp.10gen.cc:27018 is now closest at 541b04b3:1
m27017| 2014-09-18T17:13:43.930+0100 [conn17] replSet info stepping down as primary secs=10
m27017| 2014-09-18T17:13:43.959+0100 [conn17] replSet relinquishing primary state
m27017| 2014-09-18T17:13:43.959+0100 [conn17] replSet SECONDARY
m27017| 2014-09-18T17:13:43.959+0100 [conn17] replSet closing client sockets after relinquishing primary
m27017| 2014-09-18T17:13:43.960+0100 [conn12] end connection 10.7.1.80:49410 (6 connections now open)
m27017| 2014-09-18T17:13:43.960+0100 [conn1] end connection 127.0.0.1:49380 (5 connections now open)
m27017| 2014-09-18T17:13:44.149+0100 [conn17] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [127.0.0.1:49434] 
m27018| 2014-09-18T17:13:44.150+0100 [rsBackgroundSync] replSet sync source problem: 10278 dbclient error communicating with server: adamc-mbp.10gen.cc:27017
m27018| 2014-09-18T17:13:44.150+0100 [rsBackgroundSync] replSet syncing to: adamc-mbp.10gen.cc:27017
m27017| 2014-09-18T17:13:44.151+0100 [initandlisten] connection accepted from 10.7.1.80:49658 #56 (5 connections now open)
m27018| 2014-09-18T17:13:44.151+0100 [rsBackgroundSync] replset setting syncSourceFeedback to adamc-mbp.10gen.cc:27017
m27017| 2014-09-18T17:13:44.151+0100 [initandlisten] connection accepted from 10.7.1.80:49659 #57 (6 connections now open)
m27017| 2014-09-18T17:13:44.152+0100 [initandlisten] connection accepted from 127.0.0.1:49660 #58 (7 connections now open)
m27017| 2014-09-18T17:13:44.152+0100 [initandlisten] connection accepted from 127.0.0.1:49661 #59 (8 connections now open)
m27017| 2014-09-18T17:13:44.620+0100 [conn11] SocketException handling request, closing client connection: 9001 socket exception [SEND_ERROR] server [10.7.1.80:49409] 
m27018| 2014-09-18T17:13:45.336+0100 [rsHealthPoll] replSet member adamc-mbp.10gen.cc:27017 is now in state SECONDARY
m27018| 2014-09-18T17:13:45.336+0100 [rsMgr] not electing self, adamc-mbp.10gen.cc:27019 would veto with 'adamc-mbp.10gen.cc:27018 is trying to elect itself but adamc-mbp.10gen.cc:27017 is already primary and more up-to-date'
m27019| 2014-09-18T17:13:45.832+0100 [rsHealthPoll] replSet member adamc-mbp.10gen.cc:27017 is now in state SECONDARY
m27017| 2014-09-18T17:13:46.076+0100 [conn6] 		Index Build(background): 1993900/4515200	44%
m27019| 2014-09-18T17:13:48.289+0100 [clientcursormon] mem (MB) res:11 virt:2613
m27019| 2014-09-18T17:13:48.289+0100 [clientcursormon]  mapped (incl journal view):64
m27019| 2014-09-18T17:13:48.289+0100 [clientcursormon]  connections:3
m27019| 2014-09-18T17:13:48.289+0100 [clientcursormon]  replication threads:32
m27017| 2014-09-18T17:13:49.000+0100 [conn6] 		Index Build(background): 2078700/4515200	46%
m27017| 2014-09-18T17:13:52.047+0100 [conn6] 		Index Build(background): 2171200/4515200	48%
m27018| 2014-09-18T17:13:52.079+0100 [rsMgr] replSet info electSelf 1
m27019| 2014-09-18T17:13:52.079+0100 [conn47] replSet info voting yea for adamc-mbp.10gen.cc:27018 (1)
m27017| 2014-09-18T17:13:52.079+0100 [conn54] replSet info voting yea for adamc-mbp.10gen.cc:27018 (1)
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._30
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._31
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._32
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._33
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._34
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._35
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._36
m27017| 2014-09-18T17:13:52.842+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._37
m27017| 2014-09-18T17:13:52.845+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._38
m27017| 2014-09-18T17:13:52.852+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._39
m27019| 2014-09-18T17:13:52.956+0100 [conn46] end connection 10.7.1.80:49652 (2 connections now open)
m27019| 2014-09-18T17:13:52.956+0100 [initandlisten] connection accepted from 10.7.1.80:49668 #48 (3 connections now open)
m27018| 2014-09-18T17:13:54.193+0100 [rsMgr] replSet PRIMARY
m27017| 2014-09-18T17:13:54.194+0100 [conn56] end connection 10.7.1.80:49658 (6 connections now open)
m27017| 2014-09-18T17:13:54.958+0100 [rsMgr] not electing self, adamc-mbp.10gen.cc:27019 would veto with 'I don't think adamc-mbp.10gen.cc:27017 is electable'
m27017| 2014-09-18T17:13:54.959+0100 [rsHealthPoll] replSet member adamc-mbp.10gen.cc:27018 is now in state PRIMARY
m27017| 2014-09-18T17:13:55.000+0100 [conn6] 		Index Build(background): 2280500/4515200	50%
m27017| 2014-09-18T17:13:55.153+0100 [rsBackgroundSync] replSet syncing to: adamc-mbp.10gen.cc:27018
m27018| 2014-09-18T17:13:55.154+0100 [initandlisten] connection accepted from 10.7.1.80:49669 #49 (4 connections now open)
m27017| 2014-09-18T17:13:55.154+0100 [rsBackgroundSync] replset setting syncSourceFeedback to adamc-mbp.10gen.cc:27018
m27018| 2014-09-18T17:13:55.154+0100 [initandlisten] connection accepted from 10.7.1.80:49670 #50 (5 connections now open)
m27019| 2014-09-18T17:13:55.340+0100 [conn47] end connection 10.7.1.80:49653 (2 connections now open)
m27019| 2014-09-18T17:13:55.341+0100 [initandlisten] connection accepted from 10.7.1.80:49671 #49 (3 connections now open)
m27018| 2014-09-18T17:13:55.835+0100 [conn47] end connection 10.7.1.80:49654 (4 connections now open)
m27018| 2014-09-18T17:13:55.836+0100 [initandlisten] connection accepted from 10.7.1.80:49672 #51 (5 connections now open)
m27019| 2014-09-18T17:13:55.836+0100 [rsHealthPoll] replSet member adamc-mbp.10gen.cc:27018 is now in state PRIMARY
m27017| 2014-09-18T17:13:57.309+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._40
m27017| 2014-09-18T17:13:58.000+0100 [conn6] 		Index Build(background): 2386200/4515200	52%
m27017| 2014-09-18T17:14:01.000+0100 [conn6] 		Index Build(background): 2488600/4515200	55%
m27017| 2014-09-18T17:14:04.032+0100 [conn6] 		Index Build(background): 2588500/4515200	57%
m27017| 2014-09-18T17:14:07.000+0100 [conn6] 		Index Build(background): 2689800/4515200	59%
m27018| 2014-09-18T17:14:08.965+0100 [conn48] end connection 10.7.1.80:49655 (4 connections now open)
m27018| 2014-09-18T17:14:08.966+0100 [initandlisten] connection accepted from 10.7.1.80:49673 #52 (5 connections now open)
m27017| 2014-09-18T17:14:10.076+0100 [conn6] 		Index Build(background): 2787800/4515200	61%
m27017| 2014-09-18T17:14:11.345+0100 [conn54] end connection 10.7.1.80:49656 (5 connections now open)
m27017| 2014-09-18T17:14:11.346+0100 [initandlisten] connection accepted from 10.7.1.80:49674 #60 (6 connections now open)
m27017| 2014-09-18T17:14:11.843+0100 [conn55] end connection 10.7.1.80:49657 (5 connections now open)
m27017| 2014-09-18T17:14:11.843+0100 [initandlisten] connection accepted from 10.7.1.80:49675 #61 (6 connections now open)
m27017| 2014-09-18T17:14:13.000+0100 [conn6] 		Index Build(background): 2884500/4515200	63%
m27017| 2014-09-18T17:14:16.106+0100 [conn6] 		Index Build(background): 2979700/4515200	65%
m27017| 2014-09-18T17:14:19.036+0100 [conn6] 		Index Build(background): 3074300/4515200	68%
m27017| 2014-09-18T17:14:22.000+0100 [conn6] 		Index Build(background): 3170200/4515200	70%
m27019| 2014-09-18T17:14:22.970+0100 [conn48] end connection 10.7.1.80:49668 (2 connections now open)
m27019| 2014-09-18T17:14:22.971+0100 [initandlisten] connection accepted from 10.7.1.80:49676 #50 (3 connections now open)
m27017| 2014-09-18T17:14:25.000+0100 [conn6] 		Index Build(background): 3271000/4515200	72%
m27017| 2014-09-18T17:14:25.082+0100 [clientcursormon] mem (MB) res:2353 virt:6945
m27017| 2014-09-18T17:14:25.082+0100 [clientcursormon]  mapped (incl journal view):4350
m27017| 2014-09-18T17:14:25.082+0100 [clientcursormon]  connections:6
m27017| 2014-09-18T17:14:25.082+0100 [clientcursormon]  replication threads:32
m27019| 2014-09-18T17:14:25.353+0100 [conn49] end connection 10.7.1.80:49671 (2 connections now open)
m27019| 2014-09-18T17:14:25.353+0100 [initandlisten] connection accepted from 10.7.1.80:49677 #51 (3 connections now open)
m27018| 2014-09-18T17:14:25.849+0100 [conn51] end connection 10.7.1.80:49672 (4 connections now open)
m27018| 2014-09-18T17:14:25.849+0100 [initandlisten] connection accepted from 10.7.1.80:49678 #53 (5 connections now open)
m27017| 2014-09-18T17:14:28.009+0100 [conn6] 		Index Build(background): 3363100/4515200	74%
m27017| 2014-09-18T17:14:31.102+0100 [conn6] 		Index Build(background): 3458100/4515200	76%
m27017| 2014-09-18T17:14:34.195+0100 [conn6] 		Index Build(background): 3553500/4515200	78%
m27017| 2014-09-18T17:14:37.017+0100 [conn6] 		Index Build(background): 3640800/4515200	80%
m27018| 2014-09-18T17:14:38.977+0100 [conn52] end connection 10.7.1.80:49673 (4 connections now open)
m27018| 2014-09-18T17:14:38.978+0100 [initandlisten] connection accepted from 10.7.1.80:49679 #54 (5 connections now open)
m27017| 2014-09-18T17:14:40.000+0100 [conn6] 		Index Build(background): 3732000/4515200	82%
m27017| 2014-09-18T17:14:41.359+0100 [conn60] end connection 10.7.1.80:49674 (5 connections now open)
m27017| 2014-09-18T17:14:41.360+0100 [initandlisten] connection accepted from 10.7.1.80:49680 #62 (6 connections now open)
m27017| 2014-09-18T17:14:41.856+0100 [conn61] end connection 10.7.1.80:49675 (5 connections now open)
m27017| 2014-09-18T17:14:41.856+0100 [initandlisten] connection accepted from 10.7.1.80:49681 #63 (6 connections now open)
m27017| 2014-09-18T17:14:43.151+0100 [conn6] 		Index Build(background): 3828800/4515200	84%
m27017| 2014-09-18T17:14:46.014+0100 [conn6] 		Index Build(background): 3908900/4515200	86%
m27017| 2014-09-18T17:14:49.071+0100 [conn6] 		Index Build(background): 3974100/4515200	88%
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._41
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._42
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._43
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._44
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._45
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._46
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._47
m27017| 2014-09-18T17:14:51.015+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._48
m27017| 2014-09-18T17:14:51.016+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._49
m27017| 2014-09-18T17:14:51.016+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._50
m27017| 2014-09-18T17:14:51.019+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._51
m27017| 2014-09-18T17:14:52.157+0100 [conn6] 		Index Build(background): 4063500/4515200	89%
m27019| 2014-09-18T17:14:52.984+0100 [conn50] end connection 10.7.1.80:49676 (2 connections now open)
m27019| 2014-09-18T17:14:52.984+0100 [initandlisten] connection accepted from 10.7.1.80:49682 #52 (3 connections now open)
m27017| 2014-09-18T17:14:55.122+0100 [conn6] 		Index Build(background): 4150100/4515200	91%
m27019| 2014-09-18T17:14:55.367+0100 [conn51] end connection 10.7.1.80:49677 (2 connections now open)
m27019| 2014-09-18T17:14:55.367+0100 [initandlisten] connection accepted from 10.7.1.80:49683 #53 (3 connections now open)
m27017| 2014-09-18T17:14:55.837+0100 [journal] old journal file will be removed: /data/db/testReplSet-0/journal/j._52
m27018| 2014-09-18T17:14:55.863+0100 [conn53] end connection 10.7.1.80:49678 (4 connections now open)
m27018| 2014-09-18T17:14:55.864+0100 [initandlisten] connection accepted from 10.7.1.80:49684 #55 (5 connections now open)
m27017| 2014-09-18T17:14:58.000+0100 [conn6] 		Index Build(background): 4233500/4515200	93%
m27017| 2014-09-18T17:15:01.073+0100 [conn6] 		Index Build(background): 4317000/4515200	95%
m27017| 2014-09-18T17:15:04.000+0100 [conn6] 		Index Build(background): 4404200/4515200	97%
m27017| 2014-09-18T17:15:07.068+0100 [conn6] 		Index Build(background): 4484900/4515200	99%
m27017| 2014-09-18T17:15:08.058+0100 [conn6] build index done.  scanned 4515200 total records. 120.422 secs
m27017| 2014-09-18T17:15:08.058+0100 [conn6] replSet error : logOp() but not primary
m27017| 2014-09-18T17:15:08.058+0100 [conn6] indexTest.data Fatal Assertion 17405
m27017| 2014-09-18T17:15:08.061+0100 [conn6] indexTest.data 0x1006c014b 0x100677502 0x10066726e 0x100472518 0x100475d2f 0x100129267 0x1001bb3c5 0x1001bc002 0x1001bd2ac 0x1003d5c3f 0x1002a56db 0x100006b54 0x100684db1 0x1006f4595 0x7fff8b05f899 0x7fff8b05f72a 0x7fff8b063fc9 
m27017|  0   mongod                              0x00000001006c014b _ZN5mongo15printStackTraceERSo + 43
m27017|  1   mongod                              0x0000000100677502 _ZN5mongo10logContextEPKc + 114
m27017|  2   mongod                              0x000000010066726e _ZN5mongo13fassertFailedEi + 110
m27017|  3   mongod                              0x0000000100472518 _ZN5mongoL8_logOpRSEPKcS1_S1_RKNS_7BSONObjEPS2_Pbb + 376
m27017|  4   mongod                              0x0000000100475d2f _ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_PbbPS3_ + 79
m27017|  5   mongod                              0x0000000100129267 _ZN5mongo14CmdCreateIndex3runERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb + 5549
m27017|  6   mongod                              0x00000001001bb3c5 _ZN5mongo12_execCommandEPNS_7CommandERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb + 37
m27017|  7   mongod                              0x00000001001bc002 _ZN5mongo7Command11execCommandEPS0_RNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb + 2566
m27017|  8   mongod                              0x00000001001bd2ac _ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi + 1388
m27017|  9   mongod                              0x00000001003d5c3f _ZN5mongo11newRunQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1_ + 1615
m27017|  10  mongod                              0x00000001002a56db _ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE + 2443
m27017|  11  mongod                              0x0000000100006b54 _ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE + 308
m27017|  12  mongod                              0x0000000100684db1 _ZN5mongo17PortMessageServer17handleIncomingMsgEPv + 1681
m27017|  13  mongod                              0x00000001006f4595 thread_proxy + 229
m27017|  14  libsystem_pthread.dylib             0x00007fff8b05f899 _pthread_body + 138
m27017|  15  libsystem_pthread.dylib             0x00007fff8b05f72a _pthread_struct_init + 0
m27017|  16  libsystem_pthread.dylib             0x00007fff8b063fc9 thread_start + 13
m27017| 2014-09-18T17:15:08.061+0100 [conn6] 
m27017| 
m27017| ***aborting after fassert() failure
m27017| 
m27017| 
m27017| 2014-09-18T17:15:08.068+0100 [conn6] SEVERE: Got signal: 6 (Abort trap: 6).
m27017| Backtrace:0x1006c014b 0x1006bfeaf 0x7fff8e0f05aa 0 0x7fff93570b1a 0x1006672e0 0x100472518 0x100475d2f 0x100129267 0x1001bb3c5 0x1001bc002 0x1001bd2ac 0x1003d5c3f 0x1002a56db 0x100006b54 0x100684db1 0x1006f4595 0x7fff8b05f899 0x7fff8b05f72a 0x7fff8b063fc9 
m27017|  0   mongod                              0x00000001006c014b _ZN5mongo15printStackTraceERSo + 43
m27017|  1   mongod                              0x00000001006bfeaf _ZN5mongo12_GLOBAL__N_110abruptQuitEi + 191
m27017|  2   libsystem_platform.dylib            0x00007fff8e0f05aa _sigtramp + 26
m27017|  3   ???                                 0x0000000000000000 0x0 + 0
m27017|  4   libsystem_c.dylib                   0x00007fff93570b1a abort + 125
m27017|  5   mongod                              0x00000001006672e0 _ZN5mongo13fassertFailedEi + 224
m27017|  6   mongod                              0x0000000100472518 _ZN5mongoL8_logOpRSEPKcS1_S1_RKNS_7BSONObjEPS2_Pbb + 376
m27017|  7   mongod                              0x0000000100475d2f _ZN5mongo5logOpEPKcS1_RKNS_7BSONObjEPS2_PbbPS3_ + 79
m27017|  8   mongod                              0x0000000100129267 _ZN5mongo14CmdCreateIndex3runERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb + 5549
m27017|  9   mongod                              0x00000001001bb3c5 _ZN5mongo12_execCommandEPNS_7CommandERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb + 37
m27017|  10  mongod                              0x00000001001bc002 _ZN5mongo7Command11execCommandEPS0_RNS_6ClientEiPKcRNS_7BSONObjERNS_14BSONObjBuilderEb + 2566
m27017|  11  mongod                              0x00000001001bd2ac _ZN5mongo12_runCommandsEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi + 1388
m27017|  12  mongod                              0x00000001003d5c3f _ZN5mongo11newRunQueryERNS_7MessageERNS_12QueryMessageERNS_5CurOpES1_ + 1615
m27017|  13  mongod                              0x00000001002a56db _ZN5mongo16assembleResponseERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE + 2443
m27017|  14  mongod                              0x0000000100006b54 _ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE + 308
m27017|  15  mongod                              0x0000000100684db1 _ZN5mongo17PortMessageServer17handleIncomingMsgEPv + 1681
m27017|  16  mongod                              0x00000001006f4595 thread_proxy + 229
m27017|  17  libsystem_pthread.dylib             0x00007fff8b05f899 _pthread_body + 138
m27017|  18  libsystem_pthread.dylib             0x00007fff8b05f72a _pthread_struct_init + 0
m27017|  19  libsystem_pthread.dylib             0x00007fff8b063fc9 thread_start + 13
m27019| 2014-09-18T17:15:08.260+0100 [conn52] end connection 10.7.1.80:49682 (2 connections now open)
m27018| 2014-09-18T17:15:08.260+0100 [conn50] end connection 10.7.1.80:49670 (4 connections now open)
m27018| 2014-09-18T17:15:08.260+0100 [conn54] end connection 10.7.1.80:49679 (4 connections now open)
m27018| 2014-09-18T17:15:09.372+0100 [rsHealthPoll] DBClientCursor::init call() failed
m27018| 2014-09-18T17:15:09.374+0100 [rsHealthPoll] replset info adamc-mbp.10gen.cc:27017 heartbeat failed, retrying
m27018| 2014-09-18T17:15:09.375+0100 [rsHealthPoll] warning: Failed to connect to 10.7.1.80:27017, reason: errno:61 Connection refused
m27018| 2014-09-18T17:15:09.376+0100 [rsHealthPoll] replSet info adamc-mbp.10gen.cc:27017 is down (or slow to respond): 
m27018| 2014-09-18T17:15:09.376+0100 [rsHealthPoll] replSet member adamc-mbp.10gen.cc:27017 is now in state DOWN
m27019| 2014-09-18T17:15:09.871+0100 [rsHealthPoll] DBClientCursor::init call() failed
m27019| 2014-09-18T17:15:09.871+0100 [rsHealthPoll] replset info adamc-mbp.10gen.cc:27017 heartbeat failed, retrying
m27019| 2014-09-18T17:15:09.873+0100 [rsHealthPoll] warning: Failed to connect to 10.7.1.80:27017, reason: errno:61 Connection refused
m27019| 2014-09-18T17:15:09.873+0100 [rsHealthPoll] replSet info adamc-mbp.10gen.cc:27017 is down (or slow to respond): 
m27019| 2014-09-18T17:15:09.873+0100 [rsHealthPoll] replSet member adamc-mbp.10gen.cc:27017 is now in state DOWN
m27018| 2014-09-18T17:15:10.453+0100 [conn49] end connection 10.7.1.80:49669 (2 connections now open)

Participants:

 Description   

Active (background) index builds during primary stepdown try to log the index build to the oplog as primary, causing fassert and shutdown.

The stepdown should cancel any index builds, since they have not been replicated.

Workaround: Before stepping down a primary one should cancel all active index builds.



 Comments   
Comment by Githook User [ 05/Feb/15 ]

Author:

{u'username': u'benety', u'name': u'Benety Goh', u'email': u'benety@mongodb.com'}

Message: SERVER-15308 SERVER-17150 cancel current command on the primary when the node is stepped down

(cherry picked from commit 1e58c0374677a37c09438aa8c21d745cd5b08468)
Branch: v3.0
https://github.com/mongodb/mongo/commit/25d7e2bde8969c3a2c6725c3663eb21e7df86d21

Comment by Githook User [ 05/Feb/15 ]

Author:

{u'username': u'benety', u'name': u'Benety Goh', u'email': u'benety@mongodb.com'}

Message: SERVER-15308 SERVER-17150 cancel current command on the primary when the node is stepped down
Branch: master
https://github.com/mongodb/mongo/commit/1e58c0374677a37c09438aa8c21d745cd5b08468

Generated at Thu Feb 08 03:37:39 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.