Uploaded image for project: 'Core Server'
  1. Core Server
  2. SERVER-47038

Some RangeDeletion unit tests don't correctly wait for threads to join

    • 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":""}
      

            Assignee:
            alex.taskov@mongodb.com Alexander Taskov (Inactive)
            Reporter:
            kevin.pulo@mongodb.com Kevin Pulo
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: