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

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

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major - P3
    • Resolution: Duplicate
    • Affects Version/s: 3.0.2
    • Fix Version/s: None
    • Component/s: Replication
    • Labels:
      None
    • Operating System:
      ALL
    • Steps To Reproduce:
      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.
    • Linked BF Score:
      0

      Description

      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
      

        Attachments

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

          Issue Links

            Activity

              People

              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved: