diff options
author | Kaitlin Mahar <kaitlin.mahar@mongodb.com> | 2023-03-02 19:58:52 +0000 |
---|---|---|
committer | Evergreen Agent <no-reply@evergreen.mongodb.com> | 2023-03-22 20:18:43 +0000 |
commit | 75a60fabbfd7cb3df17cc509f8babf38a1087a52 (patch) | |
tree | af80a3920f3f9f1651c29927e5c6b9654f65deee /src/mongo/db/repl/primary_only_service_test.cpp | |
parent | 5767f6d16fbd191e3ebc3d0b929b398774a80fb6 (diff) | |
download | mongo-75a60fabbfd7cb3df17cc509f8babf38a1087a52.tar.gz |
SERVER-66996 Log warnings when ReplicaSetAwareServices and PrimaryOnlyServices block stepUp from completing
Diffstat (limited to 'src/mongo/db/repl/primary_only_service_test.cpp')
-rw-r--r-- | src/mongo/db/repl/primary_only_service_test.cpp | 51 |
1 files changed, 51 insertions, 0 deletions
diff --git a/src/mongo/db/repl/primary_only_service_test.cpp b/src/mongo/db/repl/primary_only_service_test.cpp index b65a54592d7..277400040fa 100644 --- a/src/mongo/db/repl/primary_only_service_test.cpp +++ b/src/mongo/db/repl/primary_only_service_test.cpp @@ -42,6 +42,7 @@ #include "mongo/rpc/get_status_from_command_result.h" #include "mongo/rpc/metadata/egress_metadata_hook_list.h" #include "mongo/unittest/death_test.h" +#include "mongo/unittest/log_test.h" #include "mongo/unittest/unittest.h" #include "mongo/util/concurrency/thread_pool.h" #include "mongo/util/fail_point.h" @@ -1152,3 +1153,53 @@ TEST_F(PrimaryOnlyServiceTest, StateTransitionFromRebuildingShouldWakeUpConditio stepUpThread.join(); lookUpInstanceThread.join(); } + +TEST_F(PrimaryOnlyServiceTest, PrimaryOnlyServiceLogSlowServices) { + std::string slowSingleServiceStepUpCompleteMsg = + "Duration spent in PrimaryOnlyServiceRegistry::onStepUpComplete for service " + "exceeded slowServiceOnStepUpCompleteThresholdMS"; + std::string slowTotalTimeStepUpCompleteMsg = + "Duration spent in PrimaryOnlyServiceRegistry::onStepUpComplete for all services " + "exceeded slowTotalOnStepUpCompleteThresholdMS"; + + stepDown(); + + // First test a stepUp with no hanging. We shouldn't log anything. + startCapturingLogMessages(); + stepUp(); + stopCapturingLogMessages(); + ASSERT_EQ(0, countTextFormatLogLinesContaining(slowSingleServiceStepUpCompleteMsg)); + ASSERT_EQ(0, countTextFormatLogLinesContaining(slowTotalTimeStepUpCompleteMsg)); + + // Use the "PrimaryOnlyServiceHangBeforeLaunchingStepUpLogic", which is encountered + // via PrimaryOnlyServiceRegistry::onStepUpComplete, to simulate a slow primary-only + // service. + auto doStepUpWithHang = [this](long long ms) { + stepDown(); + + auto stepUpTimesEntered = + PrimaryOnlyServiceHangBeforeLaunchingStepUpLogic.setMode(FailPoint::alwaysOn); + + // Start an async task to step up, which will block on the fail point. + auto stepUpFuture = ExecutorFuture<void>(_testExecutor).then([this]() { stepUp(); }); + + // Once stepUp has hit the failpoint, sleep for the specified amount of ms so the service + // hangs, before disabling the failpoint and allowing stepUp to proceed. + PrimaryOnlyServiceHangBeforeLaunchingStepUpLogic.waitForTimesEntered(++stepUpTimesEntered); + sleepmillis(ms); + PrimaryOnlyServiceHangBeforeLaunchingStepUpLogic.setMode(FailPoint::off); + stepUpFuture.wait(); + }; + + // Hang for long enough to generate a message about the single service being slow. + startCapturingLogMessages(); + doStepUpWithHang(repl::slowServiceOnStepUpCompleteThresholdMS.load() + 1); + stopCapturingLogMessages(); + ASSERT_EQ(1, countTextFormatLogLinesContaining(slowSingleServiceStepUpCompleteMsg)); + + // Hang for long enough to generate a message about the total time being slow. + startCapturingLogMessages(); + doStepUpWithHang(repl::slowTotalOnStepUpCompleteThresholdMS.load() + 1); + stopCapturingLogMessages(); + ASSERT_EQ(1, countTextFormatLogLinesContaining(slowTotalTimeStepUpCompleteMsg)); +} |