Launching soon: The world's first vendor agnostic bug scrubLearn more & join waitlist
OPERATIONAL DEFECT DATABASE
...
...
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":""}
xgen-internal-githook commented on Wed, 1 Apr 2020 21:33:16 +0000: 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 xgen-internal-githook commented on Wed, 1 Apr 2020 17:40:50 +0000: 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 alex.taskov commented on Wed, 1 Apr 2020 01:48:16 +0000: 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 kevin.pulo@10gen.com commented on Mon, 23 Mar 2020 08:17:16 +0000: 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.