1. Insert 1,000,000 1kb records (1GB) into primary of replica set (2 servers, one arbiter).
2. Stop primary well before secondary is caught up (Primary has 1,000,000 recs, Secondary has about 500,000 recs).
3. Secondary is now primary. Insert one extra record.
4. Restart original primary. Its log is below:
Tony1:~# mongodb-linux-x86_64-1.8.0-rc2/bin/mongod --dbpath db --dur --replSet rs0 --noprealloc --oplogSize 2000 --smallfiles
note: noprealloc may hurt performance in many applications
Fri Mar 11 00:02:57 [initandlisten] MongoDB starting : pid=938 port=27017 dbpath=db 64-bit
Fri Mar 11 00:02:57 [initandlisten] db version v1.8.0-rc2, pdfile version 4.5
Fri Mar 11 00:02:57 [initandlisten] git version: 460d32f86ba837a4f1dd41cfeb65eddee41df65f
Fri Mar 11 00:02:57 [initandlisten] build sys info: Linux bs-linux64.10gen.cc 2.6.21.7-2.ec2.v1.2.fc8xen #1 SMP Fri Nov 20 17:48:28 EST 2009 x86_64 BOOST_LIB_VERSION=1_41
Fri Mar 11 00:02:57 [initandlisten] journal dir=db/journal
Fri Mar 11 00:02:57 [initandlisten] recover : no journal files present, no recovery needed
Fri Mar 11 00:02:57 [initandlisten] waiting for connections on port 27017
Fri Mar 11 00:02:57 [websvr] web admin interface listening on port 28017
Fri Mar 11 00:02:57 [initandlisten] connection accepted from 127.0.0.1:32924 #1
Fri Mar 11 00:02:57 [initandlisten] connection accepted from 50.56.93.218:36447 #2
Fri Mar 11 00:02:57 [ReplSetHealthPollTask] replSet info 50.56.93.135 is up
Fri Mar 11 00:02:57 [ReplSetHealthPollTask] replSet member 50.56.93.135 ARBITER
Fri Mar 11 00:02:57 [startReplSets] replSet STARTUP2
Fri Mar 11 00:02:57 [replica set sync] replSet SECONDARY
Fri Mar 11 00:02:57 [rs Manager] replSet info not electing self, we are not freshest
Fri Mar 11 00:02:57 [rs Manager] replSet info not electing self, we are not freshest
Fri Mar 11 00:02:57 [initandlisten] connection accepted from 50.56.93.135:44900 #3
Fri Mar 11 00:02:57 [initandlisten] connection accepted from 50.56.93.134:57576 #4
Fri Mar 11 00:02:59 [ReplSetHealthPollTask] replSet info 50.56.93.134 is up
Fri Mar 11 00:02:59 [ReplSetHealthPollTask] replSet member 50.56.93.134 PRIMARY
Fri Mar 11 00:02:59 [replica set sync] building new index on
for local.me
Fri Mar 11 00:02:59 [replica set sync] done for 0 records 0.001secs
Fri Mar 11 00:02:59 [replica set sync] replSet our last op time written: Mar 10 23:54:20:69b
Fri Mar 11 00:02:59 [replica set sync] replset source's GTE: Mar 11 00:01:44:1
Fri Mar 11 00:02:59 [replica set sync] replSet rollback 0
Fri Mar 11 00:02:59 [replica set sync] replSet ROLLBACK
Fri Mar 11 00:02:59 [replica set sync] replSet rollback 1
Fri Mar 11 00:02:59 [replica set sync] replSet rollback 2 FindCommonPoint
Fri Mar 11 00:02:59 [replica set sync] replSet info rollback our last optime: Mar 10 23:54:20:69b
Fri Mar 11 00:02:59 [replica set sync] replSet info rollback their last optime: Mar 11 00:02:38:1
Fri Mar 11 00:02:59 [replica set sync] replSet info rollback diff in end of log times: -498 seconds
Fri Mar 11 00:03:23 [replica set sync] replSet rollback found matching events at Mar 10 23:53:25:8c5
Fri Mar 11 00:03:23 [replica set sync] replSet rollback findcommonpoint scanned : 444453
Fri Mar 11 00:03:23 [replica set sync] replSet replSet rollback 3 fixup
Fri Mar 11 00:03:47 [initandlisten] connection accepted from 50.56.93.218:36453 #5
Fri Mar 11 00:03:57 [dur] lsn set 59425
Fri Mar 11 00:04:57 [dur] lsn set 118955
Fri Mar 11 00:05:06 [replica set sync] replSet rollback 3.5
Fri Mar 11 00:05:06 [replica set sync] replSet rollback 4 n:444449
Fri Mar 11 00:05:06 [replica set sync] replSet minvalid=Mar 11 00:02:38 4d79669e:1
Fri Mar 11 00:05:06 [dur] lsn set 127505
Fri Mar 11 00:05:06 [replica set sync] building new index on
for local.replset.minvalid
Fri Mar 11 00:05:06 [replica set sync] done for 0 records 0.001secs
Fri Mar 11 00:05:06 [replica set sync] replSet rollback 4.6
Fri Mar 11 00:05:06 [replica set sync] replSet rollback 4.7
Fri Mar 11 00:05:10 [replica set sync] test.foo Assertion failure: unindex failed test.foo.$_id
Fri Mar 11 00:05:10 [replica set sync] Assertion failure: _unindex failed: DR102 too much data written uncommitted
obj:
key:{ : 613559.0 }
dl:5:4a1d8e8
0x55138e 0x76fabd 0x772240 0x647106 0x6fd95b 0x700857 0x7016a9 0x70655d 0x707908 0x70798c 0x70a7a2 0x8b89b0 0x7f0ee5a67fc7 0x7f0ee50375ad
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo12sayDbContextEPKc+0xae) [0x55138e]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod [0x76fabd]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11DataFileMgr12deleteRecordEPKcPNS_6RecordERKNS_7DiskLocEbb+0x140) [0x772240]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo13deleteObjectsEPKcNS_7BSONObjEbbbPNS_11RemoveSaverE+0x9c6) [0x647106]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl9syncFixUpERNS_10HowToFixUpERNS_11OplogReaderE+0x20ab) [0x6fd95b]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl13_syncRollbackERNS_11OplogReaderE+0x2e7) [0x700857]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl12syncRollbackERNS_11OplogReaderE+0x9) [0x7016a9]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl8syncTailEv+0xb3d) [0x70655d]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl11_syncThreadEv+0xc8) [0x707908]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl10syncThreadEv+0x3c) [0x70798c]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo15startSyncThreadEv+0x252) [0x70a7a2]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(thread_proxy+0x80) [0x8b89b0]
/lib/libpthread.so.0 [0x7f0ee5a67fc7]
/lib/libc.so.6(clone+0x6d) [0x7f0ee50375ad]
Fri Mar 11 00:05:10 [replica set sync] unindex failed (key too big?) test.foo.$id
replSet error rollback delete failed ns:test.foo
Fri Mar 11 00:05:10 [replica set sync] test.foo Assertion failure: unindex failed test.foo.$_id
Fri Mar 11 00:05:10 [replica set sync] Assertion failure: _unindex failed: DR102 too much data written uncommitted
obj:
key:{ : 613560.0 }
dl:5:4a1dc20
0x55138e 0x76fabd 0x772240 0x647106 0x6fd95b 0x700857 0x7016a9 0x70655d 0x707908 0x70798c 0x70a7a2 0x8b89b0 0x7f0ee5a67fc7 0x7f0ee50375ad
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo12sayDbContextEPKc+0xae) [0x55138e]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod [0x76fabd]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11DataFileMgr12deleteRecordEPKcPNS_6RecordERKNS_7DiskLocEbb+0x140) [0x772240]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo13deleteObjectsEPKcNS_7BSONObjEbbbPNS_11RemoveSaverE+0x9c6) [0x647106]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl9syncFixUpERNS_10HowToFixUpERNS_11OplogReaderE+0x20ab) [0x6fd95b]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl13_syncRollbackERNS_11OplogReaderE+0x2e7) [0x700857]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl12syncRollbackERNS_11OplogReaderE+0x9) [0x7016a9]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl8syncTailEv+0xb3d) [0x70655d]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl11_syncThreadEv+0xc8) [0x707908]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl10syncThreadEv+0x3c) [0x70798c]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo15startSyncThreadEv+0x252) [0x70a7a2]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(thread_proxy+0x80) [0x8b89b0]
/lib/libpthread.so.0 [0x7f0ee5a67fc7]
/lib/libc.so.6(clone+0x6d) [0x7f0ee50375ad]
Fri Mar 11 00:05:10 [replica set sync] unindex failed (key too big?) test.foo.$id
replSet error rollback delete failed ns:test.foo
Fri Mar 11 00:05:10 [replica set sync] test.foo Assertion failure: unindex failed test.foo.$_id
Fri Mar 11 00:05:10 [replica set sync] Assertion failure: _unindex failed: DR102 too much data written uncommitted
obj:
key:{ : 613561.0 }
dl:5:4a1df58
0x55138e 0x76fabd 0x772240 0x647106 0x6fd95b 0x700857 0x7016a9 0x70655d 0x707908 0x70798c 0x70a7a2 0x8b89b0 0x7f0ee5a67fc7 0x7f0ee50375ad
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo12sayDbContextEPKc+0xae) [0x55138e]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod [0x76fabd]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11DataFileMgr12deleteRecordEPKcPNS_6RecordERKNS_7DiskLocEbb+0x140) [0x772240]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo13deleteObjectsEPKcNS_7BSONObjEbbbPNS_11RemoveSaverE+0x9c6) [0x647106]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl9syncFixUpERNS_10HowToFixUpERNS_11OplogReaderE+0x20ab) [0x6fd95b]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl13_syncRollbackERNS_11OplogReaderE+0x2e7) [0x700857]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl12syncRollbackERNS_11OplogReaderE+0x9) [0x7016a9]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl8syncTailEv+0xb3d) [0x70655d]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl11_syncThreadEv+0xc8) [0x707908]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo11ReplSetImpl10syncThreadEv+0x3c) [0x70798c]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(_ZN5mongo15startSyncThreadEv+0x252) [0x70a7a2]
mongodb-linux-x86_64-1.8.0-rc2/bin/mongod(thread_proxy+0x80) [0x8b89b0]
/lib/libpthread.so.0 [0x7f0ee5a67fc7]
/lib/libc.so.6(clone+0x6d) [0x7f0ee50375ad]
Fri Mar 11 00:05:10 [replica set sync] unindex failed (key too big?) test.foo.$id
replSet error rollback delete failed ns:test.foo
...
Error repeats forever very fast