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

dropIndexes() produces "Assertion: 17348:cannot dropAllIndexes when index builds in progress"

XMLWordPrintableJSON

    • Type: Icon: Bug Bug
    • Resolution: Duplicate
    • Priority: Icon: Major - P3 Major - P3
    • None
    • Affects Version/s: 3.0.2
    • Component/s: Replication
    • None
    • ALL
    • Hide

      Tried to reproduce as follows but could not reproduce:

      Started 3-node RS with following mongod options:

      • "engine" : "wiredTiger",
      • "indexBuildRetry" : false,
      1. Allowed one node to become stale.
      2. Dropped collection
      3. Recreated collection and seeded with data
      4. Ran two background index builds
      5. Killed first of two index builds
      6. Ran dropIndexes()
      7. Repeated 1-4 above, killed second of two index builds
      8. Ran dropIndexes()

      => dropIndexes() did not reproduce error either time.

      Show
      Tried to reproduce as follows but could not reproduce: Started 3-node RS with following mongod options: "engine" : "wiredTiger", "indexBuildRetry" : false, Allowed one node to become stale. Dropped collection Recreated collection and seeded with data Ran two background index builds Killed first of two index builds Ran dropIndexes() Repeated 1-4 above, killed second of two index builds Ran dropIndexes() => dropIndexes() did not reproduce error either time.
    • 0

      Background:

      • replica set – one secondary (node 19) was in RECOVERY mode the whole time
      • full list of relevant events from node 20
        • drop collection on document_store.product_01
        • a few buildIndex (background) operations that were killed prior to completing – all were successfully killed according to the log
        • dropIndexes run on document_store.product_01 – customer reports successful completion but indexes not dropped
        • dropAllIndexes run on document_store.product_01 --> Assertion
      egrep 'build index|createIndexes|kill op|Assertion|drop' mongo20.log

      2015-05-26T06:49:28.787Z I COMMAND  [conn117172] CMD: drop document_store.product_01
2015-05-26T06:49:38.715Z I COMMAND  [conn117172] CMD: drop document_store.collapsedProduct_01
2015-05-26T10:23:15.581Z I INDEX    [conn117172] build index on: document_store.product_01 properties: { v: 1, key: { modifiedDate: 1.0 }, name: "modifiedDate_1", ns: "document_store.product_01", background: true }
2015-05-26T13:06:47.426Z I COMMAND  [conn118796] going to kill op: op: 406659245.0
2015-05-26T13:06:47.470Z I COMMAND  [conn117172] command document_store.$cmd command: createIndexes { createIndexes: "product_01", indexes: [ { key: { modifiedDate: 1.0 }, name: "modifiedDate_1", background: true } ] } keyUpdates:0 writeConflicts:0 numYields:504648 reslen:151 locks:{ Global: { acquireCount: { w: 504649 } }, Database: { acquireCount: { w: 504649, W: 2 }, acquireWaitCount: { w: 14 }, timeAcquiringMicros: { w: 30991 } }, Collection: { acquireCount: { w: 504649 } } } 9811892ms
2015-05-26T13:06:47.504Z I INDEX    [conn117172] build index on: document_store.product_01 properties: { v: 1, key: { endDate: 1.0 }, name: "endDate_1", ns: "document_store.product_01", background: true }
2015-05-26T13:07:14.475Z I COMMAND  [conn118796] going to kill op: op: 409353436.0
2015-05-26T13:07:14.488Z I COMMAND  [conn117172] command document_store.$cmd command: createIndexes { createIndexes: "product_01", indexes: [ { key: { endDate: 1.0 }, name: "endDate_1", background: true } ] } keyUpdates:0 writeConflicts:0 numYields:8592 reslen:151 locks:{ Global: { acquireCount: { w: 8593 } }, Database: { acquireCount: { w: 8593, W: 2 }, acquireWaitCount: { W: 1 }, timeAcquiringMicros: { W: 10553 } }, Collection: { acquireCount: { w: 8593 } } } 26987ms
2015-05-26T13:07:14.562Z I INDEX    [conn117172] build index on: document_store.product_01 properties: { v: 1, key: { productId: -1.0, status: 1.0 }, name: "productId_-1_status_1", ns: "document_store.product_01", background: true }
2015-05-26T13:12:39.915Z I INDEX    [conn118796] build index on: document_store.product_01 properties: { v: 1, key: { endDate: 1.0 }, name: "endDate_1", ns: "document_store.product_01", background: true }
2015-05-26T13:20:41.651Z I COMMAND  [conn118885] going to kill op: op: 409364948.0
2015-05-26T13:20:41.683Z I COMMAND  [conn117172] command document_store.$cmd command: createIndexes { createIndexes: "product_01", indexes: [ { key: { productId: -1.0, status: 1.0 }, name: "productId_-1_status_1", background: true } ] } keyUpdates:0 writeConflicts:0 numYields:96458 reslen:151 locks:{ Global: { acquireCount: { w: 96459 } }, Database: { acquireCount: { w: 96459, W: 2 }, acquireWaitCount: { w: 7, W: 2 }, timeAcquiringMicros: { w: 8560, W: 30588 } }, Collection: { acquireCount: { w: 96459 } } } 807136ms
2015-05-26T13:20:41.688Z I COMMAND  [conn118796] command document_store.$cmd command: createIndexes { createIndexes: "product_01", indexes: [ { key: { endDate: 1.0 }, name: "endDate_1", background: true } ] } keyUpdates:0 writeConflicts:0 numYields:80444 reslen:196 locks:{ Global: { acquireCount: { w: 80445 } }, Database: { acquireCount: { w: 80445, W: 2 }, acquireWaitCount: { w: 1, W: 2 }, timeAcquiringMicros: { w: 9682, W: 12576 } }, Collection: { acquireCount: { w: 80445 } } } 481786ms
2015-05-26T13:21:48.224Z I COMMAND  [conn118885] CMD: drop document_store.test
2015-05-26T13:23:28.877Z I COMMAND  [conn118885] CMD: dropIndexes document_store.product_01
2015-05-26T13:24:49.939Z I COMMAND  [conn118885] CMD: dropIndexes document_store.product_01
2015-05-26T13:25:20.344Z I COMMAND  [conn118885] CMD: dropIndexes document_store.product_01
2015-05-26T13:25:20.344Z I -        [conn118885] Assertion: 17348:cannot dropAllIndexes when index builds in progress
 mongod(_ZN5mongo12IndexCatalog14dropAllIndexesEPNS_16OperationContextEb+0x729) [0x91b809]

      Full stack trace from mongo20.log:

      2015-05-26T13:25:20.344Z I COMMAND  [conn118885] CMD: dropIndexes document_store.product_01
