Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-15308

Stepdown does not cancel active (background) index builds causing shutdown on completion

    • Fully Compatible
    • ALL
    • Hide

      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)
      
      Show
      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)

      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.

            Assignee:
            benety.goh@mongodb.com Benety Goh
            Reporter:
            adam@comerford.net Adam Comerford
            Votes:
            0 Vote for this issue
            Watchers:
            11 Start watching this issue

              Created:
              Updated:
              Resolved: