-
Type: Bug
-
Resolution: Done
-
Priority: Major - P3
-
Affects Version/s: None
-
Component/s: Index Maintenance, Replication
-
None
-
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)
Showstart 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.
- is related to
-
SERVER-14186 rs.stepDown during mapReduce causes fassert in logOp
- Closed
-
SERVER-17150 logOp fassert when dropping collection on stepped-down primary
- Closed
-
SERVER-15310 kill all operations before attempting stepdown
- Closed
- related to
-
SERVER-17205 logOp fassert when creating namespace on stepped-down primary via update
- Closed
-
SERVER-17208 logOp fassert when creating namespace on stepped-down primary via createCollection
- Closed