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

Large rollback fails (DR102 too much data written uncommitted) (after "rollback 6")

    • Type: Icon: Bug Bug
    • Resolution: Done
    • Priority: Icon: Minor - P4 Minor - P4
    • 1.8.1, 1.9.0
    • Affects Version/s: 1.8.0
    • Component/s: Storage
    • None
    • Environment:
      Linux 64-bit, 256mb RAM, 512mb swap, 10gb disk
      > mongodb-linux-x86_64-1.8.0-rc2/bin/mongod --dbpath db --dur --replSet rs0 --noprealloc --oplogSize 2000 --smallfiles
    • ALL

      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

      { _id: 1 }

      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

      { _id: 1 }

      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:

      { _id: 613559.0, x: 183.0, t: BinData }

      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:

      { _id: 613560.0, x: 184.0, t: BinData }

      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:

      { _id: 613561.0, x: 185.0, t: BinData }

      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

            Assignee:
            aaron Aaron Staple
            Reporter:
            tonyh Tony Hannan
            Votes:
            1 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: