[SERVER-47038] Some RangeDeletion unit tests don't correctly wait for threads to join Created: 23/Mar/20  Updated: 29/Oct/23  Resolved: 01/Apr/20

Status: Closed
Project: Core Server
Component/s: Sharding
Affects Version/s: None
Fix Version/s: 4.4.0-rc0, 4.7.0

Type: Bug Priority: Major - P3
Reporter: Kevin Pulo Assignee: Alexander Taskov (Inactive)
Resolution: Fixed Votes: 0
Labels: sharding-4.4-stabilization
Remaining Estimate: Not Specified
Time Spent: Not Specified
Original Estimate: Not Specified

Issue Links:
Backports
Depends
Backwards Compatibility: Fully Compatible
Operating System: ALL
Backport Requested:
v4.4
Sprint: Sharding 2020-04-06
Participants:
Linked BF Score: 45

 Description   

Example bad run:

  • Collection uuid for RemoveDocumentsInRangeRetriesOnWriteConflictException: 5b4e4129-7dd5-490a-ac14-569f3ea40022
    • Note that the range-deleter thread doesn't start using it until after test tearDown (and in fact the next test has started up), resulting in a segfault.
  • Collection uuid for RemoveDocumentsInRangeRetriesOnUnexpectedError: 16428141-f2ea-4b37-b23d-955dee4bacd2
    • Even though the process is crashing from the above segfault, this collection uuid is also used by the range-deleter after this test has started to tearDown.

| 2020-03-10T15:45:35.123Z I  -        23059   [main] "\t going to run test: {tc_name}{runTimes_str}","attr":{"tc_name":"RemoveDocumentsInRangeRetriesOnWriteConflictException","runTimes_str":""}
| 2020-03-10T15:45:35.124Z I  -        23051   [main] "Created temporary directory: {path}","attr":{"path":"/data/mci/e025ac17253498310f0dfc09f5e71b64/tmp/service_context_d_test_fixture-6bd8-6997-bd73-2694"}
| 2020-03-10T15:45:35.125Z I  REPL     21531   [main] "Initialized the rollback ID to {rbid}","attr":{"rbid":100}
| 2020-03-10T15:45:35.125Z W  ASIO     22601   [main] "No TransportLayer configured during NetworkInterface startup"
| 2020-03-10T15:45:35.150Z I  REPL     21250   [main] "******"
| 2020-03-10T15:45:35.155Z I  REPL     21251   [main] "creating replication oplog of size: {size}MB...","attr":{"size":0}
| 2020-03-10T15:45:35.155Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"local.oplog.rs","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"9f283425-670f-486c-b42a-af321726af6e"}},"options":{"capped":true,"size":512000,"autoIndexId":false}}
| 2020-03-10T15:45:35.156Z I  REPL     21252   [main] "******"
| 2020-03-10T15:45:35.160Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"foo.bar","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"5b4e4129-7dd5-490a-ac14-569f3ea40022"}},"options":{}}
| 2020-03-10T15:45:35.160Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"foo.bar"}
| 2020-03-10T15:45:35.161Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"config.rangeDeletions","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"a74dd54e-617d-4bc8-be5f-924e87fbfa32"}},"options":{}}
| 2020-03-10T15:45:35.161Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"config.rangeDeletions"}
| 2020-03-10T15:45:35.175Z I  STORAGE  20320   [range-deleter] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"admin.system.version","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"d2e5b9a7-b275-4e64-957e-9b087f62d563"}},"options":{}}
| 2020-03-10T15:45:35.175Z I  INDEX    20345   [range-deleter] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"admin.system.version"}
| 2020-03-10T15:45:35.176Z I  COMMAND  518070  [main] "CMD: drop {collectionName}","attr":{"collectionName":"foo.bar"}
| 2020-03-10T15:45:35.177Z I  STORAGE  20315   [main] "dropCollection: {nss} ({uuid}) - renaming to drop-pending collection: {dpns} with drop optime {dropOpTime}","attr":{"nss":"foo.bar","uuid":{"uuid":{"$uuid":"5b4e4129-7dd5-490a-ac14-569f3ea40022"}},"dpns":"foo.system.drop.1583855135i9t0.bar","dropOpTime":{"ts":{"$timestamp":{"t":1583855135,"i":9}},"t":0}}
| 2020-03-10T15:45:35.177Z I  STORAGE  20319   [main] "renameCollection: renaming collection {collToRename_uuid} from {fromNss} to {toNss}","attr":{"collToRename_uuid":{"uuid":{"$uuid":"5b4e4129-7dd5-490a-ac14-569f3ea40022"}},"fromNss":"foo.bar","toNss":"foo.system.drop.1583855135i9t0.bar"}
| 2020-03-10T15:45:35.182Z I  ASIO     22582   [CollectionRangeDeleter-TaskExecutor] "Killing all outstanding egress activity."
| 2020-03-10T15:45:35.182Z I  ASIO     22582   [main] "Killing all outstanding egress activity."
| 2020-03-10T15:45:35.184Z I  STORAGE  20282   [main] "Deregistering all the collections"
| 2020-03-10T15:45:35.184Z I  -        23059   [main] "\t going to run test: {tc_name}{runTimes_str}","attr":{"tc_name":"RemoveDocumentsInRangeRetriesOnUnexpectedError","runTimes_str":""}
| 2020-03-10T15:45:35.186Z I  -        23051   [main] "Created temporary directory: {path}","attr":{"path":"/data/mci/e025ac17253498310f0dfc09f5e71b64/tmp/service_context_d_test_fixture-8b36-c411-34ef-917d"}
| 2020-03-10T15:45:35.186Z I  REPL     21531   [main] "Initialized the rollback ID to {rbid}","attr":{"rbid":100}
| 2020-03-10T15:45:35.186Z W  ASIO     22601   [main] "No TransportLayer configured during NetworkInterface startup"
| 2020-03-10T15:45:35.221Z I  REPL     21250   [main] "******"
| 2020-03-10T15:45:35.221Z I  REPL     21251   [main] "creating replication oplog of size: {size}MB...","attr":{"size":0}
| 2020-03-10T15:45:35.222Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"local.oplog.rs","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"eead8a99-663b-4e1d-905b-4ea2d975d930"}},"options":{"capped":true,"size":512000,"autoIndexId":false}}
| 2020-03-10T15:45:35.222Z I  REPL     21252   [main] "******"
| 2020-03-10T15:45:35.222Z I  MIGRATION 22024   [range-deleter] "Filtering metadata for namespace in deletion task {deletionTask} {collectionStatus}, forcing a refresh of {deletionTask_getNss}","attr":{"deletionTask":{"_id":{"$uuid":"07e493d1-3c1e-471f-a85e-5d53a1c6916d"},"nss":"foo.bar","collectionUuid":{"$uuid":"5b4e4129-7dd5-490a-ac14-569f3ea40022"},"donorShardId":"donor","range":{"min":{"_id":0},"max":{"_id":10}},"whenToClean":"delayed"},"collectionStatus":"is not known","deletionTask_getNss":"foo.bar","migrationId":{"uuid":{"$uuid":"07e493d1-3c1e-471f-a85e-5d53a1c6916d"}}}
{"t":{"$date":"2020-03-10T15:45:35.222Z"},"s":"F", "c":"-",       "id":0,"ctx":"range-deleter","msg":"{}","attr":{"message":"Invalid access at address: 0x68"}}
{"t":{"$date":"2020-03-10T15:45:35.222Z"},"s":"F", "c":"-",       "id":0,"ctx":"range-deleter","msg":"{}","attr":{"message":"Got signal: 11 (Segmentation fault)."}}
| 2020-03-10T15:45:35.223Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"foo.bar","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"16428141-f2ea-4b37-b23d-955dee4bacd2"}},"options":{}}
| 2020-03-10T15:45:35.223Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"foo.bar"}
| 2020-03-10T15:45:35.224Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"config.rangeDeletions","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"73af9bcf-508d-475a-aa99-d3dc10f79632"}},"options":{}}
| 2020-03-10T15:45:35.224Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"config.rangeDeletions"}
| 2020-03-10T15:45:35.229Z I  STORAGE  20320   [range-deleter] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"admin.system.version","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"ec57741c-61b4-4734-83dc-f76b9dd8ffac"}},"options":{}}
| 2020-03-10T15:45:35.239Z I  INDEX    20345   [range-deleter] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"admin.system.version"}
| 2020-03-10T15:45:35.241Z I  COMMAND  518070  [main] "CMD: drop {collectionName}","attr":{"collectionName":"foo.bar"}
| 2020-03-10T15:45:35.241Z I  STORAGE  20315   [main] "dropCollection: {nss} ({uuid}) - renaming to drop-pending collection: {dpns} with drop optime {dropOpTime}","attr":{"nss":"foo.bar","uuid":{"uuid":{"$uuid":"16428141-f2ea-4b37-b23d-955dee4bacd2"}},"dpns":"foo.system.drop.1583855135i9t0.bar","dropOpTime":{"ts":{"$timestamp":{"t":1583855135,"i":9}},"t":0}}
| 2020-03-10T15:45:35.241Z I  STORAGE  20319   [main] "renameCollection: renaming collection {collToRename_uuid} from {fromNss} to {toNss}","attr":{"collToRename_uuid":{"uuid":{"$uuid":"16428141-f2ea-4b37-b23d-955dee4bacd2"}},"fromNss":"foo.bar","toNss":"foo.system.drop.1583855135i9t0.bar"}
| 2020-03-10T15:45:35.247Z I  MIGRATION 22026   [range-deleter] "Submitting range deletion task {deletionTask}","attr":{"deletionTask":{"_id":{"$uuid":"bdc0e685-9538-4179-845d-f3f499343a05"},"nss":"foo.bar","collectionUuid":{"$uuid":"16428141-f2ea-4b37-b23d-955dee4bacd2"},"donorShardId":"donor","range":{"min":{"_id":0},"max":{"_id":10}},"whenToClean":"delayed"},"migrationId":{"uuid":{"$uuid":"bdc0e685-9538-4179-845d-f3f499343a05"}}}
| 2020-03-10T15:45:35.247Z I  MIGRATION 22027   [range-deleter] "Failed to submit range deletion task {deletionTask}{causedBy_status}","attr":{"deletionTask":{"_id":{"$uuid":"bdc0e685-9538-4179-845d-f3f499343a05"},"nss":"foo.bar","collectionUuid":{"$uuid":"16428141-f2ea-4b37-b23d-955dee4bacd2"},"donorShardId":"donor","range":{"min":{"_id":0},"max":{"_id":10}},"whenToClean":"delayed"},"causedBy_status":" :: caused by :: RangeOverlapConflict: Requested deletion range overlaps a live shard chunk","migrationId":{"uuid":{"$uuid":"bdc0e685-9538-4179-845d-f3f499343a05"}}}
| 2020-03-10T15:45:35.249Z I  ASIO     22582   [CollectionRangeDeleter-TaskExecutor] "Killing all outstanding egress activity."
| 2020-03-10T15:45:35.249Z I  ASIO     22582   [main] "Killing all outstanding egress activity."
| 2020-03-10T15:45:35.251Z I  STORAGE  20282   [main] "Deregistering all the collections"
| 2020-03-10T15:45:35.251Z F  -        23828   [main] "Client {client_desc} still exists while destroying ServiceContext@{reinterpret_cast_uint64_t_this}","attr":{"client_desc":"range-deleter","reinterpret_cast_uint64_t_this":93887301359104}
| 2020-03-10T15:45:35.251Z F  -        23828   [main] "Client {client_desc} still exists while destroying ServiceContext@{reinterpret_cast_uint64_t_this}","attr":{"client_desc":"range-deleter-refreshFilteringMetadataUntilSuccess","reinterpret_cast_uint64_t_this":93887301359104}
| 2020-03-10T15:45:35.251Z F  -        23079   [main] "Invariant failure {expr} {file} {line}","attr":{"expr":"_clients.empty()","file":"src/mongo/db/service_context.cpp","line":119}
| 2020-03-10T15:45:35.251Z F  -        23080   [main] "\n\n***aborting after invariant() failure\n\n"
| 2020-03-10T15:45:35.571Z I  CONTROL  31431   [range-deleter] "BACKTRACE: {bt}","attr":{"bt":{"backtrace":...
| 2020-03-10T15:45:35.580Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D32747E1","b":"5563D0B0B000","o":"27697E1","s":"_ZN5mongo18stack_trace_detail12_GLOBAL__N_119printStackTraceImplERKNS1_7OptionsEPNS_14StackTraceSinkE.constprop.596","s+":"1E1"}}
| 2020-03-10T15:45:35.580Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D3275EC9","b":"5563D0B0B000","o":"276AEC9","s":"_ZN5mongo15printStackTraceEv","s+":"29"}}
| 2020-03-10T15:45:35.580Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D3273560","b":"5563D0B0B000","o":"2768560","s":"_ZN5mongo12_GLOBAL__N_124abruptQuitWithAddrSignalEiP9siginfo_tPv","s+":"100"}}
| 2020-03-10T15:45:35.581Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"7F821E523600","b":"7F821E514000","o":"F600","s":"funlockfile","s+":"50"}}
| 2020-03-10T15:45:35.581Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"7F821E51DEC3","b":"7F821E514000","o":"9EC3","s":"__pthread_mutex_trylock","s+":"13"}}
| 2020-03-10T15:45:35.581Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D3261170","b":"5563D0B0B000","o":"2756170","s":"_ZN5mongo12latch_detail5Mutex4lockEv","s+":"20"}}
| 2020-03-10T15:45:35.581Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D21E8BEE","b":"5563D0B0B000","o":"16DDBEE","s":"_ZN5mongo12CatalogCache48_createOrGetCollectionEntryAndMarkAsNeedsRefreshERKNS_15NamespaceStringE","s+":"2E"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D21EBCFD","b":"5563D0B0B000","o":"16E0CFD","s":"_ZN5mongo12CatalogCache42_getCollectionRoutingInfoWithForcedRefreshEPNS_16OperationContextERKNS_15NamespaceStringE","s+":"4D"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D21EBD85","b":"5563D0B0B000","o":"16E0D85","s":"_ZN5mongo12CatalogCache35getCollectionRoutingInfoWithRefreshEPNS_16OperationContextERKNS_15NamespaceStringEb","s+":"45"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1AA6913","b":"5563D0B0B000","o":"F9B913","s":"_ZN5mongo34forceShardFilteringMetadataRefreshEPNS_16OperationContextERKNS_15NamespaceStringEb","s+":"D3"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1A7B104","b":"5563D0B0B000","o":"F70104","s":"_ZNSt17_Function_handlerIFvPN5mongo16OperationContextEEZNS0_13migrationutil36refreshFilteringMetadataUntilSuccessES2_RKNS0_15NamespaceStringEEUlS2_E_E9_M_invokeERKSt9_Any_dataOS2_","s+":"44"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1A7B481","b":"5563D0B0B000","o":"F70481","s":"_ZN5mongo13migrationutil12_GLOBAL__N_131retryIdempotentWorkUntilSuccessEPNS_16OperationContextENS_10StringDataESt8functionIFvS3_EE","s+":"2F1"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1A7D18C","b":"5563D0B0B000","o":"F7218C","s":"_ZN5mongo13migrationutil36refreshFilteringMetadataUntilSuccessEPNS_16OperationContextERKNS_15NamespaceStringE","s+":"4C"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1A81086","b":"5563D0B0B000","o":"F76086","s":"_ZZN5mongo13migrationutil23submitRangeDeletionTaskEPNS_16OperationContextERKNS_17RangeDeletionTaskEENKUlvE_clEv","s+":"4E6"}}
| 2020-03-10T15:45:35.582Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1A81744","b":"5563D0B0B000","o":"F76744","s":"_ZZN5mongo15unique_functionIFNS_16SharedSemiFutureIvEEvEE8makeImplIZNS_13migrationutil23submitRangeDeletionTaskEPNS_16OperationContextERKNS_17RangeDeletionTaskEEUlvE_EEDaOT_EN12SpecificImpl4callEv","s+":"24"}}
| 2020-03-10T15:45:35.583Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1A875ED","b":"5563D0B0B000","o":"F7C5ED","s":"_ZZNO5mongo14future_details10FutureImplINS0_8FakeVoidEE4thenIZZZNS_14ExecutorFutureIvE12wrapCBHelperIFNS_16SharedSemiFutureIvEEvEEEDaONS_15unique_functionIT_EEENUlDpOT_E_clIJEEENS_6FutureINS0_17UnwrappedTypeImplIDTclfp_spcl7forwardIDtfp_EEfp_EEEE4typeEEESH_ENUlNS_6StatusEE_clESR_EUlvE_EEDaOSC_ENKUlOS2_E_clESV_","s+":"3D"}}
| 2020-03-10T15:45:35.583Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D1A87898","b":"5563D0B0B000","o":"F7C898","s":"_ZZN5mongo15unique_functionIFvNS_6StatusEEE8makeImplIZZNS_14ExecutorFutureIvE12wrapCBHelperIFNS_16SharedSemiFutureIvEEvEEEDaONS0_IT_EEENUlDpOT_E_clIJEEENS_6FutureINS_14future_details17UnwrappedTypeImplIDTclfp_spcl7forwardIDtfp_EEfp_EEEE4typeEEESG_EUlS1_E_EEDaOSB_EN12SpecificImpl4callEOS1_","s+":"C8"}}
| 2020-03-10T15:45:35.583Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D2EA5AB1","b":"5563D0B0B000","o":"239AAB1","s":"_ZN5mongo10ThreadPool10_doOneTaskEPSt11unique_lockINS_12latch_detail5LatchEE","s+":"141"}}
| 2020-03-10T15:45:35.583Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D2EA83CC","b":"5563D0B0B000","o":"239D3CC","s":"_ZN5mongo10ThreadPool13_consumeTasksEv","s+":"8C"}}
| 2020-03-10T15:45:35.583Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D2EA94FE","b":"5563D0B0B000","o":"239E4FE","s":"_ZN5mongo10ThreadPool17_workerThreadBodyEPS0_RKNSt7__cxx1112basic_stringIcSt11char_traitsIcESaIcEEE","s+":"EE"}}
| 2020-03-10T15:45:35.583Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D2EA9780","b":"5563D0B0B000","o":"239E780","s":"_ZNSt6thread11_State_implINS_8_InvokerISt5tupleIJZN5mongo4stdx6threadC4IZNS3_10ThreadPool25_startWorkerThread_inlockEvEUlvE2_JELi0EEET_DpOT0_EUlvE_EEEEE6_M_runEv","s+":"60"}}
| 2020-03-10T15:45:35.584Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"5563D340D60F","b":"5563D0B0B000","o":"290260F","s":"execute_native_thread_routine","s+":"F"}}
| 2020-03-10T15:45:35.585Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"7F821E51BE75","b":"7F821E514000","o":"7E75","s":"__pthread_get_minstack","s+":"1165"}}
| 2020-03-10T15:45:35.585Z I  CONTROL  31427   [range-deleter] "  Frame: {frame}","attr":{"frame":{"a":"7F821E2448FD","b":"7F821E146000","o":"FE8FD","s":"clone","s+":"6D"}}

Corresponding example good run:

  • Note no excessively delayed usage of collection uuids.

| 2020-03-10T17:19:50.133Z I  -        23059   [main] "\t going to run test: {tc_name}{runTimes_str}","attr":{"tc_name":"RemoveDocumentsInRangeRetriesOnWriteConflictException","runTimes_str":""}
| 2020-03-10T17:19:50.134Z I  -        23051   [main] "Created temporary directory: {path}","attr":{"path":"/data/mci/4a1691501987813c4b2442b1971c5854/tmp/service_context_d_test_fixture-e92a-2ae6-f9ca-d086"}
| 2020-03-10T17:19:50.134Z I  REPL     21531   [main] "Initialized the rollback ID to {rbid}","attr":{"rbid":100}
| 2020-03-10T17:19:50.134Z W  ASIO     22601   [main] "No TransportLayer configured during NetworkInterface startup"
| 2020-03-10T17:19:50.140Z I  REPL     21250   [main] "******"
| 2020-03-10T17:19:50.140Z I  REPL     21251   [main] "creating replication oplog of size: {size}MB...","attr":{"size":0}
| 2020-03-10T17:19:50.140Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"local.oplog.rs","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"4149ef30-3d8e-47bc-83e8-7ab7aad89afa"}},"options":{"capped":true,"size":512000,"autoIndexId":false}}
| 2020-03-10T17:19:50.140Z I  REPL     21252   [main] "******"
| 2020-03-10T17:19:50.140Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"foo.bar","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"fb25bdc7-07a8-448e-b965-90563b131fe9"}},"options":{}}
| 2020-03-10T17:19:50.140Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"foo.bar"}
| 2020-03-10T17:19:50.141Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"config.rangeDeletions","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"f106d34a-f168-4650-acf7-646af7c88c55"}},"options":{}}
| 2020-03-10T17:19:50.141Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"config.rangeDeletions"}
| 2020-03-10T17:19:50.141Z I  MIGRATION 22026   [range-deleter] "Submitting range deletion task {deletionTask}","attr":{"deletionTask":{"_id":{"$uuid":"334aa75c-0327-4144-a7da-73449ab1b7c6"},"nss":"foo.bar","collectionUuid":{"$uuid":"fb25bdc7-07a8-448e-b965-90563b131fe9"},"donorShardId":"donor","range":{"min":{"_id":0},"max":{"_id":10}},"whenToClean":"delayed"},"migrationId":{"uuid":{"$uuid":"334aa75c-0327-4144-a7da-73449ab1b7c6"}}}
| 2020-03-10T17:19:50.141Z I  MIGRATION 22027   [range-deleter] "Failed to submit range deletion task {deletionTask}{causedBy_status}","attr":{"deletionTask":{"_id":{"$uuid":"334aa75c-0327-4144-a7da-73449ab1b7c6"},"nss":"foo.bar","collectionUuid":{"$uuid":"fb25bdc7-07a8-448e-b965-90563b131fe9"},"donorShardId":"donor","range":{"min":{"_id":0},"max":{"_id":10}},"whenToClean":"delayed"},"causedBy_status":" :: caused by :: RangeOverlapConflict: Requested deletion range overlaps a live shard chunk","migrationId":{"uuid":{"$uuid":"334aa75c-0327-4144-a7da-73449ab1b7c6"}}}
| 2020-03-10T17:19:50.141Z I  STORAGE  20320   [range-deleter] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"admin.system.version","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"6cc10446-84cd-4532-81d8-f9555b59882e"}},"options":{}}
| 2020-03-10T17:19:50.141Z I  INDEX    20345   [range-deleter] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"admin.system.version"}
| 2020-03-10T17:19:50.142Z I  COMMAND  518070  [main] "CMD: drop {collectionName}","attr":{"collectionName":"foo.bar"}
| 2020-03-10T17:19:50.142Z I  STORAGE  20315   [main] "dropCollection: {nss} ({uuid}) - renaming to drop-pending collection: {dpns} with drop optime {dropOpTime}","attr":{"nss":"foo.bar","uuid":{"uuid":{"$uuid":"fb25bdc7-07a8-448e-b965-90563b131fe9"}},"dpns":"foo.system.drop.1583860790i9t0.bar","dropOpTime":{"ts":{"$timestamp":{"t":1583860790,"i":9}},"t":0}}
| 2020-03-10T17:19:50.142Z I  STORAGE  20319   [main] "renameCollection: renaming collection {collToRename_uuid} from {fromNss} to {toNss}","attr":{"collToRename_uuid":{"uuid":{"$uuid":"fb25bdc7-07a8-448e-b965-90563b131fe9"}},"fromNss":"foo.bar","toNss":"foo.system.drop.1583860790i9t0.bar"}
| 2020-03-10T17:19:50.142Z I  ASIO     22582   [CollectionRangeDeleter-TaskExecutor] "Killing all outstanding egress activity."
| 2020-03-10T17:19:50.142Z I  ASIO     22582   [main] "Killing all outstanding egress activity."
| 2020-03-10T17:19:50.143Z I  STORAGE  20282   [main] "Deregistering all the collections"
| 2020-03-10T17:19:50.143Z I  -        23059   [main] "\t going to run test: {tc_name}{runTimes_str}","attr":{"tc_name":"RemoveDocumentsInRangeRetriesOnUnexpectedError","runTimes_str":""}
| 2020-03-10T17:19:50.144Z I  -        23051   [main] "Created temporary directory: {path}","attr":{"path":"/data/mci/4a1691501987813c4b2442b1971c5854/tmp/service_context_d_test_fixture-c44a-ff11-d168-2d2d"}
| 2020-03-10T17:19:50.144Z I  REPL     21531   [main] "Initialized the rollback ID to {rbid}","attr":{"rbid":100}
| 2020-03-10T17:19:50.144Z W  ASIO     22601   [main] "No TransportLayer configured during NetworkInterface startup"
| 2020-03-10T17:19:50.150Z I  REPL     21250   [main] "******"
| 2020-03-10T17:19:50.150Z I  REPL     21251   [main] "creating replication oplog of size: {size}MB...","attr":{"size":0}
| 2020-03-10T17:19:50.150Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"local.oplog.rs","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"210e52f5-2cbc-4245-88e3-4506b692a1d5"}},"options":{"capped":true,"size":512000,"autoIndexId":false}}
| 2020-03-10T17:19:50.151Z I  REPL     21252   [main] "******"
| 2020-03-10T17:19:50.151Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"foo.bar","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"274d14e0-1625-48d2-b49f-7757fd5321af"}},"options":{}}
| 2020-03-10T17:19:50.151Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"foo.bar"}
| 2020-03-10T17:19:50.151Z I  STORAGE  20320   [main] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"config.rangeDeletions","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"15e1df87-a01b-4e2f-9f36-d125dbe51782"}},"options":{}}
| 2020-03-10T17:19:50.151Z I  INDEX    20345   [main] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"config.rangeDeletions"}
| 2020-03-10T17:19:50.151Z I  MIGRATION 22026   [range-deleter] "Submitting range deletion task {deletionTask}","attr":{"deletionTask":{"_id":{"$uuid":"775adc56-02b6-4f2f-aa3f-905dad5ad7c5"},"nss":"foo.bar","collectionUuid":{"$uuid":"274d14e0-1625-48d2-b49f-7757fd5321af"},"donorShardId":"donor","range":{"min":{"_id":0},"max":{"_id":10}},"whenToClean":"delayed"},"migrationId":{"uuid":{"$uuid":"775adc56-02b6-4f2f-aa3f-905dad5ad7c5"}}}
| 2020-03-10T17:19:50.151Z I  MIGRATION 22027   [range-deleter] "Failed to submit range deletion task {deletionTask}{causedBy_status}","attr":{"deletionTask":{"_id":{"$uuid":"775adc56-02b6-4f2f-aa3f-905dad5ad7c5"},"nss":"foo.bar","collectionUuid":{"$uuid":"274d14e0-1625-48d2-b49f-7757fd5321af"},"donorShardId":"donor","range":{"min":{"_id":0},"max":{"_id":10}},"whenToClean":"delayed"},"causedBy_status":" :: caused by :: RangeOverlapConflict: Requested deletion range overlaps a live shard chunk","migrationId":{"uuid":{"$uuid":"775adc56-02b6-4f2f-aa3f-905dad5ad7c5"}}}
| 2020-03-10T17:19:50.151Z I  STORAGE  20320   [range-deleter] "createCollection: {nss} with {generatedUUID_generated_provided} UUID: {optionsWithUUID_uuid_get} and options: {options}","attr":{"nss":"admin.system.version","generatedUUID_generated_provided":"generated","optionsWithUUID_uuid_get":{"uuid":{"$uuid":"3e871b20-4706-4eed-968a-759e21f263cd"}},"options":{}}
| 2020-03-10T17:19:50.152Z I  INDEX    20345   [range-deleter] "index build: done building index {indexName} on ns {nss}","attr":{"indexName":"_id_","nss":"admin.system.version"}
| 2020-03-10T17:19:50.152Z I  COMMAND  518070  [main] "CMD: drop {collectionName}","attr":{"collectionName":"foo.bar"}
| 2020-03-10T17:19:50.152Z I  STORAGE  20315   [main] "dropCollection: {nss} ({uuid}) - renaming to drop-pending collection: {dpns} with drop optime {dropOpTime}","attr":{"nss":"foo.bar","uuid":{"uuid":{"$uuid":"274d14e0-1625-48d2-b49f-7757fd5321af"}},"dpns":"foo.system.drop.1583860790i9t0.bar","dropOpTime":{"ts":{"$timestamp":{"t":1583860790,"i":9}},"t":0}}
| 2020-03-10T17:19:50.152Z I  STORAGE  20319   [main] "renameCollection: renaming collection {collToRename_uuid} from {fromNss} to {toNss}","attr":{"collToRename_uuid":{"uuid":{"$uuid":"274d14e0-1625-48d2-b49f-7757fd5321af"}},"fromNss":"foo.bar","toNss":"foo.system.drop.1583860790i9t0.bar"}
| 2020-03-10T17:19:50.152Z I  ASIO     22582   [CollectionRangeDeleter-TaskExecutor] "Killing all outstanding egress activity."
| 2020-03-10T17:19:50.153Z I  ASIO     22582   [main] "Killing all outstanding egress activity."
| 2020-03-10T17:19:50.153Z I  STORAGE  20282   [main] "Deregistering all the collections"
| 2020-03-10T17:19:50.153Z I  -        23059   [main] "\t going to run test: {tc_name}{runTimes_str}","attr":{"tc_name":"RemoveDocumentsInRangeRespectsDelayInBetweenBatches","runTimes_str":""}



 Comments   
Comment by Githook User [ 01/Apr/20 ]

Author:

{'name': 'Alex Taskov', 'email': 'alex.taskov@mongodb.com', 'username': 'alextaskov'}

Message: SERVER-47038 Some RangeDeletion unit tests don't correctly wait for threads to join

(cherry picked from commit 2a89894a26de04beadd39b5f0e0ab98b98d1d62a)
Branch: v4.4
https://github.com/mongodb/mongo/commit/28c3d567cbc2b2d445eedd49294a74d400955c2b

Comment by Githook User [ 01/Apr/20 ]

Author:

{'name': 'Alex Taskov', 'email': 'alex.taskov@mongodb.com', 'username': 'alextaskov'}

Message: SERVER-47038 Some RangeDeletion unit tests don't correctly wait for threads to join
Branch: master
https://github.com/mongodb/mongo/commit/2a89894a26de04beadd39b5f0e0ab98b98d1d62a

Comment by Alexander Taskov (Inactive) [ 01/Apr/20 ]

It looks like the reason operations are still running after the unit tests terminate is that some range deletion operations are run on a separate thread pool 

Comment by Kevin Pulo [ 23/Mar/20 ]

matthew.saltz I don't understand how/why this range deleter code is able to continue running on a fixed executor thread beyond the end of the unit test.

This causes segfaults when the code tries to access the now-deleted CatalogCache (during forced refresh), or invariants in ServiceContext because the clients are still active on it.

The individual unit tests call .get() on the SemiFuture, which I expect ought to block until the range deletion has completed. And on top of that the ShardingMongodTestFixture::tearDown() calls shutdownAndJoin() on the executorPool, which I also would have expected to block until the threads have finished running... But somehow there are still log lines being emitted after teardown commences, that refer to the uuid of the foo.bar collection.

Generated at Thu Feb 08 05:13:06 UTC 2024 using Jira 9.7.1#970001-sha1:2222b88b221c4928ef0de3161136cc90c8356a66.