diff options
Diffstat (limited to 'src/mongo/watchdog')
-rw-r--r-- | src/mongo/watchdog/watchdog.cpp | 170 | ||||
-rw-r--r-- | src/mongo/watchdog/watchdog_test.cpp | 9 |
2 files changed, 127 insertions, 52 deletions
diff --git a/src/mongo/watchdog/watchdog.cpp b/src/mongo/watchdog/watchdog.cpp index accc1b3b06d..cbd6e2df39a 100644 --- a/src/mongo/watchdog/watchdog.cpp +++ b/src/mongo/watchdog/watchdog.cpp @@ -45,6 +45,7 @@ #include "mongo/base/static_assert.h" #include "mongo/db/client.h" #include "mongo/db/operation_context.h" +#include "mongo/logv2/log.h" #include "mongo/platform/process_id.h" #include "mongo/util/concurrency/idle_thread_block.h" #include "mongo/util/exit.h" @@ -159,13 +160,15 @@ void WatchdogPeriodicThread::doLoop() { } catch (const DBException& e) { // The only bad status is when we are in shutdown if (!opCtx->getServiceContext()->getKillAllOperations()) { - severe() << "Watchdog was interrupted, shutting down, reason: " << e.toStatus(); + LOGV2_FATAL(23415, + "Watchdog was interrupted, shutting down, reason: {e_toStatus}", + "e_toStatus"_attr = e.toStatus()); exitCleanly(ExitCode::EXIT_ABRUPT); } // This interruption ends the WatchdogPeriodicThread. This means it is possible to // killOp this operation and stop it for the lifetime of the process. - LOG(1) << "WatchdogPeriodicThread interrupted by: " << e; + LOGV2_DEBUG(23406, 1, "WatchdogPeriodicThread interrupted by: {e}", "e"_attr = e); return; } @@ -202,8 +205,12 @@ void WatchdogCheckThread::run(OperationContext* opCtx) { check->run(opCtx); Microseconds micros = timer.elapsed(); - LOG(1) << "Watchdog test '" << check->getDescriptionForLogging() << "' took " - << duration_cast<Milliseconds>(micros); + LOGV2_DEBUG(23407, + 1, + "Watchdog test '{check_getDescriptionForLogging}' took " + "{duration_cast_Milliseconds_micros}", + "check_getDescriptionForLogging"_attr = check->getDescriptionForLogging(), + "duration_cast_Milliseconds_micros"_attr = duration_cast<Milliseconds>(micros)); // We completed a check, bump the generation counter. _checkGeneration.fetchAndAdd(1); @@ -250,7 +257,7 @@ WatchdogMonitor::WatchdogMonitor(std::vector<std::unique_ptr<WatchdogCheck>> che } void WatchdogMonitor::start() { - log() << "Starting Watchdog Monitor"; + LOGV2(23408, "Starting Watchdog Monitor"); // Start the threads. _watchdogCheckThread.start(); @@ -279,12 +286,14 @@ void WatchdogMonitor::setPeriod(Milliseconds duration) { _watchdogCheckThread.setPeriod(_checkPeriod); _watchdogMonitorThread.setPeriod(duration); - log() << "WatchdogMonitor period changed to " << duration_cast<Seconds>(duration); + LOGV2(23409, + "WatchdogMonitor period changed to {duration_cast_Seconds_duration}", + "duration_cast_Seconds_duration"_attr = duration_cast<Seconds>(duration)); } else { _watchdogMonitorThread.setPeriod(duration); _watchdogCheckThread.setPeriod(duration); - log() << "WatchdogMonitor disabled"; + LOGV2(23410, "WatchdogMonitor disabled"); } } } @@ -342,36 +351,52 @@ void checkFile(OperationContext* opCtx, const boost::filesystem::path& file) { NULL); if (hFile == INVALID_HANDLE_VALUE) { std::uint32_t gle = ::GetLastError(); - severe() << "CreateFile failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(gle); + LOGV2_FATAL( + 23416, + "CreateFile failed for '{file_generic_string}' with error: {errnoWithDescription_gle}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_gle"_attr = errnoWithDescription(gle)); fassertNoTrace(4074, gle == 0); } DWORD bytesWrittenTotal; if (!WriteFile(hFile, nowStr.c_str(), nowStr.size(), &bytesWrittenTotal, NULL)) { std::uint32_t gle = ::GetLastError(); - severe() << "WriteFile failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(gle); + LOGV2_FATAL( + 23417, + "WriteFile failed for '{file_generic_string}' with error: {errnoWithDescription_gle}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_gle"_attr = errnoWithDescription(gle)); fassertNoTrace(4075, gle == 0); } if (bytesWrittenTotal != nowStr.size()) { - warning() << "partial write for '" << file.generic_string() << "' expected " - << nowStr.size() << " bytes but wrote " << bytesWrittenTotal << " bytes"; + LOGV2_WARNING(23411, + "partial write for '{file_generic_string}' expected {nowStr_size} bytes but " + "wrote {bytesWrittenTotal} bytes", + "file_generic_string"_attr = file.generic_string(), + "nowStr_size"_attr = nowStr.size(), + "bytesWrittenTotal"_attr = bytesWrittenTotal); } else { if (!FlushFileBuffers(hFile)) { std::uint32_t gle = ::GetLastError(); - severe() << "FlushFileBuffers failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(gle); + LOGV2_FATAL(23418, + "FlushFileBuffers failed for '{file_generic_string}' with error: " + "{errnoWithDescription_gle}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_gle"_attr = errnoWithDescription(gle)); fassertNoTrace(4076, gle == 0); } DWORD newOffset = SetFilePointer(hFile, 0, 0, FILE_BEGIN); if (newOffset != 0) { std::uint32_t gle = ::GetLastError(); - severe() << "SetFilePointer failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(gle); + LOGV2_FATAL(23419, + "SetFilePointer failed for '{file_generic_string}' with error: " + "{errnoWithDescription_gle}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_gle"_attr = errnoWithDescription(gle)); fassertNoTrace(4077, gle == 0); } @@ -379,29 +404,46 @@ void checkFile(OperationContext* opCtx, const boost::filesystem::path& file) { auto readBuffer = std::make_unique<char[]>(nowStr.size()); if (!ReadFile(hFile, readBuffer.get(), nowStr.size(), &bytesRead, NULL)) { std::uint32_t gle = ::GetLastError(); - severe() << "ReadFile failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(gle); + LOGV2_FATAL(23420, + "ReadFile failed for '{file_generic_string}' with error: " + "{errnoWithDescription_gle}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_gle"_attr = errnoWithDescription(gle)); fassertNoTrace(4078, gle == 0); } if (bytesRead != bytesWrittenTotal) { - severe() << "Read wrong number of bytes for '" << file.generic_string() << "' expected " - << bytesWrittenTotal << " bytes but read " << bytesRead << " bytes"; + LOGV2_FATAL(23421, + "Read wrong number of bytes for '{file_generic_string}' expected " + "{bytesWrittenTotal} bytes but read {bytesRead} bytes", + "file_generic_string"_attr = file.generic_string(), + "bytesWrittenTotal"_attr = bytesWrittenTotal, + "bytesRead"_attr = bytesRead); fassertNoTrace(50724, false); } if (memcmp(nowStr.c_str(), readBuffer.get(), nowStr.size()) != 0) { - severe() << "Read wrong string from file '" << file.generic_string() << nowStr.size() - << " bytes (in hex) '" << toHexLower(nowStr.c_str(), nowStr.size()) - << "' but read bytes '" << toHexLower(readBuffer.get(), bytesRead) << "'"; + LOGV2_FATAL(23422, + "Read wrong string from file '{file_generic_string}{nowStr_size} bytes (in " + "hex) '{toHexLower_nowStr_c_str_nowStr_size}' but read bytes " + "'{toHexLower_readBuffer_get_bytesRead}'", + "file_generic_string"_attr = file.generic_string(), + "nowStr_size"_attr = nowStr.size(), + "toHexLower_nowStr_c_str_nowStr_size"_attr = + toHexLower(nowStr.c_str(), nowStr.size()), + "toHexLower_readBuffer_get_bytesRead"_attr = + toHexLower(readBuffer.get(), bytesRead)); fassertNoTrace(50717, false); } } if (!CloseHandle(hFile)) { std::uint32_t gle = ::GetLastError(); - severe() << "CloseHandle failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(gle); + LOGV2_FATAL( + 23423, + "CloseHandle failed for '{file_generic_string}' with error: {errnoWithDescription_gle}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_gle"_attr = errnoWithDescription(gle)); fassertNoTrace(4079, gle == 0); } } @@ -426,8 +468,11 @@ void checkFile(OperationContext* opCtx, const boost::filesystem::path& file) { int fd = open(file.generic_string().c_str(), O_RDWR | O_CREAT, S_IRUSR | S_IWUSR); if (fd == -1) { auto err = errno; - severe() << "open failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(err); + LOGV2_FATAL( + 23424, + "open failed for '{file_generic_string}' with error: {errnoWithDescription_err}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_err"_attr = errnoWithDescription(err)); fassertNoTrace(4080, err == 0); } @@ -441,15 +486,22 @@ void checkFile(OperationContext* opCtx, const boost::filesystem::path& file) { continue; } - severe() << "write failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(err); + LOGV2_FATAL( + 23425, + "write failed for '{file_generic_string}' with error: {errnoWithDescription_err}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_err"_attr = errnoWithDescription(err)); fassertNoTrace(4081, err == 0); } // Warn if the write was incomplete if (bytesWrittenTotal == 0 && static_cast<size_t>(bytesWrittenInWrite) != nowStr.size()) { - warning() << "parital write for '" << file.generic_string() << "' expected " - << nowStr.size() << " bytes but wrote " << bytesWrittenInWrite << " bytes"; + LOGV2_WARNING(23412, + "parital write for '{file_generic_string}' expected {nowStr_size} bytes " + "but wrote {bytesWrittenInWrite} bytes", + "file_generic_string"_attr = file.generic_string(), + "nowStr_size"_attr = nowStr.size(), + "bytesWrittenInWrite"_attr = bytesWrittenInWrite); } bytesWrittenTotal += bytesWrittenInWrite; @@ -457,8 +509,11 @@ void checkFile(OperationContext* opCtx, const boost::filesystem::path& file) { if (fsync(fd)) { auto err = errno; - severe() << "fsync failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(err); + LOGV2_FATAL( + 23426, + "fsync failed for '{file_generic_string}' with error: {errnoWithDescription_err}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_err"_attr = errnoWithDescription(err)); fassertNoTrace(4082, err == 0); } @@ -473,36 +528,53 @@ void checkFile(OperationContext* opCtx, const boost::filesystem::path& file) { continue; } - severe() << "read failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(err); + LOGV2_FATAL( + 23427, + "read failed for '{file_generic_string}' with error: {errnoWithDescription_err}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_err"_attr = errnoWithDescription(err)); fassertNoTrace(4083, err == 0); } else if (bytesReadInRead == 0) { - severe() << "read failed for '" << file.generic_string() - << "' with unexpected end of file"; + LOGV2_FATAL(23428, + "read failed for '{file_generic_string}' with unexpected end of file", + "file_generic_string"_attr = file.generic_string()); fassertNoTrace(50719, false); } // Warn if the read was incomplete if (bytesReadTotal == 0 && static_cast<size_t>(bytesReadInRead) != nowStr.size()) { - warning() << "partial read for '" << file.generic_string() << "' expected " - << nowStr.size() << " bytes but read " << bytesReadInRead << " bytes"; + LOGV2_WARNING(23413, + "partial read for '{file_generic_string}' expected {nowStr_size} bytes " + "but read {bytesReadInRead} bytes", + "file_generic_string"_attr = file.generic_string(), + "nowStr_size"_attr = nowStr.size(), + "bytesReadInRead"_attr = bytesReadInRead); } bytesReadTotal += bytesReadInRead; } if (memcmp(nowStr.c_str(), readBuffer.get(), nowStr.size()) != 0) { - severe() << "Read wrong string from file '" << file.generic_string() << "' expected " - << nowStr.size() << " bytes (in hex) '" - << toHexLower(nowStr.c_str(), nowStr.size()) << "' but read bytes '" - << toHexLower(readBuffer.get(), bytesReadTotal) << "'"; + LOGV2_FATAL(23429, + "Read wrong string from file '{file_generic_string}' expected {nowStr_size} " + "bytes (in hex) '{toHexLower_nowStr_c_str_nowStr_size}' but read bytes " + "'{toHexLower_readBuffer_get_bytesReadTotal}'", + "file_generic_string"_attr = file.generic_string(), + "nowStr_size"_attr = nowStr.size(), + "toHexLower_nowStr_c_str_nowStr_size"_attr = + toHexLower(nowStr.c_str(), nowStr.size()), + "toHexLower_readBuffer_get_bytesReadTotal"_attr = + toHexLower(readBuffer.get(), bytesReadTotal)); fassertNoTrace(50718, false); } if (close(fd)) { auto err = errno; - severe() << "close failed for '" << file.generic_string() - << "' with error: " << errnoWithDescription(err); + LOGV2_FATAL( + 23430, + "close failed for '{file_generic_string}' with error: {errnoWithDescription_err}", + "file_generic_string"_attr = file.generic_string(), + "errnoWithDescription_err"_attr = errnoWithDescription(err)); fassertNoTrace(4084, err == 0); } } @@ -529,8 +601,10 @@ void DirectoryCheck::run(OperationContext* opCtx) { boost::system::error_code ec; boost::filesystem::remove(file, ec); if (ec) { - warning() << "Failed to delete file '" << file.generic_string() - << "', error: " << ec.message(); + LOGV2_WARNING(23414, + "Failed to delete file '{file_generic_string}', error: {ec_message}", + "file_generic_string"_attr = file.generic_string(), + "ec_message"_attr = ec.message()); } } diff --git a/src/mongo/watchdog/watchdog_test.cpp b/src/mongo/watchdog/watchdog_test.cpp index bc8bac2cc7b..02795b57481 100644 --- a/src/mongo/watchdog/watchdog_test.cpp +++ b/src/mongo/watchdog/watchdog_test.cpp @@ -38,6 +38,7 @@ #include "mongo/db/client.h" #include "mongo/db/service_context.h" #include "mongo/db/service_context_test_fixture.h" +#include "mongo/logv2/log.h" #include "mongo/unittest/death_test.h" #include "mongo/unittest/temp_dir.h" #include "mongo/unittest/unittest.h" @@ -300,7 +301,7 @@ class WatchdogMonitorThreadTest : public ServiceContextTest {}; TEST_F(WatchdogMonitorThreadTest, Basic) { ManualResetEvent deathEvent; WatchdogDeathCallback deathCallback = [&deathEvent]() { - log() << "Death signalled"; + LOGV2(23431, "Death signalled"); deathEvent.set(); }; @@ -345,7 +346,7 @@ private: TEST_F(WatchdogMonitorThreadTest, SleepyHungCheck) { ManualResetEvent deathEvent; WatchdogDeathCallback deathCallback = [&deathEvent]() { - log() << "Death signalled"; + LOGV2(23432, "Death signalled"); deathEvent.set(); }; @@ -375,7 +376,7 @@ class WatchdogMonitorTest : public ServiceContextTest {}; TEST_F(WatchdogMonitorTest, SleepyHungCheck) { ManualResetEvent deathEvent; WatchdogDeathCallback deathCallback = [&deathEvent]() { - log() << "Death signalled"; + LOGV2(23433, "Death signalled"); deathEvent.set(); }; @@ -412,7 +413,7 @@ DEATH_TEST(WatchdogMonitorTest, Death, "") { TEST_F(WatchdogMonitorTest, PauseAndResume) { WatchdogDeathCallback deathCallback = []() { - log() << "Death signalled, it should not have been"; + LOGV2(23434, "Death signalled, it should not have been"); invariant(false); }; |