2015-05-26T13:25:20.344Z I -        [conn118885] Assertion: 17348:cannot dropAllIndexes when index builds in progress
2015-05-26T13:25:20.408Z I CONTROL  [conn118885]
 0xf68719 0xf06c91 0xeeb1af 0x91b809 0x9501dd 0x9506de 0x9d1e74 0x9d2dfd 0x9d3b0b 0xba4746 0xab64b0 0x7fa04d 0xf1a6cb 0x3930c079d1 0x39308e89dd
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"400000","o":"B68719"},{"b":"400000","o":"B06C91"},{"b":"400000","o":"AEB1AF"},{"b":"400000","o":"51B809"},{"b":"400000","o":"5501DD"},{"b":"400000","o":"5506DE"},{"b":"400000","o":"5D1E74"},{"b":"400000","o":"5D2DFD"},{"b":"400000","o":"5D3B0B"},{"b":"400000","o":"7A4746"},{"b":"400000","o":"6B64B0"},{"b":"400000","o":"3FA04D"},{"b":"400000","o":"B1A6CB"},{"b":"3930C00000","o":"79D1"},{"b":"3930800000","o":"E89DD"}],"processInfo":{ "mongodbVersion" : "3.0.2", "gitVersion" : "6201872043ecbbc0a4cc169b5482dcf385fc464f", "uname" : { "sysname" : "Linux", "release" : "2.6.32-504.el6.x86_64", "version" : "#1 SMP Tue Sep 16 01:56:35 EDT 2014", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "528324F7E7422ECA899108CA2A12B5AAAA2A5569" }, { "b" : "7FFFD80FF000", "elfType" : 3, "buildId" : "08E42C6C3D2CD1E5D68A43B717C9EB3D310F2DF0" }, { "path" : "/lib64/libpthread.so.0", "elfType" : 3, "buildId" : "174BE4CAD6B9CDE9463A1ED403A8A45667042F1B" }, { "path" : "/usr/lib64/libssl.so.10", "elfType" : 3, "buildId" : "5D2E35CD6D2B0BE8DC9281A5ED5500ED9CAD0B79" }, { "path" : "/usr/lib64/libcrypto.so.10", "elfType" : 3, "buildId" : "49A1DD932D95CD1D6FAD062F53B7521F6396DD56" }, { "path" : "/lib64/librt.so.1", "elfType" : 3, "buildId" : "114449B5D483AC2FAEE7DD8CD72F086D2C9E7BC0" }, { "path" : "/lib64/libdl.so.2", "elfType" : 3, "buildId" : "3BD3452E91CB76304CCC9665D8742E55EF2EB903" }, { "path" : "/usr/lib64/libstdc++.so.6", "elfType" : 3, "buildId" : "743EA30ADF8E973D45AB59200C307F5ABC2749F6" }, { "path" : "/lib64/libm.so.6", "elfType" : 3, "buildId" : "BAA4D2FBB45B33028E58C6C4524D5F0D69C0FD60" }, { "path" : "/lib64/libgcc_s.so.1", "elfType" : 3, "buildId" : "7918143A0396110395C28377A1F202C769EFAC65" }, { "path" : "/lib64/libc.so.6", "elfType" : 3, "buildId" : "733AD3A438B5A695F7A63A77413F9B2C8C94E8E6" }, { "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "3BFA45BCE0E82E1D90D37A0CC8630F97F2003BF5" }, { "path" : "/lib64/libgssapi_krb5.so.2", "elfType" : 3, "buildId" : "AF7DB57AA4CA5C35AEEEFDB94CC1B97827C710FA" }, { "path" : "/lib64/libkrb5.so.3", "elfType" : 3, "buildId" : "07BD094ED077DA56CDD76B8F562586745BA01326" }, { "path" : "/lib64/libcom_err.so.2", "elfType" : 3, "buildId" : "6A22EDFF4D4F04A57573E3D1536B6B4963159CD5" }, { "path" : "/lib64/libk5crypto.so.3", "elfType" : 3, "buildId" : "54FF9CD35F9E7E253F66C458DC902307190E0F80" }, { "path" : "/lib64/libz.so.1", "elfType" : 3, "buildId" : "D053BB4FF0C2FC983842F81598813B9B931AD0D1" }, { "path" : "/lib64/libkrb5support.so.0", "elfType" : 3, "buildId" : "129AD60521E5EF66722CA7C3DA6FC854DA5A8CDB" }, { "path" : "/lib64/libkeyutils.so.1", "elfType" : 3, "buildId" : "3BCCABE75DC61BBA81AAE45D164E26EF4F9F55DB" }, { "path" : "/lib64/libresolv.so.2", "elfType" : 3, "buildId" : "D02CF15D0B3F2216AD2C54CA960F028BF3C5E4D0" }, { "path" : "/lib64/libselinux.so.1", "elfType" : 3, "buildId" : "2D0F26E648D9661ABD83ED8B4BBE8F2CFA50393B" } ] }}
 mongod(_ZN5mongo15printStackTraceERSo+0x29) [0xf68719]
 mongod(_ZN5mongo10logContextEPKc+0xE1) [0xf06c91]
 mongod(_ZN5mongo11msgassertedEiPKc+0xAF) [0xeeb1af]
 mongod(_ZN5mongo12IndexCatalog14dropAllIndexesEPNS_16OperationContextEb+0x729) [0x91b809]
 mongod(_ZN5mongo14CmdDropIndexes10wrappedRunEPNS_16OperationContextERKSsS4_PNS_8DatabaseERNS_7BSONObjERSsRNS_14BSONObjBuilderE+0x35D) [0x9501dd]
 mongod(_ZN5mongo14CmdDropIndexes3runEPNS_16OperationContextERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x11E) [0x9506de]
 mongod(_ZN5mongo12_execCommandEPNS_16OperationContextEPNS_7CommandERKSsRNS_7BSONObjEiRSsRNS_14BSONObjBuilderEb+0x34) [0x9d1e74]
 mongod(_ZN5mongo7Command11execCommandEPNS_16OperationContextEPS0_iPKcRNS_7BSONObjERNS_14BSONObjBuilderEb+0xC1D) [0x9d2dfd]
 mongod(_ZN5mongo12_runCommandsEPNS_16OperationContextEPKcRNS_7BSONObjERNS_11_BufBuilderINS_16TrivialAllocatorEEERNS_14BSONObjBuilderEbi+0x28B) [0x9d3b0b]
 mongod(_ZN5mongo8runQueryEPNS_16OperationContextERNS_7MessageERNS_12QueryMessageERKNS_15NamespaceStringERNS_5CurOpES3_+0x746) [0xba4746]
 mongod(_ZN5mongo16assembleResponseEPNS_16OperationContextERNS_7MessageERNS_10DbResponseERKNS_11HostAndPortE+0xB10) [0xab64b0]
 mongod(_ZN5mongo16MyMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortEPNS_9LastErrorE+0xDD) [0x7fa04d]
 mongod(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x34B) [0xf1a6cb]
 libpthread.so.0(+0x79D1) [0x3930c079d1]
 libc.so.6(clone+0x6D) [0x39308e89dd]
-----  END BACKTRACE  -----
2015-05-26T13:25:23.384Z I NETWORK  [conn118905] end connection 10.35.74.149:47997 (82 connections now open)

      This looks suspicious – one kill command, two background index builds that were running in parallel killed at once.

      2015-05-26T13:20:41.651Z I COMMAND  [conn118885] going to kill op: op: 409364948.0
2015-05-26T13:20:41.683Z I COMMAND  [conn117172] command document_store.$cmd command: createIndexes { createIndexes: "product_01", indexes: [ { key: { productId: -1.0, status: 1.0 }, name: "productId_-1_status_1", background: true } ] } keyUpdates:0 writeConflicts:0 numYields:96458 reslen:151 locks:{ Global: { acquireCount: { w: 96459 } }, Database: { acquireCount: { w: 96459, W: 2 }, acquireWaitCount: { w: 7, W: 2 }, timeAcquiringMicros: { w: 8560, W: 30588 } }, Collection: { acquireCount: { w: 96459 } } } 807136ms
2015-05-26T13:20:41.688Z I COMMAND  [conn118796] command document_store.$cmd command: createIndexes { createIndexes: "product_01", indexes: [ { key: { endDate: 1.0 }, name: "endDate_1", background: true } ] } keyUpdates:0 writeConflicts:0 numYields:80444 reslen:196 locks:{ Global: { acquireCount: { w: 80445 } }, Database: { acquireCount: { w: 80445, W: 2 }, acquireWaitCount: { w: 1, W: 2 }, timeAcquiringMicros: { w: 9682, W: 12576 } }, Collection: { acquireCount: { w: 80445 } } } 481786ms

        1. mongo-21.tar.gz
          3.66 MB
        2. mongo-20.tar.gz
          4.87 MB
        3. mongo-19.tar.gz
          921 kB
        4. getMongoData.log
          111 kB

            Assignee:
            milkie@mongodb.com Eric Milkie
            Reporter:
            eric.sommer@mongodb.com Eric Sommer
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: