[SERVER-19065] dropIndexes() produces "Assertion: 17348:cannot dropAllIndexes when index builds in progress" Created: 22/Jun/15  Updated: 04/Feb/16  Resolved: 22/Jun/15

Status: Closed
Project: Core Server
Component/s: Replication
Affects Version/s: 3.0.2
Fix Version/s: None

Type: Bug Priority: Major - P3
Reporter: Eric Sommer Assignee: Eric Milkie
Resolution: Duplicate Votes: 0
Labels: None
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Attachments: Text File getMongoData.log     File mongo-19.tar.gz     File mongo-20.tar.gz     File mongo-21.tar.gz    
Issue Links:
Duplicate
duplicates SERVER-17923 Creating/dropping multiple background... Closed
Related
Operating System: ALL
Steps To Reproduce:

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.

Participants:
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



 Comments   
Comment by Eric Milkie [ 22/Jun/15 ]

This is fixed by SERVER-17923, in which dropIndexes is no longer allowed while background index builds are still in progress.

Generated at Thu Feb 08 03:49:42 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.