-
Type: Bug
-
Resolution: Fixed
-
Priority: Major - P3
-
Affects Version/s: None
-
Component/s: Sharding
-
Fully Compatible
-
ALL
-
v4.4
-
Sharding 2020-04-06
-
45
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":""}