From eafd8199cbd90915088c505e75810de7b4d52f90 Mon Sep 17 00:00:00 2001 From: Gabriel Russell Date: Wed, 29 Apr 2020 17:28:15 -0400 Subject: SERVER-46932 supress more logging in the shell --- src/mongo/executor/connection_pool.cpp | 2 +- src/mongo/scripting/engine.cpp | 2 +- src/mongo/scripting/mozjs/cursor_handle.cpp | 8 ++-- src/mongo/scripting/mozjs/global.cpp | 9 +++-- src/mongo/scripting/mozjs/implscope.cpp | 23 ++++++----- src/mongo/scripting/mozjs/jsthread.cpp | 2 - src/mongo/scripting/mozjs/session.cpp | 8 ++-- src/mongo/shell/bench.cpp | 60 ++++++++++++++-------------- src/mongo/shell/kms_aws.cpp | 2 +- src/mongo/shell/shell_options.cpp | 6 ++- src/mongo/shell/shell_utils_launcher.cpp | 57 +++++++++++++------------- src/mongo/transport/transport_layer_asio.cpp | 10 ++--- 12 files changed, 97 insertions(+), 92 deletions(-) diff --git a/src/mongo/executor/connection_pool.cpp b/src/mongo/executor/connection_pool.cpp index b5943cafe17..19f6bbac6a4 100644 --- a/src/mongo/executor/connection_pool.cpp +++ b/src/mongo/executor/connection_pool.cpp @@ -63,7 +63,7 @@ namespace { auto makeSeveritySuppressor() { return std::make_unique>( - Seconds{1}, logv2::LogSeverity::Info(), logv2::LogSeverity::Debug(2)); + Seconds{1}, logv2::LogSeverity::Log(), logv2::LogSeverity::Debug(2)); } template diff --git a/src/mongo/scripting/engine.cpp b/src/mongo/scripting/engine.cpp index 71c9edad763..c430e057dbb 100644 --- a/src/mongo/scripting/engine.cpp +++ b/src/mongo/scripting/engine.cpp @@ -353,7 +353,7 @@ public: if (scope->hasOutOfMemoryException()) { // make some room - LOGV2(22777, "Clearing all idle JS contexts due to out of memory"); + LOGV2_INFO(22777, "Clearing all idle JS contexts due to out of memory"); _pools.clear(); return; } diff --git a/src/mongo/scripting/mozjs/cursor_handle.cpp b/src/mongo/scripting/mozjs/cursor_handle.cpp index 55f75160686..be97580db07 100644 --- a/src/mongo/scripting/mozjs/cursor_handle.cpp +++ b/src/mongo/scripting/mozjs/cursor_handle.cpp @@ -77,10 +77,10 @@ void CursorHandleInfo::finalize(js::FreeOp* fop, JSObject* obj) { auto status = exceptionToStatus(); try { - LOGV2(22782, - "Failed to kill cursor {cursorId} due to {status}", - "cursorId"_attr = cursorId, - "status"_attr = status); + LOGV2_INFO(22782, + "Failed to kill cursor {cursorId} due to {status}", + "cursorId"_attr = cursorId, + "status"_attr = status); } catch (...) { // This is here in case logging fails. } diff --git a/src/mongo/scripting/mozjs/global.cpp b/src/mongo/scripting/mozjs/global.cpp index 6092c560966..3ff4f9129ba 100644 --- a/src/mongo/scripting/mozjs/global.cpp +++ b/src/mongo/scripting/mozjs/global.cpp @@ -82,10 +82,11 @@ void GlobalInfo::Functions::print::call(JSContext* cx, JS::CallArgs args) { args.rval().setUndefined(); - LOGV2_OPTIONS(4615635, - logv2::LogOptions(logv2::LogTag::kPlainShell, logv2::LogTruncation::Disabled), - "{message}", - "message"_attr = ss.str()); + LOGV2_INFO_OPTIONS( + 4615635, + logv2::LogOptions(logv2::LogTag::kPlainShell, logv2::LogTruncation::Disabled), + "{message}", + "message"_attr = ss.str()); } void GlobalInfo::Functions::version::call(JSContext* cx, JS::CallArgs args) { diff --git a/src/mongo/scripting/mozjs/implscope.cpp b/src/mongo/scripting/mozjs/implscope.cpp index 85f9b9ae54e..0680ac6a86b 100644 --- a/src/mongo/scripting/mozjs/implscope.cpp +++ b/src/mongo/scripting/mozjs/implscope.cpp @@ -225,13 +225,13 @@ void MozJSImplScope::_gcCallback(JSContext* rt, JSGCStatus status, void* data) { return; } - LOGV2(22787, - "MozJS GC {status_JSGC_BEGIN_prologue_epilogue} heap stats - total: " - "{mongo_sm_get_total_bytes} limit: {mongo_sm_get_max_bytes}", - "status_JSGC_BEGIN_prologue_epilogue"_attr = - (status == JSGC_BEGIN ? "prologue" : "epilogue"), - "mongo_sm_get_total_bytes"_attr = mongo::sm::get_total_bytes(), - "mongo_sm_get_max_bytes"_attr = mongo::sm::get_max_bytes()); + LOGV2_INFO(22787, + "MozJS GC {status_JSGC_BEGIN_prologue_epilogue} heap stats - total: " + "{mongo_sm_get_total_bytes} limit: {mongo_sm_get_max_bytes}", + "status_JSGC_BEGIN_prologue_epilogue"_attr = + (status == JSGC_BEGIN ? "prologue" : "epilogue"), + "mongo_sm_get_total_bytes"_attr = mongo::sm::get_total_bytes(), + "mongo_sm_get_max_bytes"_attr = mongo::sm::get_max_bytes()); } #if __has_feature(address_sanitizer) @@ -929,10 +929,11 @@ bool MozJSImplScope::_checkErrorState(bool success, bool reportError, bool asser } if (reportError) - LOGV2_OPTIONS(4635900, - logv2::LogOptions(logv2::LogTag::kPlainShell, logv2::LogTruncation::Disabled), - "{message}", - "message"_attr = redact(_error)); + LOGV2_INFO_OPTIONS( + 4635900, + logv2::LogOptions(logv2::LogTag::kPlainShell, logv2::LogTruncation::Disabled), + "{message}", + "message"_attr = redact(_error)); // Clear the status state auto status = std::move(_status); diff --git a/src/mongo/scripting/mozjs/jsthread.cpp b/src/mongo/scripting/mozjs/jsthread.cpp index 63c4b980e72..5e039e5b51e 100644 --- a/src/mongo/scripting/mozjs/jsthread.cpp +++ b/src/mongo/scripting/mozjs/jsthread.cpp @@ -27,8 +27,6 @@ * it in the license file. */ -#define MONGO_LOGV2_DEFAULT_COMPONENT ::mongo::logv2::LogComponent::kQuery - #include "mongo/platform/basic.h" #include "mongo/scripting/mozjs/jsthread.h" diff --git a/src/mongo/scripting/mozjs/session.cpp b/src/mongo/scripting/mozjs/session.cpp index 4b205db1e76..16d2906edf2 100644 --- a/src/mongo/scripting/mozjs/session.cpp +++ b/src/mongo/scripting/mozjs/session.cpp @@ -152,10 +152,10 @@ void SessionInfo::finalize(js::FreeOp* fop, JSObject* obj) { auto status = exceptionToStatus(); try { - LOGV2(22791, - "Failed to end session {lsid} due to {status}", - "lsid"_attr = lsid, - "status"_attr = status); + LOGV2_INFO(22791, + "Failed to end session {lsid} due to {status}", + "lsid"_attr = lsid, + "status"_attr = status); } catch (...) { // This is here in case logging fails. } diff --git a/src/mongo/shell/bench.cpp b/src/mongo/shell/bench.cpp index 0d5f09a6900..6edb8cff9ad 100644 --- a/src/mongo/shell/bench.cpp +++ b/src/mongo/shell/bench.cpp @@ -738,7 +738,7 @@ void BenchRunConfig::initializeFromBson(const BSONObj& args) { ops.push_back(opFromBson(i.next().Obj())); } } else { - LOGV2(22793, "benchRun passed an unsupported field: {name}", "name"_attr = name); + LOGV2_INFO(22793, "benchRun passed an unsupported field: {name}", "name"_attr = name); uassert(34376, "benchRun passed an unsupported configuration field", false); } } @@ -917,12 +917,12 @@ void BenchRunWorker::generateLoadOnConnection(DBClientBase* conn) { (!_config->noWatchPattern && _config->watchPattern && yesWatch) || // If we're just watching things (_config->watchPattern && _config->noWatchPattern && yesWatch && !noWatch)) - LOGV2(22794, - "Error in benchRun thread for op " - "{kOpTypeNames_find_op_op_second}{causedBy_ex}", - "kOpTypeNames_find_op_op_second"_attr = - kOpTypeNames.find(op.op)->second, - "causedBy_ex"_attr = causedBy(ex)); + LOGV2_INFO(22794, + "Error in benchRun thread for op " + "{kOpTypeNames_find_op_op_second}{causedBy_ex}", + "kOpTypeNames_find_op_op_second"_attr = + kOpTypeNames.find(op.op)->second, + "causedBy_ex"_attr = causedBy(ex)); } bool yesTrap = (_config->trapPattern && _config->trapPattern->FullMatch(ex.what())); @@ -948,10 +948,11 @@ void BenchRunWorker::generateLoadOnConnection(DBClientBase* conn) { ++opState.stats->errCount; } catch (...) { if (!_config->hideErrors || op.showError) - LOGV2(22795, - "Error in benchRun thread caused by unknown error for op " - "{kOpTypeNames_find_op_op_second}", - "kOpTypeNames_find_op_op_second"_attr = kOpTypeNames.find(op.op)->second); + LOGV2_INFO(22795, + "Error in benchRun thread caused by unknown error for op " + "{kOpTypeNames_find_op_op_second}", + "kOpTypeNames_find_op_op_second"_attr = + kOpTypeNames.find(op.op)->second); if (!_config->handleErrors && !op.handleError) return; @@ -1021,9 +1022,9 @@ void BenchRunOp::executeOnce(DBClientBase* conn, } if (!config.hideResults || this->showResult) - LOGV2(22796, - "Result from benchRun thread [findOne] : {result}", - "result"_attr = result); + LOGV2_INFO(22796, + "Result from benchRun thread [findOne] : {result}", + "result"_attr = result); } break; case OpType::COMMAND: { bool ok; @@ -1152,16 +1153,17 @@ void BenchRunOp::executeOnce(DBClientBase* conn, } if (this->expected >= 0 && count != this->expected) { - LOGV2(22797, - "bench query on: {this_ns} expected: {this_expected} got: {count}", - "this_ns"_attr = this->ns, - "this_expected"_attr = this->expected, - "count"_attr = count); + LOGV2_INFO(22797, + "bench query on: {this_ns} expected: {this_expected} got: {count}", + "this_ns"_attr = this->ns, + "this_expected"_attr = this->expected, + "count"_attr = count); verify(false); } if (!config.hideResults || this->showResult) - LOGV2(22798, "Result from benchRun thread [query] : {count}", "count"_attr = count); + LOGV2_INFO( + 22798, "Result from benchRun thread [query] : {count}", "count"_attr = count); } break; case OpType::UPDATE: { BSONObj result; @@ -1231,9 +1233,9 @@ void BenchRunOp::executeOnce(DBClientBase* conn, if (this->safe) { if (!config.hideResults || this->showResult) - LOGV2(22799, - "Result from benchRun thread [safe update] : {result}", - "result"_attr = result); + LOGV2_INFO(22799, + "Result from benchRun thread [safe update] : {result}", + "result"_attr = result); if (!result["err"].eoo() && result["err"].type() == String && (config.throwGLE || this->throwGLE)) @@ -1297,9 +1299,9 @@ void BenchRunOp::executeOnce(DBClientBase* conn, if (this->safe) { if (!config.hideResults || this->showResult) - LOGV2(22800, - "Result from benchRun thread [safe insert] : {result}", - "result"_attr = result); + LOGV2_INFO(22800, + "Result from benchRun thread [safe insert] : {result}", + "result"_attr = result); if (!result["err"].eoo() && result["err"].type() == String && (config.throwGLE || this->throwGLE)) @@ -1344,9 +1346,9 @@ void BenchRunOp::executeOnce(DBClientBase* conn, if (this->safe) { if (!config.hideResults || this->showResult) - LOGV2(22801, - "Result from benchRun thread [safe remove] : {result}", - "result"_attr = result); + LOGV2_INFO(22801, + "Result from benchRun thread [safe remove] : {result}", + "result"_attr = result); if (!result["err"].eoo() && result["err"].type() == String && (config.throwGLE || this->throwGLE)) diff --git a/src/mongo/shell/kms_aws.cpp b/src/mongo/shell/kms_aws.cpp index e9734e9c741..76bf5837d28 100644 --- a/src/mongo/shell/kms_aws.cpp +++ b/src/mongo/shell/kms_aws.cpp @@ -61,7 +61,7 @@ namespace { class AWSConnection { public: AWSConnection(SSLManagerInterface* ssl) - : _sslManager(ssl), _socket(std::make_unique(10, logv2::LogSeverity::Log())) {} + : _sslManager(ssl), _socket(std::make_unique(10, logv2::LogSeverity::Info())) {} UniqueKmsResponse makeOneRequest(const HostAndPort& host, ConstDataRange request); diff --git a/src/mongo/shell/shell_options.cpp b/src/mongo/shell/shell_options.cpp index 2365462e317..307e6301f48 100644 --- a/src/mongo/shell/shell_options.cpp +++ b/src/mongo/shell/shell_options.cpp @@ -113,10 +113,12 @@ Status storeMongoShellOptions(const moe::Environment& params, shellGlobalParams.enableIPv6 = true; } + auto minimumLoggedSeveity = logv2::LogSeverity::Info(); if (params.count("verbose")) { - logv2::LogManager::global().getGlobalSettings().setMinimumLoggedSeverity( - mongo::logv2::LogComponent::kDefault, logv2::LogSeverity::Debug(1)); + minimumLoggedSeveity = logv2::LogSeverity::Debug(1); } + logv2::LogManager::global().getGlobalSettings().setMinimumLoggedSeverity( + mongo::logv2::LogComponent::kDefault, minimumLoggedSeveity); // `objcheck` option is part of `serverGlobalParams` to avoid making common parts depend upon // the client options. The option is set to false in clients by default. diff --git a/src/mongo/shell/shell_utils_launcher.cpp b/src/mongo/shell/shell_utils_launcher.cpp index 77efd095703..4fdba455081 100644 --- a/src/mongo/shell/shell_utils_launcher.cpp +++ b/src/mongo/shell/shell_utils_launcher.cpp @@ -469,7 +469,7 @@ void ProgramRunner::start() { for (unsigned i = 0; i < _argv.size(); i++) { ss << " " << _argv[i]; } - LOGV2(22810, "{ss_str}", "ss_str"_attr = ss.str()); + LOGV2_INFO(22810, "{ss_str}", "ss_str"_attr = ss.str()); } } @@ -724,7 +724,7 @@ bool wait_for_pid(ProcessId pid, bool block = true, int* exit_code = nullptr) { return false; } else if (ret != WAIT_OBJECT_0) { const auto ewd = errnoWithDescription(); - LOGV2(22811, "wait_for_pid: WaitForSingleObject failed: {ewd}", "ewd"_attr = ewd); + LOGV2_INFO(22811, "wait_for_pid: WaitForSingleObject failed: {ewd}", "ewd"_attr = ewd); } DWORD tmp; @@ -743,7 +743,7 @@ bool wait_for_pid(ProcessId pid, bool block = true, int* exit_code = nullptr) { return true; } else { const auto ewd = errnoWithDescription(); - LOGV2(22812, "GetExitCodeProcess failed: {ewd}", "ewd"_attr = ewd); + LOGV2_INFO(22812, "GetExitCodeProcess failed: {ewd}", "ewd"_attr = ewd); return false; } #else @@ -805,7 +805,7 @@ BSONObj WaitMongoProgram(const BSONObj& a, void* data) { int exit_code = -123456; // sentinel value invariant(port >= 0); if (!registry.isPortRegistered(port)) { - LOGV2(22813, "No db started on port: {port}", "port"_attr = port); + LOGV2_INFO(22813, "No db started on port: {port}", "port"_attr = port); return BSON(string("") << 0); } pid = registry.pidForPort(port); @@ -901,12 +901,12 @@ void copyDir(const boost::filesystem::path& from, const boost::filesystem::path& boost::system::error_code ec; boost::filesystem::copy_file(p, to / p.leaf(), ec); if (ec) { - LOGV2(22814, - "Skipping copying of file from '{p_generic_string}' to " - "'{to_p_leaf_generic_string}' due to: {ec_message}", - "p_generic_string"_attr = p.generic_string(), - "to_p_leaf_generic_string"_attr = (to / p.leaf()).generic_string(), - "ec_message"_attr = ec.message()); + LOGV2_INFO(22814, + "Skipping copying of file from '{p_generic_string}' to " + "'{to_p_leaf_generic_string}' due to: {ec_message}", + "p_generic_string"_attr = p.generic_string(), + "to_p_leaf_generic_string"_attr = (to / p.leaf()).generic_string(), + "ec_message"_attr = ec.message()); } } else if (p.leaf() != "mongod.lock" && p.leaf() != "WiredTiger.lock") { if (boost::filesystem::is_directory(p)) { @@ -956,11 +956,12 @@ inline void kill_wrapper(ProcessId pid, int sig, int port, const BSONObj& opt) { const auto ewd = errnoWithDescription(); LOGV2_WARNING(22827, "kill_wrapper OpenEvent failed: {ewd}", "ewd"_attr = ewd); } else { - LOGV2(22815, - "kill_wrapper OpenEvent failed to open event to the process {pid_asUInt32}. It " - "has likely died already or server is running an older version. Attempting to " - "shutdown through admin command.", - "pid_asUInt32"_attr = pid.asUInt32()); + LOGV2_INFO( + 22815, + "kill_wrapper OpenEvent failed to open event to the process {pid_asUInt32}. It " + "has likely died already or server is running an older version. Attempting to " + "shutdown through admin command.", + "pid_asUInt32"_attr = pid.asUInt32()); // Back-off to the old way of shutting down the server on Windows, in case we // are managing a pre-2.6.0rc0 service, which did not have the event. @@ -1008,7 +1009,7 @@ inline void kill_wrapper(ProcessId pid, int sig, int port, const BSONObj& opt) { if (errno == ESRCH) { } else { const auto ewd = errnoWithDescription(); - LOGV2(22816, "killFailed: {ewd}", "ewd"_attr = ewd); + LOGV2_INFO(22816, "killFailed: {ewd}", "ewd"_attr = ewd); uasserted(ErrorCodes::UnknownError, "kill({}, {}) failed: {}"_format(pid.toNative(), sig, ewd)); } @@ -1021,7 +1022,7 @@ int killDb(int port, ProcessId _pid, int signal, const BSONObj& opt, bool waitPi ProcessId pid; if (port > 0) { if (!registry.isPortRegistered(port)) { - LOGV2(22817, "No db started on port: {port}", "port"_attr = port); + LOGV2_INFO(22817, "No db started on port: {port}", "port"_attr = port); return 0; } pid = registry.pidForPort(port); @@ -1033,13 +1034,13 @@ int killDb(int port, ProcessId _pid, int signal, const BSONObj& opt, bool waitPi // If we are not waiting for the process to end, then return immediately. if (!waitPid) { - LOGV2(22818, "skip waiting for pid {pid} to terminate", "pid"_attr = pid); + LOGV2_INFO(22818, "skip waiting for pid {pid} to terminate", "pid"_attr = pid); return 0; } int exitCode = EXIT_FAILURE; try { - LOGV2(22819, "waiting for process {pid} to terminate.", "pid"_attr = pid); + LOGV2_INFO(22819, "waiting for process {pid} to terminate.", "pid"_attr = pid); wait_for_pid(pid, true, &exitCode); } catch (...) { LOGV2_WARNING(22828, "process {pid} failed to terminate.", "pid"_attr = pid); @@ -1106,12 +1107,12 @@ BSONObj StopMongoProgram(const BSONObj& a, void* data) { uassert(ErrorCodes::FailedToParse, "wrong number of arguments", nFields >= 1 && nFields <= 4); uassert(ErrorCodes::BadValue, "stopMongoProgram needs a number", a.firstElement().isNumber()); int port = int(a.firstElement().number()); - LOGV2(22820, - "shell: stopping mongo program, waitpid={getWaitPid_a}", - "getWaitPid_a"_attr = getWaitPid(a)); + LOGV2_INFO(22820, + "shell: stopping mongo program, waitpid={getWaitPid_a}", + "getWaitPid_a"_attr = getWaitPid(a)); int code = killDb(port, ProcessId::fromNative(0), getSignal(a), getStopMongodOpts(a), getWaitPid(a)); - LOGV2(22821, "shell: stopped mongo program on port {port}", "port"_attr = port); + LOGV2_INFO(22821, "shell: stopped mongo program on port {port}", "port"_attr = port); return BSON("" << (double)code); } @@ -1122,7 +1123,7 @@ BSONObj StopMongoProgramByPid(const BSONObj& a, void* data) { ErrorCodes::BadValue, "stopMongoProgramByPid needs a number", a.firstElement().isNumber()); ProcessId pid = ProcessId::fromNative(int(a.firstElement().number())); int code = killDb(0, pid, getSignal(a), getStopMongodOpts(a)); - LOGV2(22822, "shell: stopped mongo program with pid {pid}", "pid"_attr = pid); + LOGV2_INFO(22822, "shell: stopped mongo program with pid {pid}", "pid"_attr = pid); return BSON("" << (double)code); } @@ -1142,10 +1143,10 @@ int KillMongoProgramInstances() { int port = registry.portForPid(pid); int code = killDb(port != -1 ? port : 0, pid, SIGTERM); if (code != EXIT_SUCCESS) { - LOGV2(22823, - "Process with pid {pid} exited with error code {code}", - "pid"_attr = pid, - "code"_attr = code); + LOGV2_INFO(22823, + "Process with pid {pid} exited with error code {code}", + "pid"_attr = pid, + "code"_attr = code); returnCode = code; } } diff --git a/src/mongo/transport/transport_layer_asio.cpp b/src/mongo/transport/transport_layer_asio.cpp index 9f0747fd488..6d2401a4c8b 100644 --- a/src/mongo/transport/transport_layer_asio.cpp +++ b/src/mongo/transport/transport_layer_asio.cpp @@ -829,16 +829,16 @@ Status validateFastOpenOnce() noexcept { kPrefixString, "reason"_attr = maybeTcpFastOpenStatus->reason()); } else { - LOGV2_INFO(4648601, - "Implicit TCP FastOpen unavailable. " - "If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, " - "and tcpFastOpenQueueSize."); + LOGV2(4648601, + "Implicit TCP FastOpen unavailable. " + "If TCP FastOpen is required, set tcpFastOpenServer, tcpFastOpenClient, " + "and tcpFastOpenQueueSize."); } maybeTcpFastOpenStatus->addContext(kPrefixString); } else { if (!tcpFastOpenIsConfigured) { - LOGV2_INFO(4648602, "Implicit TCP FastOpen in use."); + LOGV2(4648602, "Implicit TCP FastOpen in use."); } } } -- cgit v1.2.1