[SERVER-25497] Fix sharded query path to handle shutdown of the mongos process Created: 08/Aug/16  Updated: 16/Oct/20  Resolved: 15/Oct/20

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: 3.4.0-rc0
Fix Version/s: 4.9.0

Type: Bug Priority: Major - P3
Reporter: Davenson Lombard Assignee: Ruoxin Xu
Resolution: Done Votes: 0
Labels: mongos-drain-mode-fallout, qexec-team, query-44-grooming
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Depends
Related
related to SERVER-33522 Possible to call TaskExecutor::signal... Closed
is related to SERVER-27460 RouterStageMerge::kill() can crash du... Closed
is related to SERVER-6496 provide a way to kill a sharded query... Closed
is related to SERVER-4274 mongos: support a graceful shutdown Closed
Backwards Compatibility: Fully Compatible
Operating System: ALL
Sprint: Sharding 2016-10-10, Query 2018-02-26, Query 2020-05-04, Query 2020-10-05, Query 2020-10-19
Participants:
Case:
Linked BF Score: 15

 Description   

The AsyncResultsMerger is the component of the new mongos find execution path introduced in version 3.2.0. It uses the TaskExecutor to run find and getMore commands against the shards. During shutdown of the mongos process, the TaskExecutor shutdown sequence occurs, during which mongos cursors may still exist but the TaskExecutor can no longer be used to run commands on remote nodes.

The AsyncResultsMerger does not behave correctly during TaskExecutor shutdown. This can cause mongos to crash during shutdown in one of several ways.

Original description

Hi all,

I found the following stack trace and I am not sure what is the root cause of this. It happened on all the mongos with a few minutes interval. It did occur after a signal 15 so I do not know if that is the reason.

2016-08-05T08:03:08.269Z I -        [conn798228] Invariant failure event.isValid() src/mongo/executor/thread_pool_task_executor.cpp 234
2016-08-05T08:03:08.269Z I -        [conn798228] 
 
***aborting after invariant() failure
 
 
2016-08-05T08:03:08.271Z F -        [conn799245] Got signal: 6 (Aborted).
 
 0xc5dca2 0xc5cbc9 0xc5d3d2 0x7f03252f2cb0 0x7f0324f5b035 0x7f0324f5e79b 0xbe245b 0xa13cb8 0xb8a68c 0xb81536 0xb8777a 0xba0ee7 0xb8e8fb 0x672115 0xc07715 0x7f03252eae9a 0x7f032501836d
----- BEGIN BACKTRACE -----
{"backtrace":[{"b":"400000","o":"85DCA2","s":"_ZN5mongo15printStackTraceERSo"},{"b":"400000","o":"85CBC9"},{"b":"400000","o":"85D3D2"},{"b":"7F03252E3000","o":"FCB0"},{"b":"7F0324F25000","o":"36035","s":"gsignal"},{"b":"7F0324F25000","o":"3979B","s":"abort"},{"b":"400000","o":"7E245B","s":"_ZN5mongo15invariantFailedEPKcS1_j"},{"b":"400000","o":"613CB8"},{"b":"400000","o":"78A68C","s":"_ZN5mongo16RouterStageMerge4killEv"},{"b":"400000","o":"781536","s":"_ZN5mongo24ClusterClientCursorGuardD1Ev"},{"b":"400000","o":"78777A","s":"_ZN5mongo11ClusterFind8runQueryEPNS_16OperationContextERKNS_14CanonicalQueryERKNS_21ReadPreferenceSettingEPSt6vectorINS_7BSONObjESaISA_EE"},{"b":"400000","o":"7A0EE7","s":"_ZN5mongo8Strategy7queryOpEPNS_16OperationContextERNS_7RequestE"},{"b":"400000","o":"78E8FB","s":"_ZN5mongo7Request7processEPNS_16OperationContextEi"},{"b":"400000","o":"272115","s":"_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortE"},{"b":"400000","o":"807715","s":"_ZN5mongo17PortMessageServer17handleIncomingMsgEPv"},{"b":"7F03252E3000","o":"7E9A"},{"b":"7F0324F25000","o":"F336D","s":"clone"}],"processInfo":{ "mongodbVersion" : "3.2.8", "gitVersion" : "ed70e33130c977bda0024c125b56d159573dbaf0", "compiledModules" : [], "uname" : { "sysname" : "Linux", "release" : "3.2.0-77-virtual", "version" : "#114-Ubuntu SMP Tue Mar 10 17:38:02 UTC 2015", "machine" : "x86_64" }, "somap" : [ { "elfType" : 2, "b" : "400000", "buildId" : "16C848A3171CB2CF2FDC800A602C9F785595A08F" }, { "b" : "7FFF0700B000", "elfType" : 3, "buildId" : "4CF95530ACFE32D062E1E8F7524D5E956AF54586" }, { "b" : "7F03261FA000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "05BB9627FE4CCFC087FC0A1E064098BAAAF0ABE2" }, { "b" : "7F0325E1E000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "88FFD2D95DF12BF9CA931AF6E50F42D83A98C3FE" }, { "b" : "7F0325C16000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "8C19981216B96C14A1C82A4C884D1FA7FECB7979" }, { "b" : "7F0325A12000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "68048F961CC6B636BC27B40DE0DD8B8632B10180" }, { "b" : "7F0325716000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "97900BE41183B1AB4E6322A8FE08D68315FED60A" }, { "b" : "7F0325500000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "ECF322A96E26633C5D10F18215170DD4395AF82C" }, { "b" : "7F03252E3000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "9E17F98B86F7723CA1DC42235AEAB33B86FCB89D" }, { "b" : "7F0324F25000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "FC161CFC250D850EB08A7B76BAD5D2022AAEBB10" }, { "b" : "7F0326458000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "B60D4C2FCB331CEC2764B936F83C0622676CF9ED" }, { "b" : "7F0324D0E000", "path" : "/lib/x86_64-linux-gnu/libz.so.1", "elfType" : 3, "buildId" : "F695ECFCF3918D5D34989398A14B7ECDD9F46CD0" } ] }}
 mongos(_ZN5mongo15printStackTraceERSo+0x32) [0xc5dca2]
 mongos(+0x85CBC9) [0xc5cbc9]
 mongos(+0x85D3D2) [0xc5d3d2]
 libpthread.so.0(+0xFCB0) [0x7f03252f2cb0]
 libc.so.6(gsignal+0x35) [0x7f0324f5b035]
 libc.so.6(abort+0x17B) [0x7f0324f5e79b]
 mongos(_ZN5mongo15invariantFailedEPKcS1_j+0xCB) [0xbe245b]
 mongos(+0x613CB8) [0xa13cb8]
 mongos(_ZN5mongo16RouterStageMerge4killEv+0x2C) [0xb8a68c]
 mongos(_ZN5mongo24ClusterClientCursorGuardD1Ev+0x46) [0xb81536]
 mongos(_ZN5mongo11ClusterFind8runQueryEPNS_16OperationContextERKNS_14CanonicalQueryERKNS_21ReadPreferenceSettingEPSt6vectorINS_7BSONObjESaISA_EE+0xCFA) [0xb8777a]
 mongos(_ZN5mongo8Strategy7queryOpEPNS_16OperationContextERNS_7RequestE+0x567) [0xba0ee7]
 mongos(_ZN5mongo7Request7processEPNS_16OperationContextEi+0x5CB) [0xb8e8fb]
 mongos(_ZN5mongo21ShardedMessageHandler7processERNS_7MessageEPNS_21AbstractMessagingPortE+0x65) [0x672115]
 mongos(_ZN5mongo17PortMessageServer17handleIncomingMsgEPv+0x325) [0xc07715]
 libpthread.so.0(+0x7E9A) [0x7f03252eae9a]
 libc.so.6(clone+0x6D) [0x7f032501836d]
-----  END BACKTRACE  -----



 Comments   
Comment by Githook User [ 15/Oct/20 ]

Author:

{'name': 'Ruoxin Xu', 'email': 'ruoxin.xu@mongodb.com', 'username': 'RuoxinXu'}

Message: SERVER-25497 Fix sharded query path to handle shutdown of the mongos process
Branch: master
https://github.com/mongodb/mongo/commit/4530bcb094d5017599699a3da074a061a493f2b1

Comment by Ian Boros [ 27/Feb/18 ]

Also! Note that there's another subtle bug with how the ARM deals with shutdown: When it checks for shutdown and returns an invalid event, the caller will likely free the ARM immediately. This is not safe because there may be outstanding callbacks, which, when run will try to access the ARM.

Both of the solutions we came up with above (changing the shutdown order and using futures) should solve this problem as well.

Comment by Ian Boros [ 27/Feb/18 ]

We looked into fixing this as part of the sharded kill project.

The fact that an event is double-signaled is a larger problem that's outside the scope of this ticket. I've filed a ticket about this particular problem here: SERVER-33522.

As far as fixing the problem with the ARM:

After more discussion with david.storch, we've agreed that doing what he suggests in the comment above could be too costly to performance on point-finds. We could add partition-locking to the ClusterCursorManager to mitigate this, but it could still affect performance.

Another way to fix this problem would be to change the order of shutdown so that the TaskExecutor shuts down after all client threads have terminated. However, we only join on client threads when running under ASAN, and even then, we do so with a timeout. Changing the mongos to join with all client threads would probably be a significant amount of work.

Yet another alternative would be to use "Events" which are separate from the TaskExecutor, and still work even when shutdown is happening. After talking with redbeard0531 in-person, it seems like "Futures" will provide exactly this. Therefore I think that modifying the ARM to use Futures rather than TaskExecutor Events should fix the problems around the ARM and shutdown. Since this work of "futurizing" the ARM is already planned, I think we should just wait until we have futures to work on this.

Comment by David Storch [ 19/Dec/16 ]

After further investigation by the MongoDB Query Team, we have decided to mitigate the problem by fixing the initially reported crash under related ticket SERVER-27460. Please watch SERVER-27460 for updates on this partial fix.

In order to fix the problem in a complete way, we would have to make the following changes:

  1. Prevent new mongos cursors from coming into being while the process is shutting down.
  2. Wait for all existing cursors to be cleaned up before proceeding with the rest of shutdown, including shutting down the TaskExecutor.

We already shut down the mongos cursor manager before shutting down the TaskExecutor and we already prevent registration of new cursors once the ClusterCursorManager begins to shut down. Therefore, in order to acheive #1, all we need to do is ensure that mongos cursors come into existence registered. This would prevent the creation of any new cursors once ClusterCursorManager::shutdown() begins. It is an easy code change to make, but could come with a performance cost. In fact, the implementation used to work this way, but was changed in this commit in order to improve performance.

One way to achieve #2 would be to mark all outstanding cursors as kill pending and wait for them to die before proceeding with shutdown. This is an unacceptable approach because it could delay shutdown for large amounts of time while the shards complete query execution work. Therefore, we need a way to preemptively kill an active mongos cursor by terminating any cursors which are in use on the shards. Allowing pinned cursors to be killed, SERVER-21710, is a prerequisite for this work. Building a cross-shard preemptive mongos cursor-killing mechanism for shutdown would bring us a long way towards SERVER-6496, the ability to quickly terminate a sharded query on all participating nodes.

The complexity of these changes makes it unlikely that we will deliver the complete fix in 3.2 or 3.4, which is why we have chosen to work on the smaller, mitigating fix in SERVER-27460.

CC schwerin.

Comment by David Storch [ 28/Oct/16 ]

Our testing has revealed a similar race which can cause mongos to crash during shutdown with the following invariant failure:

[js_test:views_all_commands] 2016-08-28T18:23:49.637+0000 s20765| 2016-08-28T18:23:49.636+0000 I CONTROL  [signalProcessingThread] got signal 15 (Terminated), will terminate after current cmd ends
[js_test:views_all_commands] 2016-08-28T18:23:49.640+0000 s20765| 2016-08-28T18:23:49.639+0000 I -        [ClusterCursorCleanupJob] Invariant failure !eventState->isSignaledFlag src/mongo/executor/thread_pool_task_executor.cpp 433
[js_test:views_all_commands] 2016-08-28T18:23:49.640+0000 s20765| 2016-08-28T18:23:49.639+0000 I -        [ClusterCursorCleanupJob]
[js_test:views_all_commands] 2016-08-28T18:23:49.640+0000 s20765|
[js_test:views_all_commands] 2016-08-28T18:23:49.640+0000 s20765| ***aborting after invariant() failure
[js_test:views_all_commands] 2016-08-28T18:23:49.640+0000 s20765|
[js_test:views_all_commands] 2016-08-28T18:23:49.640+0000 s20765|
[js_test:views_all_commands] 2016-08-28T18:23:49.643+0000 s20765| 2016-08-28T18:23:49.643+0000 F -        [ClusterCursorCleanupJob] Got signal: 6 (Aborted).
[js_test:views_all_commands] 2016-08-28T18:23:49.643+0000 s20765|
[js_test:views_all_commands] 2016-08-28T18:23:49.643+0000 s20765|  0x55e8678048d1 0x55e86905b0b3 0x55e869059ca3 0x7fee30a383d0 0x7fee3047d418 0x7fee3047f01a 0x55e868e68bf1 0x55e8687cd021 0x55e8687d088e 0x55e868d0e07b 0x55e868d3f724 0x55e868d1d7ed 0x55e868d19a54 0x55e868e789ce 0x7fee30cfcc80 0x7fee30a2e6fa 0x7fee3054eb5d
[js_test:views_all_commands] 2016-08-28T18:23:49.644+0000 s20765| ----- BEGIN BACKTRACE -----
[js_test:views_all_commands] 2016-08-28T18:23:49.654+0000 s20765| {"backtrace":[{"b":"55E866F14000","o":"8F08D1","s":"__interceptor_backtrace"},{"b":"55E866F14000","o":"21470B3","s":"_ZN5mongo15printStackTraceERSo"},{"b":"55E866F14000","o":"2145CA3"},{"b":"7FEE30A27000","o":"113D0"},{"b":"7FEE30448000","o":"35418","s":"gsignal"},{"b":"7FEE30448000","o":"3701A","s":"abort"},{"b":"55E866F14000","o":"1F54BF1","s":"_ZN5mongo15invariantFailedEPKcS1_j"},{"b":"55E866F14000","o":"18B9021","s":"_ZN5mongo8executor22ThreadPoolTaskExecutor18signalEvent_inlockERKNS0_12TaskExecutor11EventHandleESt11unique_lockISt5mutexE"},{"b":"55E866F14000","o":"18BC88E","s":"_ZN5mongo8executor22ThreadPoolTaskExecutor11signalEventERKNS0_12TaskExecutor11EventHandleE"},{"b":"55E866F14000","o":"1DFA07B","s":"_ZN5mongo18AsyncResultsMerger4killEv"},{"b":"55E866F14000","o":"1E2B724","s":"_ZN5mongo16RouterStageMerge4killEv"},{"b":"55E866F14000","o":"1E097ED","s":"_ZN5mongo20ClusterCursorManager17reapZombieCursorsEv"},{"b":"55E866F14000","o":"1E05A54","s":"_ZN5mongo23ClusterCursorCleanupJob3runEv"},{"b":"55E866F14000","o":"1F649CE","s":"_ZN5mongo13BackgroundJob7jobBodyEv"},{"b":"7FEE30C44000","o":"B8C80"},{"b":"7FEE30A27000","o":"76FA"},{"b":"7FEE30448000","o":"106B5D","s":"clone"}],"processInfo":{ "mongodbVersion" : "3.3.11-240-g38e2879", "gitVersion" : "38e287962414f62323abb93a67c5561a0d3175b3", "compiledModules" : [ "enterprise" ], "uname" : { "sysname" : "Linux", "release" : "4.4.0-21-generic", "version" : "#37-Ubuntu SMP Mon Apr 18 18:33:37 UTC 2016", "machine" : "x86_64" }, "somap" : [ { "b" : "55E866F14000", "elfType" : 3, "buildId" : "AF5809D4F4DD2E8FDE8B073A4CA74AF0BC677ACB" }, { "b" : "7FFE3EFFA000", "elfType" : 3, "buildId" : "19C37034D41570D4CBC5A74A3874BC0C32CBCA5B" }, { "b" : "7FEE32413000", "path" : "/usr/lib/x86_64-linux-gnu/libldap_r-2.4.so.2", "elfType" : 3, "buildId" : "ADF6F41F223D42193165FA0C55871F02D915FB19" }, { "b" : "7FEE32204000", "path" : "/usr/lib/x86_64-linux-gnu/liblber-2.4.so.2", "elfType" : 3, "buildId" : "6B9F4061A1D44813A54DA4DBB0088F529D8D78EA" }, { "b" : "7FEE31FE9000", "path" : "/usr/lib/x86_64-linux-gnu/libsasl2.so.2", "elfType" : 3, "buildId" : "96BCC7EB28D81B1469EED6F24FC083CBD58577BC" }, { "b" : "7FEE31D9F000", "path" : "/usr/lib/x86_64-linux-gnu/libgssapi_krb5.so.2", "elfType" : 3, "buildId" : "54EB3E674DB58B5BAEF009CBC4AB02CCF5386CA7" }, { "b" : "7FEE31A96000", "path" : "/lib/x86_64-linux-gnu/libm.so.6", "elfType" : 3, "buildId" : "5C4078C04888A418F3DB0868702ECFDB35B3AD8B" }, { "b" : "7FEE3182D000", "path" : "/lib/x86_64-linux-gnu/libssl.so.1.0.0", "elfType" : 3, "buildId" : "CC601E6C47AE87C33EE639D61CE08220A98A263F" }, { "b" : "7FEE313D2000", "path" : "/lib/x86_64-linux-gnu/libcrypto.so.1.0.0", "elfType" : 3, "buildId" : "4BE6A02E9E96DDC6E8D22F73749388923AE5652B" }, { "b" : "7FEE311CA000", "path" : "/lib/x86_64-linux-gnu/librt.so.1", "elfType" : 3, "buildId" : "A779DBCB3A477DC0C8D09B60FAC7335D396C19DF" }, { "b" : "7FEE30FC6000", "path" : "/lib/x86_64-linux-gnu/libdl.so.2", "elfType" : 3, "buildId" : "A2ADF3615338D49C702C41EB83A99AB743D2B574" }, { "b" : "7FEE30C44000", "path" : "/usr/lib/x86_64-linux-gnu/libstdc++.so.6", "elfType" : 3, "buildId" : "FCBB11A30679DE016410A0CDB6CCF0C2D11FD093" }, { "b" : "7FEE30A27000", "path" : "/lib/x86_64-linux-gnu/libpthread.so.0", "elfType" : 3, "buildId" : "B77847CC9CACBCA3B5753D0D25A32E5795AFE75B" }, { "b" : "7FEE30811000", "path" : "/lib/x86_64-linux-gnu/libgcc_s.so.1", "elfType" : 3, "buildId" : "68220AE2C65D65C1B6AAA12FA6765A6EC2F5F434" }, { "b" : "7FEE30448000", "path" : "/lib/x86_64-linux-gnu/libc.so.6", "elfType" : 3, "buildId" : "369DE0E1D833CAA693AF17F17C83BA937F0A4DAD" }, { "b" : "7FEE3022D000", "path" : "/lib/x86_64-linux-gnu/libresolv.so.2", "elfType" : 3, "buildId" : "81EF82040E9877E63ADCA93B365F52A4BB831EE1" }, { "b" : "7FEE2FFEC000", "path" : "/usr/lib/x86_64-linux-gnu/libgssapi.so.3", "elfType" : 3, "buildId" : "40315538B8F467FA9379C26806C2C2E5F75DF62A" }, { "b" : "7FEE2FCBB000", "path" : "/usr/lib/x86_64-linux-gnu/libgnutls.so.30", "elfType" : 3, "buildId" : "424060547E784D4275171E91AA31276D4A43D1FF" }, { "b" : "7FEE2F9E9000", "path" : "/usr/lib/x86_64-linux-gnu/libkrb5.so.3", "elfType" : 3, "buildId" : "D60D5A759577E5C477314520EF3D13BDBAED5111" }, { "b" : "7FEE2F7BA000", "path" : "/usr/lib/x86_64-linux-gnu/libk5crypto.so.3", "elfType" : 3, "buildId" : "09FA442048F4AA6E701F0B504FEB688F09618E30" }, { "b" : "7FEE2F5B6000", "path" : "/lib/x86_64-linux-gnu/libcom_err.so.2", "elfType" : 3, "buildId" : "1E16CB57F699E215A2A8D4EFEF90883BC749B12D" }, { "b" : "7FEE2F3AB000", "path" : "/usr/lib/x86_64-linux-gnu/libkrb5support.so.0", "elfType" : 3, "buildId" : "00DFFD025B1AEBFD619FAE9DE01610BA6F209367" }, { "b" : "7FEE32664000", "path" : "/lib64/ld-linux-x86-64.so.2", "elfType" : 3, "buildId" : "EDFA6D46E00CA97F349FDD3333D88493D442932C" }, { "b" : "7FEE2F1A2000", "path" : "/usr/lib/x86_64-linux-gnu/libheimntlm.so.0", "elfType" : 3, "buildId" : "D72147C9E81DC821D2C5CA3A93757EE00DAC67EA" }, { "b" : "7FEE2EF18000", "path" : "/usr/lib/x86_64-linux-gnu/libkrb5.so.26", "elfType" : 3, "buildId" : "889221E5B7DFAA3D74CD8D55DAEF89DD962DAEB7" }, { "b" : "7FEE2EC76000", "path" : "/usr/lib/x86_64-linux-gnu/libasn1.so.8", "elfType" : 3, "buildId" : "B7A0E46FB5107A9566AB0D448C865DB7BB1390BF" }, { "b" : "7FEE2EA43000", "path" : "/usr/lib/x86_64-linux-gnu/libhcrypto.so.4", "elfType" : 3, "buildId" : "54027CA597C9AFC9D32A3D677857E5C8512C9FBF" }, { "b" : "7FEE2E82D000", "path" : "/usr/lib/x86_64-linux-gnu/libroken.so.18", "elfType" : 3, "buildId" : "AE98B3C2FEC7AEDB3064E03BD8C1883FD12898D1" }, { "b" : "7FEE2E613000", "path" : "/lib/x86_64-linux-gnu/libz.so.1", "elfType" : 3, "buildId" : "340B7B463F981B8A0FB3451751F881DF1B0C2F74" }, { "b" : "7FEE2E3AE000", "path" : "/usr/lib/x86_64-linux-gnu/libp11-kit.so.0", "elfType" : 3, "buildId" : "2F170DCF36786FE91EB82D547A42B2DEE2E9DF81" }, { "b" : "7FEE2E17B000", "path" : "/usr/lib/x86_64-linux-gnu/libidn.so.11", "elfType" : 3, "buildId" : "F3945D210B52CC973C619CCD08C4394BBC33E07F" }, { "b" : "7FEE2DF68000", "path" : "/usr/lib/x86_64-linux-gnu/libtasn1.so.6", "elfType" : 3, "buildId" : "F5B37E248C55FD582ECD9B0240F96E8458F8E6F0" }, { "b" : "7FEE2DD32000", "path" : "/usr/lib/x86_64-linux-gnu/libnettle.so.6", "elfType" : 3, "buildId" : "74A0B167DA794B5E8B6DAA64367F6385DECF9A6C" }, { "b" : "7FEE2DAFF000", "path" : "/usr/lib/x86_64-linux-gnu/libhogweed.so.4", "elfType" : 3, "buildId" : "25494D1AE45F2D8F1770895BB899771547668E20" }, { "b" : "7FEE2D87F000", "path" : "/usr/lib/x86_64-linux-gnu/libgmp.so.10", "elfType" : 3, "buildId" : "7B3533D5998D20EE1A1BE3F87789B69041E7F620" }, { "b" : "7FEE2D67B000", "path" : "/lib/x86_64-linux-gnu/libkeyutils.so.1", "elfType" : 3, "buildId" : "3364D4BF2113C4E8D17EF533867ECC99A53413D6" }, { "b" : "7FEE2D452000", "path" : "/usr/lib/x86_64-linux-gnu/libwind.so.0", "elfType" : 3, "buildId" : "FEA2A08A986C1C954F7DED5A27616F0B4B18C6A2" }, { "b" : "7FEE2D243000", "path" : "/usr/lib/x86_64-linux-gnu/libheimbase.so.1", "elfType" : 3, "buildId" : "E5BC16E04FC04459D5AB8F045B5F7C7838B86027" }, { "b" : "7FEE2CFF8000", "path" : "/usr/lib/x86_64-linux-gnu/libhx509.so.5", "elfType" : 3, "buildId" : "6B6EF07C8D0FA1CE7CCEE58043BDB6C347F25544" }, { "b" : "7FEE2CD23000", "path" : "/usr/lib/x86_64-linux-gnu/libsqlite3.so.0", "elfType" : 3, "buildId" : "D9782BA023CAEC26B15D8676E3A5D07B55E121EF" }, { "b" : "7FEE2CAEB000", "path" : "/lib/x86_64-linux-gnu/libcrypt.so.1", "elfType" : 3, "buildId" : "1B46E1518CBF3AB34A3FE34E0AFE928AD689BD78" }, { "b" : "7FEE2C8E3000", "path" : "/usr/lib/x86_64-linux-gnu/libffi.so.6", "elfType" : 3, "buildId" : "9D9C958F1F4894AFEF6AECD90D1C430EA29AC34F" } ] }}
[js_test:views_all_commands] 2016-08-28T18:23:49.654+0000 s20765|  mongos(__interceptor_backtrace+0x41) [0x55e8678048d1]
[js_test:views_all_commands] 2016-08-28T18:23:49.654+0000 s20765|  mongos(_ZN5mongo15printStackTraceERSo+0x113) [0x55e86905b0b3]
[js_test:views_all_commands] 2016-08-28T18:23:49.654+0000 s20765|  mongos(+0x2145CA3) [0x55e869059ca3]
[js_test:views_all_commands] 2016-08-28T18:23:49.654+0000 s20765|  libpthread.so.0(+0x113D0) [0x7fee30a383d0]
[js_test:views_all_commands] 2016-08-28T18:23:49.654+0000 s20765|  libc.so.6(gsignal+0x38) [0x7fee3047d418]
[js_test:views_all_commands] 2016-08-28T18:23:49.655+0000 s20765|  libc.so.6(abort+0x16A) [0x7fee3047f01a]
[js_test:views_all_commands] 2016-08-28T18:23:49.655+0000 s20765|  mongos(_ZN5mongo15invariantFailedEPKcS1_j+0xB61) [0x55e868e68bf1]
[js_test:views_all_commands] 2016-08-28T18:23:49.655+0000 s20765|  mongos(_ZN5mongo8executor22ThreadPoolTaskExecutor18signalEvent_inlockERKNS0_12TaskExecutor11EventHandleESt11unique_lockISt5mutexE+0x541) [0x55e8687cd021]
[js_test:views_all_commands] 2016-08-28T18:23:49.655+0000 s20765|  mongos(_ZN5mongo8executor22ThreadPoolTaskExecutor11signalEventERKNS0_12TaskExecutor11EventHandleE+0xFE) [0x55e8687d088e]
[js_test:views_all_commands] 2016-08-28T18:23:49.656+0000 s20765|  mongos(_ZN5mongo18AsyncResultsMerger4killEv+0xC6B) [0x55e868d0e07b]
[js_test:views_all_commands] 2016-08-28T18:23:49.656+0000 s20765|  mongos(_ZN5mongo16RouterStageMerge4killEv+0x94) [0x55e868d3f724]
[js_test:views_all_commands] 2016-08-28T18:23:49.656+0000 s20765|  mongos(_ZN5mongo20ClusterCursorManager17reapZombieCursorsEv+0xC0D) [0x55e868d1d7ed]
[js_test:views_all_commands] 2016-08-28T18:23:49.656+0000 s20765|  mongos(_ZN5mongo23ClusterCursorCleanupJob3runEv+0x1A4) [0x55e868d19a54]
[js_test:views_all_commands] 2016-08-28T18:23:49.656+0000 s20765|  mongos(_ZN5mongo13BackgroundJob7jobBodyEv+0x3BE) [0x55e868e789ce]
[js_test:views_all_commands] 2016-08-28T18:23:49.656+0000 s20765|  libstdc++.so.6(+0xB8C80) [0x7fee30cfcc80]
[js_test:views_all_commands] 2016-08-28T18:23:49.656+0000 s20765|  libpthread.so.0(+0x76FA) [0x7fee30a2e6fa]
[js_test:views_all_commands] 2016-08-28T18:23:49.657+0000 s20765|  libc.so.6(clone+0x6D) [0x7fee3054eb5d]
[js_test:views_all_commands] 2016-08-28T18:23:49.657+0000 s20765| -----  END BACKTRACE  -----

This crash occurs due to the following sequence of events:

  1. The ClusterCursorCleanupJob kills a cursor that is pending for deletion. During cursor killing, it asks the ThreadPoolTaskExecutor for an event which will be signaled when it is safe to destroy the cursor.
  2. This happens at a time when the mongos process, and hence the ThreadPoolTaskExecutor, is not shutting down. This means we skip this if-block and hold onto the event as AsyncResultsMerger::_killCursorsScheduledEvent.
  3. Before we get a chance to signal the event, but after it has been successfully created, the mongos process begins its shutdown sequence. As part of this process, we call ThreadPoolTaskExecutor::join(), which signals any unsignaled events.
  4. The killing thread is unaware of this, and happily proceeds to signal the event again. Oops!
Comment by David Storch [ 07/Oct/16 ]

The cause behind the invariant failure described by schwerin is not yet clear to me, though I can see from code inspection how the originally reported invariant failure can occur. The original invariant failure happens in RouterStageMerge::kill(), which asks the AsyncResultsMerger for an event and then waits on it:

https://github.com/mongodb/mongo/blob/r3.4.0-rc0/src/mongo/s/query/router_stage_merge.cpp#L59-L60

If mongos shutdown is in progress, however, we will have returned an invalid Event:

https://github.com/mongodb/mongo/blob/r3.4.0-rc0/src/mongo/s/query/async_results_merger.cpp#L635

We trip the invariant when attempting to wait on this invalid Event. The bug should only manifest when a mongos cursor gets killed (or kills itself) concurrently with mongos shutdown. The stack trace provided by Andy seems to be a separate bug, probably with a very similar root cause.

Comment by Andy Schwerin [ 07/Oct/16 ]

The stack trace from the repro instructions is different from the one in the original bug report. In the repro, the invalid event is returned from AsyncResultsMerger::nextEvent, and in the original report it comes from AsyncResultsMerger::kill. Maybe two similar bugs, maybe one root cause. Here's the stack trace from the repro, as of 3.4.0-rc0:

  * frame #0: 0x0000555556c1f812 mongos`mongo::executor::ThreadPoolTaskExecutor::waitForEvent(this=0x00007ffff7f1d980, event=0x00007ffff7eb44a0) + 32 at thread_pool_task_executor.cpp:234
    frame #1: 0x0000555556da47c7 mongos`mongo::RouterStageMerge::next(this=0x00007ffff1634220) + 237 at router_stage_merge.cpp:52
    frame #2: 0x0000555556d8fc0b mongos`mongo::ClusterClientCursorImpl::next(this=0x00007ffff185b6a0) + 281 at cluster_client_cursor_impl.cpp:84
    frame #3: 0x0000555556d9f8a0 mongos`mongo::(anonymous namespace)::runQueryWithoutRetrying(txn=0x00007fffdd73d4a0, query=0x00007ffff1601f80, readPref=0x00007ffff7eb4eb0, chunkManager=0x0000000000000000, primary=shared_ptr<mongo::Shard> @ 0x00007ffff7eb4ab0, results=0x00007ffff7eb4ce0, viewDefinition=0x00007ffff7eb4c90) + 2597 at cluster_find.cpp:236
    frame #4: 0x0000555556da0466 mongos`mongo::ClusterFind::runQuery(txn=0x00007fffdd73d4a0, query=0x00007ffff1601f80, readPref=0x00007ffff7eb4eb0, results=0x00007ffff7eb4ce0, viewDefinition=0x00007ffff7eb4c90) + 946 at cluster_find.cpp:333
    frame #5: 0x0000555556d23fa4 mongos`mongo::(anonymous namespace)::ClusterFindCmd::run(this=0x0000555558170860, txn=0x00007fffdd73d4a0, dbname="PP???\x7f"..., cmdObj=0x00007ffff7eb53d0, options=0, errmsg="\xb0P???\x7f", result=0x00007ffff7eb54c0) const + 992 at cluster_find_cmd.cpp:195
    frame #6: 0x0000555556db0ffe mongos`mongo::Command::execCommandClient(txn=0x00007fffdd73d4a0, c=0x0000555558170860, queryOptions=0, ns="test.$cmd", cmdObj=0x00007ffff7eb53d0, result=0x00007ffff7eb54c0) + 1190 at s_only.cpp:141
    frame #7: 0x0000555556d6c9a5 mongos`mongo::(anonymous namespace)::runAgainstRegistered(txn=0x00007fffdd73d4a0, ns="test.$cmd", jsobj=0x00007ffff7eb53d0, anObjBuilder=0x00007ffff7eb54c0, queryOptions=0) + 660 at strategy.cpp:111
    frame #8: 0x0000555556d6e5af mongos`mongo::Strategy::clientCommandOp(txn=0x00007fffdd73d4a0, request=0x00007ffff7eb5910) + 1995 at strategy.cpp:324
    frame #9: 0x0000555556d69579 mongos`mongo::Request::process(this=0x00007ffff7eb5910, txn=0x00007fffdd73d4a0, attempt=0) + 849 at request.cpp:110
    frame #10: 0x0000555556615c72 mongos`mongo::ServiceEntryPointMongos::_sessionLoop(this=0x00007ffff118c8a0, session=0x00007fffef95baa0) + 488 at service_entry_point_mongos.cpp:114
    frame #11: 0x00005555566159f0 mongos`operator(__closure=0x00007fffef95bb28, session=0x00007fffef95baa0) + 38 at service_entry_point_mongos.cpp:78
    frame #12: 0x0000555556616521 mongos`std::_Function_handler<void(mongo::transport::Session*), mongo::ServiceEntryPointMongos::startSession(mongo::transport::Session&&)::<lambda(mongo::transport::Session*)> >::_M_invoke(__functor=0x00007fffef95bb28, __args#0=0x00007ffff7eb5b60) + 55 at functional:1871
    frame #13: 0x0000555556e0fc79 mongos`std::function<void (mongo::transport::Session*)>::operator(this=0x00007fffef95bb28, __args#0=0x00007fffef95baa0)(mongo::transport::Session*) const + 73 at functional:2267
    frame #14: 0x0000555556e0ebed mongos`mongo::(anonymous namespace)::runFunc(ptr=0x00007fffef95baa0) + 399 at service_entry_point_utils.cpp:74
    frame #15: 0x00007ffff5fa26fa libpthread.so.0`start_thread + 202
    frame #16: 0x00007ffff5cd8b5d libc.so.6`__clone + 109 at clone.S:109

Comment by Andy Schwerin [ 07/Oct/16 ]

This appears to be a race between the AsyncResultsMerger's execution of nextEvent() and shutting down the task executor, causing nextEvent() to return Status::OK() with an invalid event. This causes the RouterStageMerge processor to call wait on an invalid event, violating the invariant.

Assigning to query team for analysis and triage. I'm pretty sure this only happens during mongos shutdown.

Generated at Thu Feb 08 04:09:21 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.