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

IndexRebuilder assertion at startup

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: None
    • Component/s: Index Maintenance
    • Labels:
      None
    • OS X

      Looking to see if I can reproduce this state from scratch. Data files attached to ticket.

      git version: 320397d71a0344db775146e42a54d755241533b2

      Log messages at startup with logLevel(5)

      dan:(git)mongo[master]/$ mongod --dbpath /data/corrupt/ -vvvvv
      2014-01-26T13:07:44.626-0500 [DataFileSync] BackgroundJob starting: DataFileSync
      2014-01-26T13:07:44.626-0500 shardObjTest passed
      2014-01-26T13:07:44.626-0500 isInRangeTest passed
      2014-01-26T13:07:44.626-0500 shardKeyTest passed
      2014-01-26T13:07:44.626-0500 [initandlisten] MongoDB starting : pid=1629 port=27017 dbpath=/data/corrupt/ 64-bit host=DANIELs-MacBook-Pro-2.local
      2014-01-26T13:07:44.626-0500 [initandlisten] 
      2014-01-26T13:07:44.627-0500 [initandlisten] ** NOTE: This is a development version (2.5.5-pre-) of MongoDB.
      2014-01-26T13:07:44.627-0500 [initandlisten] **       Not recommended for production.
      2014-01-26T13:07:44.627-0500 [initandlisten] 
      2014-01-26T13:07:44.627-0500 [initandlisten] db version v2.5.5-pre-
      2014-01-26T13:07:44.627-0500 [initandlisten] git version: 320397d71a0344db775146e42a54d755241533b2
      2014-01-26T13:07:44.627-0500 [initandlisten] build info: Darwin DANIELs-MacBook-Pro-2.local 13.0.2 Darwin Kernel Version 13.0.2: Sun Sep 29 19:38:57 PDT 2013; root:xnu-2422.75.4~1/RELEASE_X86_64 x86_64 BOOST_LIB_VERSION=1_49
      2014-01-26T13:07:44.627-0500 [initandlisten] allocator: tcmalloc
      2014-01-26T13:07:44.627-0500 [initandlisten] options: { storage: { dbPath: "/data/corrupt/" }, vvvvv: true }
      2014-01-26T13:07:44.628-0500 [initandlisten] journal dir=/data/corrupt/journal
      2014-01-26T13:07:44.628-0500 [initandlisten] recover : no journal files present, no recovery needed
      2014-01-26T13:07:44.638-0500 [initandlisten] opening db:  local
      2014-01-26T13:07:44.638-0500 [initandlisten] mmf open /data/corrupt/local.ns
      2014-01-26T13:07:44.638-0500 [initandlisten] mmf finishOpening 0x104d89000 /data/corrupt/local.ns len:16777216
      2014-01-26T13:07:44.639-0500 [initandlisten] mmf open /data/corrupt/local.0
      2014-01-26T13:07:44.639-0500 [initandlisten] mmf finishOpening 0x106d89000 /data/corrupt/local.0 len:67108864
      2014-01-26T13:07:44.644-0500 [initandlisten] enter repairDatabases (to check pdfile version #)
      2014-01-26T13:07:44.644-0500 [initandlisten] 	local
      2014-01-26T13:07:44.644-0500 [initandlisten] mmf close /data/corrupt/local.0
      2014-01-26T13:07:44.644-0500 [initandlisten] _groupCommit 
      2014-01-26T13:07:44.644-0500 [initandlisten] journal REMAPPRIVATEVIEW
      2014-01-26T13:07:44.644-0500 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:2 0ms
      2014-01-26T13:07:44.644-0500 [initandlisten] groupCommit end
      2014-01-26T13:07:44.644-0500 [initandlisten] mmf close /data/corrupt/local.ns
      2014-01-26T13:07:44.644-0500 [initandlisten] _groupCommit 
      2014-01-26T13:07:44.644-0500 [initandlisten] journal REMAPPRIVATEVIEW
      2014-01-26T13:07:44.644-0500 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms
      2014-01-26T13:07:44.644-0500 [initandlisten] groupCommit end
      2014-01-26T13:07:44.644-0500 [initandlisten] 	test
      2014-01-26T13:07:44.645-0500 [initandlisten] opening db:  test
      2014-01-26T13:07:44.645-0500 [initandlisten] mmf open /data/corrupt/test.ns
      2014-01-26T13:07:44.645-0500 [initandlisten] mmf finishOpening 0x104d89000 /data/corrupt/test.ns len:16777216
      2014-01-26T13:07:44.646-0500 [initandlisten] mmf open /data/corrupt/test.0
      2014-01-26T13:07:44.646-0500 [initandlisten] mmf finishOpening 0x106d89000 /data/corrupt/test.0 len:67108864
      2014-01-26T13:07:44.650-0500 [initandlisten] mmf open /data/corrupt/test.1
      2014-01-26T13:07:44.650-0500 [initandlisten] mmf finishOpening 0x10ee0c000 /data/corrupt/test.1 len:134217728
      2014-01-26T13:07:44.660-0500 [initandlisten] mmf close /data/corrupt/test.1
      2014-01-26T13:07:44.660-0500 [initandlisten] _groupCommit 
      2014-01-26T13:07:44.660-0500 [initandlisten] journal REMAPPRIVATEVIEW
      2014-01-26T13:07:44.660-0500 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms
      2014-01-26T13:07:44.660-0500 [initandlisten] groupCommit end
      2014-01-26T13:07:44.660-0500 [initandlisten] mmf close /data/corrupt/test.0
      2014-01-26T13:07:44.660-0500 [initandlisten] _groupCommit 
      2014-01-26T13:07:44.660-0500 [initandlisten] journal REMAPPRIVATEVIEW
      2014-01-26T13:07:44.660-0500 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 1 n:1 0ms
      2014-01-26T13:07:44.660-0500 [initandlisten] groupCommit end
      2014-01-26T13:07:44.660-0500 [initandlisten] mmf close /data/corrupt/test.ns
      2014-01-26T13:07:44.660-0500 [initandlisten] _groupCommit 
      2014-01-26T13:07:44.660-0500 [initandlisten] journal REMAPPRIVATEVIEW
      2014-01-26T13:07:44.660-0500 [initandlisten] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 0ms
      2014-01-26T13:07:44.660-0500 [initandlisten] groupCommit end
      2014-01-26T13:07:44.661-0500 [initandlisten] done repairDatabases
      2014-01-26T13:07:44.661-0500 [initandlisten] opening db:  admin
      2014-01-26T13:07:44.661-0500 [initandlisten] query admin.system.roles ntoreturn:0 ntoskip:0 keyUpdates:0 numYields:0 locks(micros) W:141 r:45 nreturned:0 reslen:20 0ms
      2014-01-26T13:07:44.661-0500 [snapshot] BackgroundJob starting: snapshot
      2014-01-26T13:07:44.661-0500 [PeriodicTaskRunner] BackgroundJob starting: PeriodicTaskRunner
      2014-01-26T13:07:44.661-0500 [ClientCursorMonitor] BackgroundJob starting: ClientCursorMonitor
      2014-01-26T13:07:44.661-0500 [TTLMonitor] BackgroundJob starting: TTLMonitor
      2014-01-26T13:07:44.661-0500 [IndexRebuilder] BackgroundJob starting: IndexRebuilder
      2014-01-26T13:07:44.661-0500 [initandlisten] fd limit hard:9223372036854775807 soft:4864 max conn: 3891
      2014-01-26T13:07:44.661-0500 [IndexRebuilder] opening db:  local
      2014-01-26T13:07:44.661-0500 [IndexRebuilder] mmf open /data/corrupt/local.ns
      2014-01-26T13:07:44.662-0500 [IndexRebuilder] mmf finishOpening 0x10509b000 /data/corrupt/local.ns len:16777216
      2014-01-26T13:07:44.663-0500 [IndexRebuilder] mmf open /data/corrupt/local.0
      2014-01-26T13:07:44.663-0500 [IndexRebuilder] mmf finishOpening 0x10709b000 /data/corrupt/local.0 len:67108864
      2014-01-26T13:07:44.670-0500 [initandlisten] run command local.$cmd { create: "startup_log", size: 10485760, capped: true }
      2014-01-26T13:07:44.670-0500 [initandlisten] create collection local.startup_log { size: 10485760, capped: true }
      2014-01-26T13:07:44.671-0500 [initandlisten] command local.$cmd command: { create: "startup_log", size: 10485760, capped: true } ntoreturn:1 keyUpdates:0 numYields:0  reslen:75 0ms
      2014-01-26T13:07:44.671-0500 [initandlisten] info PageFaultRetryableSection will not yield, already locked upon reaching
      2014-01-26T13:07:44.671-0500 [initandlisten] insert local.startup_log ninserted:1 keyUpdates:0 numYields:0  0ms
      2014-01-26T13:07:44.671-0500 [initandlisten] waiting for connections on port 27017
      2014-01-26T13:07:44.679-0500 [IndexRebuilder] opening db:  test
      2014-01-26T13:07:44.679-0500 [IndexRebuilder] mmf open /data/corrupt/test.ns
      2014-01-26T13:07:44.679-0500 [IndexRebuilder] mmf finishOpening 0x10b09b000 /data/corrupt/test.ns len:16777216
      2014-01-26T13:07:44.680-0500 [IndexRebuilder] mmf open /data/corrupt/test.0
      2014-01-26T13:07:44.680-0500 [IndexRebuilder] mmf finishOpening 0x112e0c000 /data/corrupt/test.0 len:67108864
      2014-01-26T13:07:44.686-0500 [IndexRebuilder] mmf open /data/corrupt/test.1
      2014-01-26T13:07:44.686-0500 [IndexRebuilder] mmf finishOpening 0x11ae0c000 /data/corrupt/test.1 len:134217728
      2014-01-26T13:07:44.695-0500 [IndexRebuilder] mmf close /data/corrupt/test.1
      2014-01-26T13:07:44.695-0500 [IndexRebuilder] _groupCommit 
      2014-01-26T13:07:44.695-0500 [IndexRebuilder] journal WRITETODATAFILES 1
      2014-01-26T13:07:44.695-0500 [IndexRebuilder] journal WRITETODATAFILES 2
      2014-01-26T13:07:44.695-0500 [IndexRebuilder] journal WRITETODATAFILES 0.108ms
      2014-01-26T13:07:44.695-0500 [IndexRebuilder] journal REMAPPRIVATEVIEW
      2014-01-26T13:07:44.700-0500 [IndexRebuilder] journal REMAPPRIVATEVIEW done startedAt: 0 n:1 4ms
      2014-01-26T13:07:44.700-0500 [IndexRebuilder] groupCommit end
      2014-01-26T13:07:44.706-0500 [IndexRebuilder] IndexRebuilder::checkNS: local.startup_log
      2014-01-26T13:07:44.706-0500 [IndexRebuilder] IndexRebuilder::checkNS: local.system.indexes
      2014-01-26T13:07:44.706-0500 [IndexRebuilder] IndexRebuilder::checkNS: local.system.namespaces
      2014-01-26T13:07:44.706-0500 [IndexRebuilder] IndexRebuilder::checkNS: test.repro
      2014-01-26T13:07:44.706-0500 [IndexRebuilder] IndexRebuilder::checkNS: test.c
      2014-01-26T13:07:44.707-0500 [IndexRebuilder] uh oh: -2
      2014-01-26T13:07:44.707-0500 [IndexRebuilder] test.c Assertion failure n >= 0 && n < static_cast<int>(_files.size()) src/mongo/db/storage/extent_manager.cpp 111
      2014-01-26T13:07:44.716-0500 [IndexRebuilder] test.c 0x1007297a0 0x1006d685b 0x1006c4273 0x10050bf12 0x10050c8b6 0x10050f358 0x10011011f 0x10010186a 0x1001092d1 0x1002b61d3 0x1002b5acc 0x1006c639d 0x100763581 0x7fff899af899 0x7fff899af72a 0x7fff899b3fc9 
       0   mongod                              0x00000001007297a0 _ZN5mongo15printStackTraceERSo + 64
       1   mongod                              0x00000001006d685b _ZN5mongo10logContextEPKc + 155
       2   mongod                              0x00000001006c4273 _ZN5mongo12verifyFailedEPKcS1_j + 435
       3   mongod                              0x000000010050bf12 _ZNK5mongo13ExtentManager12_getOpenFileEi + 258
       4   mongod                              0x000000010050c8b6 _ZNK5mongo13ExtentManager9recordForERKNS_7DiskLocE + 22
       5   mongod                              0x000000010050f358 _ZNK5mongo7DiskLoc3objEv + 72
       6   mongod                              0x000000010011011f _ZN5mongo12IndexCatalog4initEv + 287
       7   mongod                              0x000000010010186a _ZN5mongo10CollectionC2ERKNS_10StringDataEPNS_16NamespaceDetailsEPNS_8DatabaseE + 314
       8   mongod                              0x00000001001092d1 _ZN5mongo8Database13getCollectionERKNS_10StringDataE + 305
       9   mongod                              0x00000001002b61d3 _ZN5mongo14IndexRebuilder7checkNSERKSt4listISsSaISsEE + 307
       10  mongod                              0x00000001002b5acc _ZN5mongo14IndexRebuilder3runEv + 380
       11  mongod                              0x00000001006c639d _ZN5mongo13BackgroundJob7jobBodyEv + 237
       12  mongod                              0x0000000100763581 thread_proxy + 177
       13  libsystem_pthread.dylib             0x00007fff899af899 _pthread_body + 138
       14  libsystem_pthread.dylib             0x00007fff899af72a _pthread_struct_init + 0
       15  libsystem_pthread.dylib             0x00007fff899b3fc9 thread_start + 13
      2014-01-26T13:07:44.716-0500 [IndexRebuilder] warning: index rebuilding did not complete
      2014-01-26T13:07:44.716-0500 [IndexRebuilder] checking complete
      

            Assignee:
            Unassigned Unassigned
            Reporter:
            dan@mongodb.com Daniel Pasette (Inactive)
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: