diff options
Diffstat (limited to 'src/mongo/client')
21 files changed, 503 insertions, 196 deletions
diff --git a/src/mongo/client/authenticate.cpp b/src/mongo/client/authenticate.cpp index 71c9aa3cbc6..9136aa19ac7 100644 --- a/src/mongo/client/authenticate.cpp +++ b/src/mongo/client/authenticate.cpp @@ -42,6 +42,7 @@ #include "mongo/db/auth/authorization_manager.h" #include "mongo/db/auth/sasl_command_constants.h" #include "mongo/db/server_options.h" +#include "mongo/logv2/log.h" #include "mongo/platform/mutex.h" #include "mongo/rpc/get_status_from_command_result.h" #include "mongo/rpc/op_msg_rpc_impls.h" @@ -150,8 +151,9 @@ Future<void> authenticateClient(const BSONObj& params, auto errorHandler = [](Status status) { if (serverGlobalParams.transitionToAuth && !ErrorCodes::isNetworkError(status)) { // If auth failed in transitionToAuth, just pretend it succeeded. - log() << "Failed to authenticate in transitionToAuth, falling back to no " - "authentication."; + LOGV2(20108, + "Failed to authenticate in transitionToAuth, falling back to no " + "authentication."); return Status::OK(); } diff --git a/src/mongo/client/connection_string_connect.cpp b/src/mongo/client/connection_string_connect.cpp index c60770e2f3f..229495c3a0e 100644 --- a/src/mongo/client/connection_string_connect.cpp +++ b/src/mongo/client/connection_string_connect.cpp @@ -38,6 +38,7 @@ #include "mongo/client/dbclient_rs.h" #include "mongo/client/mongo_uri.h" +#include "mongo/logv2/log.h" #include "mongo/util/assert_util.h" #include "mongo/util/log.h" @@ -61,11 +62,12 @@ std::unique_ptr<DBClientBase> ConnectionString::connect(StringData applicationNa auto c = std::make_unique<DBClientConnection>(true, 0, newURI); c->setSoTimeout(socketTimeout); - LOG(1) << "creating new connection to:" << server; + LOGV2_DEBUG( + 20109, 1, "creating new connection to:{server}", "server"_attr = server); if (!c->connect(server, applicationName, errmsg)) { continue; } - LOG(1) << "connected connection!"; + LOGV2_DEBUG(20110, 1, "connected connection!"); return std::move(c); } return nullptr; @@ -96,8 +98,12 @@ std::unique_ptr<DBClientBase> ConnectionString::connect(StringData applicationNa // Double-checked lock, since this will never be active during normal operation auto replacementConn = _connectHook->connect(*this, errmsg, socketTimeout); - log() << "replacing connection to " << this->toString() << " with " - << (replacementConn ? replacementConn->getServerAddress() : "(empty)"); + LOGV2(20111, + "replacing connection to {this} with " + "{replacementConn_replacementConn_getServerAddress_empty}", + "this"_attr = this->toString(), + "replacementConn_replacementConn_getServerAddress_empty"_attr = + (replacementConn ? replacementConn->getServerAddress() : "(empty)")); return replacementConn; } diff --git a/src/mongo/client/connpool.cpp b/src/mongo/client/connpool.cpp index cdb9115b40b..7c035961eb4 100644 --- a/src/mongo/client/connpool.cpp +++ b/src/mongo/client/connpool.cpp @@ -44,6 +44,7 @@ #include "mongo/client/global_conn_pool.h" #include "mongo/client/replica_set_monitor.h" #include "mongo/executor/connection_pool_stats.h" +#include "mongo/logv2/log.h" #include "mongo/stdx/chrono.h" #include "mongo/util/exit.h" #include "mongo/util/log.h" @@ -267,8 +268,10 @@ public: PoolForHost& p = _this->_pools[PoolKey(host, timeout)]; if (p.openConnections() >= _this->_maxInUse) { - log() << "Too many in-use connections; waiting until there are fewer than " - << _this->_maxInUse; + LOGV2(20112, + "Too many in-use connections; waiting until there are fewer than " + "{this_maxInUse}", + "this_maxInUse"_attr = _this->_maxInUse); p.waitForFreeConnection(timeout, lk); } else { // Drop the lock here, so we can connect without holding it. @@ -352,9 +355,13 @@ DBClientBase* DBConnectionPool::_finishCreate(const string& ident, throw; } - log() << "Successfully connected to " << ident << " (" << openConnections(ident, socketTimeout) - << " connections now open to " << ident << " with a " << socketTimeout - << " second timeout)"; + LOGV2(20113, + "Successfully connected to {ident} ({openConnections_ident_socketTimeout} connections " + "now open to {ident2} with a {socketTimeout} second timeout)", + "ident"_attr = ident, + "openConnections_ident_socketTimeout"_attr = openConnections(ident, socketTimeout), + "ident2"_attr = ident, + "socketTimeout"_attr = socketTimeout); return conn; } @@ -472,7 +479,7 @@ void DBConnectionPool::flush() { void DBConnectionPool::clear() { stdx::lock_guard<Latch> L(_mutex); - LOG(2) << "Removing connections on all pools owned by " << _name << endl; + LOGV2_DEBUG(20114, 2, "Removing connections on all pools owned by {name}", "name"_attr = _name); for (PoolMap::iterator iter = _pools.begin(); iter != _pools.end(); ++iter) { iter->second.clear(); } @@ -480,7 +487,8 @@ void DBConnectionPool::clear() { void DBConnectionPool::removeHost(const string& host) { stdx::lock_guard<Latch> L(_mutex); - LOG(2) << "Removing connections from all pools for host: " << host << endl; + LOGV2_DEBUG( + 20115, 2, "Removing connections from all pools for host: {host}", "host"_attr = host); for (PoolMap::iterator i = _pools.begin(); i != _pools.end(); ++i) { const string& poolHost = i->first.ident; if (!serverNameCompare()(host, poolHost) && !serverNameCompare()(poolHost, host)) { diff --git a/src/mongo/client/dbclient_base.cpp b/src/mongo/client/dbclient_base.cpp index 3654b2f89cc..5ba32922a6f 100644 --- a/src/mongo/client/dbclient_base.cpp +++ b/src/mongo/client/dbclient_base.cpp @@ -56,6 +56,7 @@ #include "mongo/db/wire_version.h" #include "mongo/executor/remote_command_request.h" #include "mongo/executor/remote_command_response.h" +#include "mongo/logv2/log.h" #include "mongo/platform/mutex.h" #include "mongo/rpc/factory.h" #include "mongo/rpc/get_status_from_command_result.h" @@ -469,7 +470,7 @@ Status DBClientBase::authenticateInternalUser() { ScopedMetadataWriterRemover remover{this}; if (!auth::isInternalAuthSet()) { if (!serverGlobalParams.quiet.load()) { - log() << "ERROR: No authentication parameters set for internal user"; + LOGV2(20116, "ERROR: No authentication parameters set for internal user"); } return {ErrorCodes::AuthenticationFailed, "No authentication parameters set for internal user"}; @@ -491,8 +492,10 @@ Status DBClientBase::authenticateInternalUser() { } if (serverGlobalParams.quiet.load()) { - log() << "can't authenticate to " << toString() - << " as internal user, error: " << status.reason(); + LOGV2(20117, + "can't authenticate to {} as internal user, error: {status_reason}", + ""_attr = toString(), + "status_reason"_attr = status.reason()); } return status; @@ -892,7 +895,10 @@ void DBClientBase::dropIndex(const string& ns, const string& indexName) { if (!runCommand(nsToDatabase(ns), BSON("dropIndexes" << nsToCollectionSubstring(ns) << "index" << indexName), info)) { - LOG(_logLevel) << "dropIndex failed: " << info << endl; + LOGV2_DEBUG(20118, + logSeverityV1toV2(_logLevel).toInt(), + "dropIndex failed: {info}", + "info"_attr = info); uassert(10007, "dropIndex failed", 0); } } diff --git a/src/mongo/client/dbclient_connection.cpp b/src/mongo/client/dbclient_connection.cpp index 5a9d29859cc..c7e2a18021c 100644 --- a/src/mongo/client/dbclient_connection.cpp +++ b/src/mongo/client/dbclient_connection.cpp @@ -65,6 +65,7 @@ #include "mongo/db/wire_version.h" #include "mongo/executor/remote_command_request.h" #include "mongo/executor/remote_command_response.h" +#include "mongo/logv2/log.h" #include "mongo/platform/mutex.h" #include "mongo/rpc/get_status_from_command_result.h" #include "mongo/rpc/metadata/client_metadata.h" @@ -341,7 +342,9 @@ Status DBClientConnection::connect(const HostAndPort& serverAddress, StringData auto validateStatus = rpc::validateWireVersion(WireSpec::instance().outgoing, swProtocolSet.getValue().version); if (!validateStatus.isOK()) { - warning() << "remote host has incompatible wire version: " << validateStatus; + LOGV2_WARNING(20126, + "remote host has incompatible wire version: {validateStatus}", + "validateStatus"_attr = validateStatus); return validateStatus; } @@ -424,7 +427,7 @@ Status DBClientConnection::connectSocketOnly(const HostAndPort& serverAddress) { _lastConnectivityCheck = Date_t::now(); _session->setTimeout(_socketTimeout); _session->setTags(_tagMask); - LOG(1) << "connected to server " << toString(); + LOGV2_DEBUG(20119, 1, "connected to server {}", ""_attr = toString()); return Status::OK(); } @@ -551,12 +554,19 @@ void DBClientConnection::_checkConnection() { // Don't hammer reconnects, backoff if needed sleepFor(_autoReconnectBackoff.nextSleep()); - LOG(_logLevel) << "trying reconnect to " << toString() << endl; + LOGV2_DEBUG(20120, + logSeverityV1toV2(_logLevel).toInt(), + "trying reconnect to {}", + ""_attr = toString()); string errmsg; auto connectStatus = connect(_serverAddress, _applicationName); if (!connectStatus.isOK()) { _markFailed(kSetFlag); - LOG(_logLevel) << "reconnect " << toString() << " failed " << errmsg << endl; + LOGV2_DEBUG(20121, + logSeverityV1toV2(_logLevel).toInt(), + "reconnect {} failed {errmsg}", + ""_attr = toString(), + "errmsg"_attr = errmsg); if (connectStatus == ErrorCodes::IncompatibleCatalogManager) { uassertStatusOK(connectStatus); // Will always throw } else { @@ -564,7 +574,8 @@ void DBClientConnection::_checkConnection() { } } - LOG(_logLevel) << "reconnect " << toString() << " ok" << endl; + LOGV2_DEBUG( + 20122, logSeverityV1toV2(_logLevel).toInt(), "reconnect {} ok", ""_attr = toString()); if (_internalAuthOnReconnect) { uassertStatusOK(authenticateInternalUser()); } else { @@ -572,10 +583,16 @@ void DBClientConnection::_checkConnection() { try { DBClientConnection::_auth(kv.second); } catch (ExceptionFor<ErrorCodes::AuthenticationFailed>& ex) { - LOG(_logLevel) << "reconnect: auth failed " - << kv.second[auth::getSaslCommandUserDBFieldName()] - << kv.second[auth::getSaslCommandUserFieldName()] << ' ' << ex.what() - << std::endl; + LOGV2_DEBUG(20123, + logSeverityV1toV2(_logLevel).toInt(), + "reconnect: auth failed " + "{kv_second_auth_getSaslCommandUserDBFieldName}{kv_second_auth_" + "getSaslCommandUserFieldName} {ex_what}", + "kv_second_auth_getSaslCommandUserDBFieldName"_attr = + kv.second[auth::getSaslCommandUserDBFieldName()], + "kv_second_auth_getSaslCommandUserFieldName"_attr = + kv.second[auth::getSaslCommandUserFieldName()], + "ex_what"_attr = ex.what()); } } } @@ -728,8 +745,10 @@ bool DBClientConnection::call(Message& toSend, auto sinkStatus = _session->sinkMessage(swm.getValue()); if (!sinkStatus.isOK()) { - log() << "DBClientConnection failed to send message to " << getServerAddress() << " - " - << redact(sinkStatus); + LOGV2(20124, + "DBClientConnection failed to send message to {getServerAddress} - {sinkStatus}", + "getServerAddress"_attr = getServerAddress(), + "sinkStatus"_attr = redact(sinkStatus)); return maybeThrow(sinkStatus); } @@ -737,8 +756,11 @@ bool DBClientConnection::call(Message& toSend, if (swm.isOK()) { response = std::move(swm.getValue()); } else { - log() << "DBClientConnection failed to receive message from " << getServerAddress() << " - " - << redact(swm.getStatus()); + LOGV2(20125, + "DBClientConnection failed to receive message from {getServerAddress} - " + "{swm_getStatus}", + "getServerAddress"_attr = getServerAddress(), + "swm_getStatus"_attr = redact(swm.getStatus())); return maybeThrow(swm.getStatus()); } diff --git a/src/mongo/client/dbclient_cursor.cpp b/src/mongo/client/dbclient_cursor.cpp index 7639abe1ec6..4fa665c5e14 100644 --- a/src/mongo/client/dbclient_cursor.cpp +++ b/src/mongo/client/dbclient_cursor.cpp @@ -46,6 +46,7 @@ #include "mongo/db/query/cursor_response.h" #include "mongo/db/query/getmore_request.h" #include "mongo/db/query/query_request.h" +#include "mongo/logv2/log.h" #include "mongo/rpc/factory.h" #include "mongo/rpc/get_status_from_command_result.h" #include "mongo/rpc/metadata.h" @@ -203,13 +204,13 @@ bool DBClientCursor::init() { _client->call(toSend, reply, true, &_originalHost); } catch (const DBException&) { // log msg temp? - log() << "DBClientCursor::init call() failed" << endl; + LOGV2(20127, "DBClientCursor::init call() failed"); // We always want to throw on network exceptions. throw; } if (reply.empty()) { // log msg temp? - log() << "DBClientCursor::init message from call() was empty" << endl; + LOGV2(20128, "DBClientCursor::init message from call() was empty"); return false; } dataReceived(reply); @@ -235,9 +236,11 @@ bool DBClientCursor::initLazyFinish(bool& retry) { // If we get a bad response, return false if (!recvStatus.isOK() || reply.empty()) { if (!recvStatus.isOK()) - log() << "DBClientCursor::init lazy say() failed: " << redact(recvStatus) << endl; + LOGV2(20129, + "DBClientCursor::init lazy say() failed: {recvStatus}", + "recvStatus"_attr = redact(recvStatus)); if (reply.empty()) - log() << "DBClientCursor::init message from say() was empty" << endl; + LOGV2(20130, "DBClientCursor::init message from say() was empty"); _client->checkResponse({}, true, &retry, &_lazyHost); diff --git a/src/mongo/client/dbclient_cursor_test.cpp b/src/mongo/client/dbclient_cursor_test.cpp index cf4864e70f3..41641170333 100644 --- a/src/mongo/client/dbclient_cursor_test.cpp +++ b/src/mongo/client/dbclient_cursor_test.cpp @@ -27,11 +27,15 @@ * it in the license file. */ +#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault + #include "mongo/client/dbclient_connection.h" #include "mongo/client/dbclient_cursor.h" #include "mongo/db/query/cursor_response.h" +#include "mongo/logv2/log.h" #include "mongo/unittest/unittest.h" #include "mongo/util/assert_util.h" +#include "mongo/util/log.h" namespace mongo { namespace { @@ -78,7 +82,7 @@ public: // No-op. void killCursor(const NamespaceString& ns, long long cursorID) override { - unittest::log() << "Killing cursor in DBClientConnectionForTest"; + LOGV2(20131, "Killing cursor in DBClientConnectionForTest"); } void setSupportedProtocols(rpc::ProtocolSet protocols) { diff --git a/src/mongo/client/dbclient_rs.cpp b/src/mongo/client/dbclient_rs.cpp index 25fd973fc8f..b71f63fa2ec 100644 --- a/src/mongo/client/dbclient_rs.cpp +++ b/src/mongo/client/dbclient_rs.cpp @@ -45,6 +45,7 @@ #include "mongo/db/auth/sasl_command_constants.h" #include "mongo/db/dbmessage.h" #include "mongo/db/jsobj.h" +#include "mongo/logv2/log.h" #include "mongo/util/log.h" namespace mongo { @@ -158,9 +159,10 @@ ReplicaSetMonitorPtr DBClientReplicaSet::_getMonitor() { // This can't throw an exception because it is called in the destructor of ScopedDbConnection string DBClientReplicaSet::getServerAddress() const { if (!_rsm) { - warning() << "Trying to get server address for DBClientReplicaSet, but no " - "ReplicaSetMonitor exists for " - << _setName; + LOGV2_WARNING(20147, + "Trying to get server address for DBClientReplicaSet, but no " + "ReplicaSetMonitor exists for {setName}", + "setName"_attr = _setName); return str::stream() << _setName << "/"; } return _rsm->getServerAddress(); @@ -358,7 +360,10 @@ void DBClientReplicaSet::_authConnection(DBClientConnection* conn) { if (_internalAuthRequested) { auto status = conn->authenticateInternalUser(); if (!status.isOK()) { - warning() << "cached auth failed for set " << _setName << ": " << status; + LOGV2_WARNING(20148, + "cached auth failed for set {setName}: {status}", + "setName"_attr = _setName, + "status"_attr = status); } return; } @@ -367,9 +372,15 @@ void DBClientReplicaSet::_authConnection(DBClientConnection* conn) { try { conn->auth(i->second); } catch (const AssertionException&) { - warning() << "cached auth failed for set: " << _setName - << " db: " << i->second[saslCommandUserDBFieldName].str() - << " user: " << i->second[saslCommandUserFieldName].str() << endl; + LOGV2_WARNING(20149, + "cached auth failed for set: {setName} db: " + "{i_second_saslCommandUserDBFieldName_str} user: " + "{i_second_saslCommandUserFieldName_str}", + "setName"_attr = _setName, + "i_second_saslCommandUserDBFieldName_str"_attr = + i->second[saslCommandUserDBFieldName].str(), + "i_second_saslCommandUserFieldName_str"_attr = + i->second[saslCommandUserFieldName].str()); } } } @@ -381,8 +392,11 @@ void DBClientReplicaSet::logoutAll(DBClientConnection* conn) { try { conn->logout(i->first, response); } catch (const AssertionException& ex) { - warning() << "Failed to logout: " << conn->getServerAddress() << " on db: " << i->first - << causedBy(redact(ex)); + LOGV2_WARNING(20150, + "Failed to logout: {conn_getServerAddress} on db: {i_first}{causedBy_ex}", + "conn_getServerAddress"_attr = conn->getServerAddress(), + "i_first"_attr = i->first, + "causedBy_ex"_attr = causedBy(redact(ex))); } } } @@ -416,7 +430,10 @@ Status DBClientReplicaSet::_runAuthLoop(Authenticate authCb) { const auto readPref = std::make_shared<ReadPreferenceSetting>(ReadPreference::PrimaryPreferred, TagSet()); - LOG(3) << "dbclient_rs authentication of " << _getMonitor()->getName(); + LOGV2_DEBUG(20132, + 3, + "dbclient_rs authentication of {getMonitor_getName}", + "getMonitor_getName"_attr = _getMonitor()->getName()); // NOTE that we retry MAX_RETRY + 1 times, since we're always primary preferred we don't // fallback to the primary. @@ -533,14 +550,19 @@ unique_ptr<DBClientCursor> DBClientReplicaSet::query(const NamespaceStringOrUUID invariant(nsOrUuid.nss()); const string ns = nsOrUuid.nss()->ns(); if (_isSecondaryQuery(ns, query.obj, *readPref)) { - LOG(3) << "dbclient_rs query using secondary or tagged node selection in " - << _getMonitor()->getName() << ", read pref is " << readPref->toString() - << " (primary : " - << (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]") - << ", lastTagged : " - << (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() - : "[not cached]") - << ")" << endl; + LOGV2_DEBUG(20133, + 3, + "dbclient_rs query using secondary or tagged node selection in " + "{getMonitor_getName}, read pref is {readPref} (primary : " + "{master_get_nullptr_master_getServerAddress_not_cached}, lastTagged : " + "{lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached})", + "getMonitor_getName"_attr = _getMonitor()->getName(), + "readPref"_attr = readPref->toString(), + "master_get_nullptr_master_getServerAddress_not_cached"_attr = + (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]"), + "lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached"_attr = + (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() + : "[not cached]")); string lastNodeErrMsg; @@ -573,7 +595,10 @@ unique_ptr<DBClientCursor> DBClientReplicaSet::query(const NamespaceStringOrUUID uasserted(16370, assertMsg.str()); } - LOG(3) << "dbclient_rs query to primary node in " << _getMonitor()->getName() << endl; + LOGV2_DEBUG(20134, + 3, + "dbclient_rs query to primary node in {getMonitor_getName}", + "getMonitor_getName"_attr = _getMonitor()->getName()); return checkMaster()->query( nsOrUuid, query, nToReturn, nToSkip, fieldsToReturn, queryOptions, batchSize); @@ -585,14 +610,19 @@ BSONObj DBClientReplicaSet::findOne(const string& ns, int queryOptions) { shared_ptr<ReadPreferenceSetting> readPref(_extractReadPref(query.obj, queryOptions)); if (_isSecondaryQuery(ns, query.obj, *readPref)) { - LOG(3) << "dbclient_rs findOne using secondary or tagged node selection in " - << _getMonitor()->getName() << ", read pref is " << readPref->toString() - << " (primary : " - << (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]") - << ", lastTagged : " - << (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() - : "[not cached]") - << ")" << endl; + LOGV2_DEBUG(20135, + 3, + "dbclient_rs findOne using secondary or tagged node selection in " + "{getMonitor_getName}, read pref is {readPref} (primary : " + "{master_get_nullptr_master_getServerAddress_not_cached}, lastTagged : " + "{lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached})", + "getMonitor_getName"_attr = _getMonitor()->getName(), + "readPref"_attr = readPref->toString(), + "master_get_nullptr_master_getServerAddress_not_cached"_attr = + (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]"), + "lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached"_attr = + (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() + : "[not cached]")); string lastNodeErrMsg; @@ -622,7 +652,10 @@ BSONObj DBClientReplicaSet::findOne(const string& ns, uasserted(16379, assertMsg.str()); } - LOG(3) << "dbclient_rs findOne to primary node in " << _getMonitor()->getName() << endl; + LOGV2_DEBUG(20136, + 3, + "dbclient_rs findOne to primary node in {getMonitor_getName}", + "getMonitor_getName"_attr = _getMonitor()->getName()); return checkMaster()->findOne(ns, query, fieldsToReturn, queryOptions); } @@ -682,7 +715,10 @@ void DBClientReplicaSet::isntSecondary() { DBClientConnection* DBClientReplicaSet::selectNodeUsingTags( shared_ptr<ReadPreferenceSetting> readPref) { if (checkLastHost(readPref.get())) { - LOG(3) << "dbclient_rs selecting compatible last used node " << _lastSlaveOkHost; + LOGV2_DEBUG(20137, + 3, + "dbclient_rs selecting compatible last used node {lastSlaveOkHost}", + "lastSlaveOkHost"_attr = _lastSlaveOkHost); return _lastSlaveOkConn.get(); } @@ -691,8 +727,11 @@ DBClientConnection* DBClientReplicaSet::selectNodeUsingTags( auto selectedNodeStatus = monitor->getHostOrRefresh(*readPref).getNoThrow(); if (!selectedNodeStatus.isOK()) { - LOG(3) << "dbclient_rs no compatible node found" - << causedBy(redact(selectedNodeStatus.getStatus())); + LOGV2_DEBUG(20138, + 3, + "dbclient_rs no compatible node found{causedBy_selectedNodeStatus_getStatus}", + "causedBy_selectedNodeStatus_getStatus"_attr = + causedBy(redact(selectedNodeStatus.getStatus()))); return nullptr; } @@ -712,7 +751,10 @@ DBClientConnection* DBClientReplicaSet::selectNodeUsingTags( if (monitor->isPrimary(selectedNode)) { checkMaster(); - LOG(3) << "dbclient_rs selecting primary node " << selectedNode << endl; + LOGV2_DEBUG(20139, + 3, + "dbclient_rs selecting primary node {selectedNode}", + "selectedNode"_attr = selectedNode); _lastSlaveOkConn = _master; @@ -748,7 +790,10 @@ DBClientConnection* DBClientReplicaSet::selectNodeUsingTags( // Mongos pooled connections are authenticated through ShardingConnectionHook::onCreate() } - LOG(3) << "dbclient_rs selecting node " << _lastSlaveOkHost << endl; + LOGV2_DEBUG(20140, + 3, + "dbclient_rs selecting node {lastSlaveOkHost}", + "lastSlaveOkHost"_attr = _lastSlaveOkHost); return _lastSlaveOkConn.get(); } @@ -766,14 +811,20 @@ void DBClientReplicaSet::say(Message& toSend, bool isRetry, string* actualServer shared_ptr<ReadPreferenceSetting> readPref(_extractReadPref(qm.query, qm.queryOptions)); if (_isSecondaryQuery(qm.ns, qm.query, *readPref)) { - LOG(3) << "dbclient_rs say using secondary or tagged node selection in " - << _getMonitor()->getName() << ", read pref is " << readPref->toString() - << " (primary : " - << (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]") - << ", lastTagged : " - << (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() - : "[not cached]") - << ")" << endl; + LOGV2_DEBUG( + 20141, + 3, + "dbclient_rs say using secondary or tagged node selection in {getMonitor_getName}, " + "read pref is {readPref} (primary : " + "{master_get_nullptr_master_getServerAddress_not_cached}, lastTagged : " + "{lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached})", + "getMonitor_getName"_attr = _getMonitor()->getName(), + "readPref"_attr = readPref->toString(), + "master_get_nullptr_master_getServerAddress_not_cached"_attr = + (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]"), + "lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached"_attr = + (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() + : "[not cached]")); string lastNodeErrMsg; @@ -818,7 +869,10 @@ void DBClientReplicaSet::say(Message& toSend, bool isRetry, string* actualServer } } - LOG(3) << "dbclient_rs say to primary node in " << _getMonitor()->getName() << endl; + LOGV2_DEBUG(20142, + 3, + "dbclient_rs say to primary node in {getMonitor_getName}", + "getMonitor_getName"_attr = _getMonitor()->getName()); DBClientConnection* master = checkMaster(); if (actualServer) @@ -840,8 +894,10 @@ Status DBClientReplicaSet::recv(Message& m, int lastRequestId) { try { return _lazyState._lastClient->recv(m, lastRequestId); } catch (DBException& e) { - log() << "could not receive data from " << _lazyState._lastClient->toString() - << causedBy(redact(e)); + LOGV2(20143, + "could not receive data from {lazyState_lastClient}{causedBy_e}", + "lazyState_lastClient"_attr = _lazyState._lastClient->toString(), + "causedBy_e"_attr = causedBy(redact(e))); return e.toStatus(); } } @@ -891,17 +947,20 @@ void DBClientReplicaSet::checkResponse(const std::vector<BSONObj>& batch, } else if (_lazyState._lastClient == _master.get()) { isntMaster(); } else { - warning() << "passed " << redact(dataObj) << " but last rs client " - << _lazyState._lastClient->toString() << " is not master or secondary" - << endl; + LOGV2_WARNING(20151, + "passed {dataObj} but last rs client {lazyState_lastClient} is not " + "master or secondary", + "dataObj"_attr = redact(dataObj), + "lazyState_lastClient"_attr = _lazyState._lastClient->toString()); } if (_lazyState._retries < static_cast<int>(MAX_RETRY)) { _lazyState._retries++; *retry = true; } else { - log() << "too many retries (" << _lazyState._retries - << "), could not get data from replica set" << endl; + LOGV2(20144, + "too many retries ({lazyState_retries}), could not get data from replica set", + "lazyState_retries"_attr = _lazyState._retries); } } } else if (_lazyState._lastOp == dbQuery) { @@ -997,14 +1056,20 @@ bool DBClientReplicaSet::call(Message& toSend, shared_ptr<ReadPreferenceSetting> readPref(_extractReadPref(qm.query, qm.queryOptions)); if (_isSecondaryQuery(ns, qm.query, *readPref)) { - LOG(3) << "dbclient_rs call using secondary or tagged node selection in " - << _getMonitor()->getName() << ", read pref is " << readPref->toString() - << " (primary : " - << (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]") - << ", lastTagged : " - << (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() - : "[not cached]") - << ")" << endl; + LOGV2_DEBUG( + 20145, + 3, + "dbclient_rs call using secondary or tagged node selection in " + "{getMonitor_getName}, read pref is {readPref} (primary : " + "{master_get_nullptr_master_getServerAddress_not_cached}, lastTagged : " + "{lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached})", + "getMonitor_getName"_attr = _getMonitor()->getName(), + "readPref"_attr = readPref->toString(), + "master_get_nullptr_master_getServerAddress_not_cached"_attr = + (_master.get() != nullptr ? _master->getServerAddress() : "[not cached]"), + "lastSlaveOkConn_get_nullptr_lastSlaveOkConn_getServerAddress_not_cached"_attr = + (_lastSlaveOkConn.get() != nullptr ? _lastSlaveOkConn->getServerAddress() + : "[not cached]")); for (size_t retry = 0; retry < MAX_RETRY; retry++) { try { @@ -1034,7 +1099,10 @@ bool DBClientReplicaSet::call(Message& toSend, } } - LOG(3) << "dbclient_rs call to primary node in " << _getMonitor()->getName() << endl; + LOGV2_DEBUG(20146, + 3, + "dbclient_rs call to primary node in {getMonitor_getName}", + "getMonitor_getName"_attr = _getMonitor()->getName()); DBClientConnection* m = checkMaster(); if (actualServer) diff --git a/src/mongo/client/mongo_uri_test.cpp b/src/mongo/client/mongo_uri_test.cpp index e80abbf5e6b..badc6cf3a96 100644 --- a/src/mongo/client/mongo_uri_test.cpp +++ b/src/mongo/client/mongo_uri_test.cpp @@ -27,6 +27,8 @@ * it in the license file. */ +#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault + #include "mongo/platform/basic.h" #include <fstream> @@ -39,6 +41,8 @@ #include "mongo/db/service_context_test_fixture.h" #include "mongo/unittest/unittest.h" +#include "mongo/logv2/log.h" +#include "mongo/util/log.h" #include <boost/filesystem/operations.hpp> #include <boost/optional.hpp> #include <boost/optional/optional_io.hpp> @@ -84,11 +88,16 @@ void compareOptions(size_t lineNumber, for (std::size_t i = 0; i < std::min(options.size(), expectedOptions.size()); ++i) { if (options[i] != expectedOptions[i]) { - unittest::log() << "Option: \"tolower(" << options[i].first.original() - << ")=" << options[i].second << "\" doesn't equal: \"tolower(" - << expectedOptions[i].first.original() - << ")=" << expectedOptions[i].second << "\"" - << " data on line: " << lineNumber << std::endl; + LOGV2( + 20152, + "Option: \"tolower({options_i_first_original})={options_i_second}\" doesn't equal: " + "\"tolower({expectedOptions_i_first_original})={expectedOptions_i_second}\" data " + "on line: {lineNumber}", + "options_i_first_original"_attr = options[i].first.original(), + "options_i_second"_attr = options[i].second, + "expectedOptions_i_first_original"_attr = expectedOptions[i].first.original(), + "expectedOptions_i_second"_attr = expectedOptions[i].second, + "lineNumber"_attr = lineNumber); std::cerr << "Failing URI: \"" << uri << "\"" << " data on line: " << lineNumber << std::endl; ASSERT(false); @@ -594,7 +603,7 @@ std::string returnStringFromElementOrNull(BSONElement element) { // Helper method to take a valid test case, parse() it, and assure the output is correct void testValidURIFormat(URITestCase testCase) { - unittest::log() << "Testing URI: " << testCase.URI << '\n'; + LOGV2(20153, "Testing URI: {testCase_URI}", "testCase_URI"_attr = testCase.URI); std::string errMsg; const auto cs_status = MongoURI::parse(testCase.URI); ASSERT_OK(cs_status); @@ -622,7 +631,7 @@ TEST(MongoURI, InvalidURIs) { for (size_t i = 0; i != numCases; ++i) { const InvalidURITestCase testCase = invalidCases[i]; - unittest::log() << "Testing URI: " << testCase.URI << '\n'; + LOGV2(20154, "Testing URI: {testCase_URI}", "testCase_URI"_attr = testCase.URI); auto cs_status = MongoURI::parse(testCase.URI); ASSERT_NOT_OK(cs_status); if (testCase.code) { @@ -704,7 +713,7 @@ TEST(MongoURI, specTests) { if (!valid) { // This uri string is invalid --> parse the uri and ensure it fails const InvalidURITestCase testCase = InvalidURITestCase{uri}; - unittest::log() << "Testing URI: " << testCase.URI << '\n'; + LOGV2(20155, "Testing URI: {testCase_URI}", "testCase_URI"_attr = testCase.URI); auto cs_status = MongoURI::parse(testCase.URI); ASSERT_NOT_OK(cs_status); } else { diff --git a/src/mongo/client/remote_command_retry_scheduler_test.cpp b/src/mongo/client/remote_command_retry_scheduler_test.cpp index fa887a6eb9d..03bcbd44fe8 100644 --- a/src/mongo/client/remote_command_retry_scheduler_test.cpp +++ b/src/mongo/client/remote_command_retry_scheduler_test.cpp @@ -27,6 +27,8 @@ * it in the license file. */ +#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault + #include "mongo/platform/basic.h" #include <memory> @@ -39,9 +41,11 @@ #include "mongo/executor/remote_command_response.h" #include "mongo/executor/task_executor.h" #include "mongo/executor/thread_pool_task_executor_test_fixture.h" +#include "mongo/logv2/log.h" #include "mongo/unittest/task_executor_proxy.h" #include "mongo/unittest/unittest.h" #include "mongo/util/assert_util.h" +#include "mongo/util/log.h" #include "mongo/util/net/hostandport.h" namespace { @@ -555,7 +559,9 @@ TEST_F(RemoteCommandRetrySchedulerTest, request, [&result, sharedCallbackData](const executor::TaskExecutor::RemoteCommandCallbackArgs& rcba) { - unittest::log() << "setting result to " << rcba.response.status; + LOGV2(20156, + "setting result to {rcba_response_status}", + "rcba_response_status"_attr = rcba.response.status); result = rcba.response.status; }, std::move(policy)); diff --git a/src/mongo/client/remote_command_targeter_rs.cpp b/src/mongo/client/remote_command_targeter_rs.cpp index 97eae89da0d..d5640d3a4ae 100644 --- a/src/mongo/client/remote_command_targeter_rs.cpp +++ b/src/mongo/client/remote_command_targeter_rs.cpp @@ -38,6 +38,7 @@ #include "mongo/client/read_preference.h" #include "mongo/client/replica_set_monitor.h" #include "mongo/db/operation_context.h" +#include "mongo/logv2/log.h" #include "mongo/util/assert_util.h" #include "mongo/util/log.h" #include "mongo/util/net/hostandport.h" @@ -52,9 +53,15 @@ RemoteCommandTargeterRS::RemoteCommandTargeterRS(const std::string& rsName, std::set<HostAndPort> seedServers(seedHosts.begin(), seedHosts.end()); _rsMonitor = ReplicaSetMonitor::createIfNeeded(rsName, seedServers); - LOG(1) << "Started targeter for " - << ConnectionString::forReplicaSet( - rsName, std::vector<HostAndPort>(seedServers.begin(), seedServers.end())); + LOGV2_DEBUG( + 20157, + 1, + "Started targeter for " + "{ConnectionString_forReplicaSet_rsName_std_vector_HostAndPort_seedServers_begin_" + "seedServers_end}", + "ConnectionString_forReplicaSet_rsName_std_vector_HostAndPort_seedServers_begin_seedServers_end"_attr = + ConnectionString::forReplicaSet( + rsName, std::vector<HostAndPort>(seedServers.begin(), seedServers.end()))); } ConnectionString RemoteCommandTargeterRS::connectionString() { diff --git a/src/mongo/client/replica_set_change_notifier.cpp b/src/mongo/client/replica_set_change_notifier.cpp index 3f23418c08e..b0a35057dd9 100644 --- a/src/mongo/client/replica_set_change_notifier.cpp +++ b/src/mongo/client/replica_set_change_notifier.cpp @@ -33,6 +33,7 @@ #include "mongo/client/replica_set_change_notifier.h" +#include "mongo/logv2/log.h" #include "mongo/util/fail_point.h" #include "mongo/util/log.h" #include "mongo/util/stacktrace.h" @@ -54,7 +55,7 @@ void ReplicaSetChangeNotifier::_removeListener(Listener* listener) { } void ReplicaSetChangeNotifier::onFoundSet(const std::string& name) noexcept { - LOG(2) << "Signaling found set " << name; + LOGV2_DEBUG(20158, 2, "Signaling found set {name}", "name"_attr = name); stdx::unique_lock<Latch> lk(_mutex); @@ -69,7 +70,10 @@ void ReplicaSetChangeNotifier::onFoundSet(const std::string& name) noexcept { } void ReplicaSetChangeNotifier::onPossibleSet(ConnectionString connectionString) noexcept { - LOG(2) << "Signaling possible set " << connectionString; + LOGV2_DEBUG(20159, + 2, + "Signaling possible set {connectionString}", + "connectionString"_attr = connectionString); const auto& name = connectionString.getSetName(); @@ -96,7 +100,11 @@ void ReplicaSetChangeNotifier::onPossibleSet(ConnectionString connectionString) void ReplicaSetChangeNotifier::onConfirmedSet(ConnectionString connectionString, HostAndPort primary, std::set<HostAndPort> passives) noexcept { - LOG(2) << "Signaling confirmed set " << connectionString << " with primary " << primary; + LOGV2_DEBUG(20160, + 2, + "Signaling confirmed set {connectionString} with primary {primary}", + "connectionString"_attr = connectionString, + "primary"_attr = primary); const auto& name = connectionString.getSetName(); stdx::unique_lock<Latch> lk(_mutex); @@ -121,7 +129,7 @@ void ReplicaSetChangeNotifier::onConfirmedSet(ConnectionString connectionString, } void ReplicaSetChangeNotifier::onDroppedSet(const std::string& name) noexcept { - LOG(2) << "Signaling dropped set " << name; + LOGV2_DEBUG(20161, 2, "Signaling dropped set {name}", "name"_attr = name); stdx::unique_lock<Latch> lk(_mutex); diff --git a/src/mongo/client/replica_set_monitor.cpp b/src/mongo/client/replica_set_monitor.cpp index 1098b74b047..e5604439330 100644 --- a/src/mongo/client/replica_set_monitor.cpp +++ b/src/mongo/client/replica_set_monitor.cpp @@ -45,6 +45,7 @@ #include "mongo/db/operation_context.h" #include "mongo/db/repl/bson_extract_optime.h" #include "mongo/db/server_options.h" +#include "mongo/logv2/log.h" #include "mongo/platform/atomic_word.h" #include "mongo/platform/mutex.h" #include "mongo/stdx/condition_variable.h" @@ -195,7 +196,8 @@ ReplicaSetMonitor::ReplicaSetMonitor(const MongoURI& uri) void ReplicaSetMonitor::init() { if (areRefreshRetriesDisabledForTest.load()) { // This is for MockReplicaSet. Those tests want to control when scanning happens. - warning() << "*** Not starting background refresh because refresh retries are disabled."; + LOGV2_WARNING(20180, + "*** Not starting background refresh because refresh retries are disabled."); return; } @@ -245,7 +247,10 @@ void ReplicaSetMonitor::SetState::rescheduleRefresh(SchedulingStrategy strategy) } if (isDropped) { // already removed so no need to refresh - LOG(1) << "Stopping refresh for replica set " << name << " because it's removed"; + LOGV2_DEBUG(20162, + 1, + "Stopping refresh for replica set {name} because it's removed", + "name"_attr = name); return; } @@ -270,7 +275,10 @@ void ReplicaSetMonitor::SetState::rescheduleRefresh(SchedulingStrategy strategy) } nextScanTime = possibleNextScanTime; - LOG(1) << "Next replica set scan scheduled for " << nextScanTime; + LOGV2_DEBUG(20163, + 1, + "Next replica set scan scheduled for {nextScanTime}", + "nextScanTime"_attr = nextScanTime); auto swHandle = scheduleWorkAt(nextScanTime, [this](const CallbackArgs& cbArgs) { if (cbArgs.myHandle != refresherHandle) return; // We've been replaced! @@ -286,13 +294,18 @@ void ReplicaSetMonitor::SetState::rescheduleRefresh(SchedulingStrategy strategy) }); if (ErrorCodes::isShutdownError(swHandle.getStatus().code())) { - LOG(1) << "Cant schedule refresh for " << name << ". Executor shutdown in progress"; + LOGV2_DEBUG(20164, + 1, + "Cant schedule refresh for {name}. Executor shutdown in progress", + "name"_attr = name); return; } if (!swHandle.isOK()) { - severe() << "Can't continue refresh for replica set " << name << " due to " - << redact(swHandle.getStatus()); + LOGV2_FATAL(20184, + "Can't continue refresh for replica set {name} due to {swHandle_getStatus}", + "name"_attr = name, + "swHandle_getStatus"_attr = redact(swHandle.getStatus())); fassertFailed(40140); } @@ -552,8 +565,11 @@ void Refresher::scheduleNetworkRequests() { } if (!swHandle.isOK()) { - severe() << "Can't continue scan for replica set " << _set->name << " due to " - << redact(swHandle.getStatus()); + LOGV2_FATAL( + 20185, + "Can't continue scan for replica set {set_name} due to {swHandle_getStatus}", + "set_name"_attr = _set->name, + "swHandle_getStatus"_attr = redact(swHandle.getStatus())); fassertFailed(31176); } @@ -649,7 +665,8 @@ Refresher::NextStep Refresher::getNextStep() { if (_scan->hostsToScan.empty()) { // We've tried all hosts we can, so nothing more to do in this round. if (!_scan->foundUpMaster) { - warning() << "Unable to reach primary for set " << _set->name; + LOGV2_WARNING( + 20181, "Unable to reach primary for set {set_name}", "set_name"_attr = _set->name); // Since we've talked to everyone we could but still didn't find a primary, we // do the best we can, and assume all unconfirmedReplies are actually from nodes @@ -682,10 +699,12 @@ Refresher::NextStep Refresher::getNextStep() { } else { auto nScans = _set->consecutiveFailedScans++; if (nScans <= 10 || nScans % 10 == 0) { - log() << "Cannot reach any nodes for set " << _set->name - << ". Please check network connectivity and the status of the set. " - << "This has happened for " << _set->consecutiveFailedScans - << " checks in a row."; + LOGV2(20165, + "Cannot reach any nodes for set {set_name}. Please check network " + "connectivity and the status of the set. This has happened for " + "{set_consecutiveFailedScans} checks in a row.", + "set_name"_attr = _set->name, + "set_consecutiveFailedScans"_attr = _set->consecutiveFailedScans); } } @@ -693,8 +712,11 @@ Refresher::NextStep Refresher::getNextStep() { _set->currentScan.reset(); _set->notify(); - LOG(1) << "Refreshing replica set " << _set->name << " took " << _scan->timer.millis() - << "ms"; + LOGV2_DEBUG(20166, + 1, + "Refreshing replica set {set_name} took {scan_timer_millis}ms", + "set_name"_attr = _set->name, + "scan_timer_millis"_attr = _scan->timer.millis()); return NextStep(NextStep::DONE); } @@ -732,9 +754,13 @@ void Refresher::receivedIsMaster(const HostAndPort& from, _scan->possibleNodes.insert(reply.members.begin(), reply.members.end()); } } else { - error() << "replset name mismatch: expected \"" << _set->name << "\", " - << "but remote node " << from << " has replset name \"" << reply.setName << "\"" - << ", ismaster: " << replyObj; + LOGV2_ERROR(20183, + "replset name mismatch: expected \"{set_name}\", but remote node {from} " + "has replset name \"{reply_setName}\", ismaster: {replyObj}", + "set_name"_attr = _set->name, + "from"_attr = from, + "reply_setName"_attr = reply.setName, + "replyObj"_attr = replyObj); } failedHost(from, @@ -861,8 +887,12 @@ Status Refresher::receivedIsMasterFromMaster(const HostAndPort& from, const IsMa // REMINDER: both _set->nodes and reply.members are sorted. if (_set->nodes.size() != reply.members.size() || !std::equal(_set->nodes.begin(), _set->nodes.end(), reply.members.begin(), hostsEqual)) { - LOG(2) << "Adjusting nodes in our view of replica set " << _set->name - << " based on master reply: " << redact(reply.raw); + LOGV2_DEBUG(20167, + 2, + "Adjusting nodes in our view of replica set {set_name} based on master reply: " + "{reply_raw}", + "set_name"_attr = _set->name, + "reply_raw"_attr = redact(reply.raw)); // remove non-members from _set->nodes _set->nodes.erase( @@ -900,7 +930,10 @@ Status Refresher::receivedIsMasterFromMaster(const HostAndPort& from, const IsMa // LogLevel can be pretty low, since replica set reconfiguration should be pretty rare // and we want to record our changes - log() << "Confirmed replica set for " << _set->name << " is " << _set->seedConnStr; + LOGV2(20168, + "Confirmed replica set for {set_name} is {set_seedConnStr}", + "set_name"_attr = _set->name, + "set_seedConnStr"_attr = _set->seedConnStr); _set->notifier->onConfirmedSet(_set->seedConnStr, reply.host, reply.passives); } @@ -971,7 +1004,10 @@ void IsMasterReply::parse(const BSONObj& obj) { } } catch (const std::exception& e) { ok = false; - log() << "exception while parsing isMaster reply: " << e.what() << " " << obj; + LOGV2(20169, + "exception while parsing isMaster reply: {e_what} {obj}", + "e_what"_attr = e.what(), + "obj"_attr = obj); } } @@ -979,7 +1015,10 @@ Node::Node(const HostAndPort& host) : host(host), latencyMicros(unknownLatency) void Node::markFailed(const Status& status) { if (isUp) { - log() << "Marking host " << host << " as failed" << causedBy(redact(status)); + LOGV2(20170, + "Marking host {host} as failed{causedBy_status}", + "host"_attr = host, + "causedBy_status"_attr = causedBy(redact(status))); isUp = false; } @@ -989,11 +1028,15 @@ void Node::markFailed(const Status& status) { bool Node::matches(const ReadPreference pref) const { if (!isUp) { - LOG(3) << "Host " << host << " is not up"; + LOGV2_DEBUG(20171, 3, "Host {host} is not up", "host"_attr = host); return false; } - LOG(3) << "Host " << host << " is " << (isMaster ? "primary" : "not primary"); + LOGV2_DEBUG(20172, + 3, + "Host {host} is {isMaster_primary_not_primary}", + "host"_attr = host, + "isMaster_primary_not_primary"_attr = (isMaster ? "primary" : "not primary")); if (pref == ReadPreference::PrimaryOnly) { return isMaster; } @@ -1020,7 +1063,11 @@ void Node::update(const IsMasterReply& reply) { invariant(host == reply.host); invariant(reply.ok); - LOG(3) << "Updating host " << host << " based on ismaster reply: " << reply.raw; + LOGV2_DEBUG(20173, + 3, + "Updating host {host} based on ismaster reply: {reply_raw}", + "host"_attr = host, + "reply_raw"_attr = reply.raw); // Nodes that are hidden or neither master or secondary are considered down since we can't // send any operations to them. @@ -1043,10 +1090,18 @@ void Node::update(const IsMasterReply& reply) { } } - LOG(3) << "Updating " << host << " lastWriteDate to " << reply.lastWriteDate; + LOGV2_DEBUG(20174, + 3, + "Updating {host} lastWriteDate to {reply_lastWriteDate}", + "host"_attr = host, + "reply_lastWriteDate"_attr = reply.lastWriteDate); lastWriteDate = reply.lastWriteDate; - LOG(3) << "Updating " << host << " opTime to " << reply.opTime; + LOGV2_DEBUG(20175, + 3, + "Updating {host} opTime to {reply_opTime}", + "host"_attr = host, + "reply_opTime"_attr = reply.opTime); opTime = reply.opTime; lastWriteDateUpdateTime = Date_t::now(); } @@ -1065,7 +1120,9 @@ SetState::SetState(const MongoURI& uri, uassert(13642, "Replica set seed list can't be empty", !seedNodes.empty()); if (name.empty()) - warning() << "Replica set name empty, first node: " << *(seedNodes.begin()); + LOGV2_WARNING(20182, + "Replica set name empty, first node: {seedNodes_begin}", + "seedNodes_begin"_attr = *(seedNodes.begin())); // This adds the seed hosts to nodes, but they aren't usable for anything except seeding a // scan until we start a scan and either find a master or contact all hosts without finding @@ -1265,7 +1322,11 @@ Node* SetState::findOrCreateNode(const HostAndPort& host) { // to consider alternate algorithms. Nodes::iterator it = std::lower_bound(nodes.begin(), nodes.end(), host, compareHosts); if (it == nodes.end() || it->host != host) { - LOG(2) << "Adding node " << host << " to our view of replica set " << name; + LOGV2_DEBUG(20176, + 2, + "Adding node {host} to our view of replica set {name}", + "host"_attr = host, + "name"_attr = name); it = nodes.insert(it, Node(host)); } return &(*it); @@ -1274,8 +1335,12 @@ Node* SetState::findOrCreateNode(const HostAndPort& host) { void SetState::updateNodeIfInNodes(const IsMasterReply& reply) { Node* node = findNode(reply.host); if (!node) { - LOG(2) << "Skipping application of ismaster reply from " << reply.host - << " since it isn't a confirmed member of set " << name; + LOGV2_DEBUG(20177, + 2, + "Skipping application of ismaster reply from {reply_host} since it isn't a " + "confirmed member of set {name}", + "reply_host"_attr = reply.host, + "name"_attr = name); return; } @@ -1321,12 +1386,16 @@ void SetState::notify() { it->promise.emplaceValue(std::move(match)); waiters.erase(it++); } else if (it->deadline <= cachedNow) { - LOG(1) << "Unable to statisfy read preference " << it->criteria << " by deadline " - << it->deadline; + LOGV2_DEBUG( + 20178, + 1, + "Unable to statisfy read preference {it_criteria} by deadline {it_deadline}", + "it_criteria"_attr = it->criteria, + "it_deadline"_attr = it->deadline); it->promise.setError(makeUnsatisfedReadPrefError(it->criteria)); waiters.erase(it++); } else if (shouldQuickFail) { - LOG(1) << "Unable to statisfy read preference because tests fail quickly"; + LOGV2_DEBUG(20179, 1, "Unable to statisfy read preference because tests fail quickly"); it->promise.setError(makeUnsatisfedReadPrefError(it->criteria)); waiters.erase(it++); } else { diff --git a/src/mongo/client/replica_set_monitor_manager.cpp b/src/mongo/client/replica_set_monitor_manager.cpp index 96d270a5e4e..8e27ca8e284 100644 --- a/src/mongo/client/replica_set_monitor_manager.cpp +++ b/src/mongo/client/replica_set_monitor_manager.cpp @@ -45,6 +45,7 @@ #include "mongo/executor/task_executor.h" #include "mongo/executor/task_executor_pool.h" #include "mongo/executor/thread_pool_task_executor.h" +#include "mongo/logv2/log.h" #include "mongo/platform/mutex.h" #include "mongo/rpc/metadata/egress_metadata_hook_list.h" #include "mongo/util/log.h" @@ -121,7 +122,7 @@ shared_ptr<ReplicaSetMonitor> ReplicaSetMonitorManager::getOrCreateMonitor(const return monitor; } - log() << "Starting new replica set monitor for " << uri.toString(); + LOGV2(20186, "Starting new replica set monitor for {uri}", "uri"_attr = uri.toString()); auto newMonitor = std::make_shared<ReplicaSetMonitor>(uri); _monitors[setName] = newMonitor; @@ -149,7 +150,8 @@ void ReplicaSetMonitorManager::removeMonitor(StringData setName) { monitor->drop(); } _monitors.erase(it); - log() << "Removed ReplicaSetMonitor for replica set " << setName; + LOGV2( + 20187, "Removed ReplicaSetMonitor for replica set {setName}", "setName"_attr = setName); } } @@ -172,12 +174,12 @@ void ReplicaSetMonitorManager::shutdown() { } if (taskExecutor) { - LOG(1) << "Shutting down task executor used for monitoring replica sets"; + LOGV2_DEBUG(20188, 1, "Shutting down task executor used for monitoring replica sets"); taskExecutor->shutdown(); } if (monitors.size()) { - log() << "Dropping all ongoing scans against replica sets"; + LOGV2(20189, "Dropping all ongoing scans against replica sets"); } for (auto& [name, monitor] : monitors) { auto anchor = monitor.lock(); diff --git a/src/mongo/client/replica_set_monitor_scan_test.cpp b/src/mongo/client/replica_set_monitor_scan_test.cpp index fdba042c86c..dfac48e56f8 100644 --- a/src/mongo/client/replica_set_monitor_scan_test.cpp +++ b/src/mongo/client/replica_set_monitor_scan_test.cpp @@ -34,6 +34,7 @@ #include "mongo/client/replica_set_monitor_test_fixture.h" #include "mongo/client/mongo_uri.h" +#include "mongo/logv2/log.h" #include "mongo/util/log.h" namespace mongo { @@ -1416,11 +1417,15 @@ TEST_F(MinOpTimeTest, MinOpTimeIgnored) { class Listener : public ReplicaSetChangeNotifier::Listener { public: void logEvent(StringData name, const Key& key) { - log() << name << ": " << key; + LOGV2(20190, "{name}: {key}", "name"_attr = name, "key"_attr = key); } void logEvent(StringData name, const State& state) { - log() << name << ": " - << "(" << state.generation << ") " << state.connStr << " | " << state.primary; + LOGV2(20191, + "{name}: ({state_generation}) {state_connStr} | {state_primary}", + "name"_attr = name, + "state_generation"_attr = state.generation, + "state_connStr"_attr = state.connStr, + "state_primary"_attr = state.primary); } void onFoundSet(const Key& key) noexcept override { diff --git a/src/mongo/client/replica_set_monitor_test_concurrent.cpp b/src/mongo/client/replica_set_monitor_test_concurrent.cpp index 55ac5e4716c..f5720053f4f 100644 --- a/src/mongo/client/replica_set_monitor_test_concurrent.cpp +++ b/src/mongo/client/replica_set_monitor_test_concurrent.cpp @@ -38,6 +38,7 @@ #include "mongo/executor/thread_pool_mock.h" #include "mongo/executor/thread_pool_task_executor.h" #include "mongo/executor/thread_pool_task_executor_test_fixture.h" +#include "mongo/logv2/log.h" #include "mongo/unittest/unittest.h" #include "mongo/util/duration.h" #include "mongo/util/log.h" @@ -102,15 +103,19 @@ protected: const auto net = getNet(); const auto request = noi->getRequest(); _numChecks[request.target]++; - LOG(2) << "at " << elapsed() << " got mock net operation " << request.toString(); + LOGV2_DEBUG(20192, + 2, + "at {elapsed} got mock net operation {request}", + "elapsed"_attr = elapsed(), + "request"_attr = request.toString()); const auto node = replSet.getNode(request.target.toString()); if (node->isRunning()) { const auto opmsg = OpMsgRequest::fromDBAndBody(request.dbname, request.cmdObj); const auto reply = node->runCommand(request.id, opmsg)->getCommandReply(); - LOG(2) << "replying " << reply; + LOGV2_DEBUG(20193, 2, "replying {reply}", "reply"_attr = reply); net->scheduleSuccessfulResponse(noi, RemoteCommandResponse(reply, Milliseconds(0))); } else { - LOG(2) << "black hole"; + LOGV2_DEBUG(20194, 2, "black hole"); net->blackHole(noi); } net->runReadyNetworkOperations(); @@ -122,9 +127,13 @@ protected: InNetworkGuard guard(net); // Operations can happen inline with advanceTime(), so log before and after the call. - LOG(3) << "Advancing time from " << elapsed() << " to " << (elapsed() + d); + LOGV2_DEBUG(20195, + 3, + "Advancing time from {elapsed} to {elapsed_d}", + "elapsed"_attr = elapsed(), + "elapsed_d"_attr = (elapsed() + d)); net->advanceTime(net->now() + d); - LOG(3) << "Advanced to " << elapsed(); + LOGV2_DEBUG(20196, 3, "Advanced to {elapsed}", "elapsed"_attr = elapsed()); } int getNumChecks(HostAndPort host) { diff --git a/src/mongo/client/sasl_client_authenticate_impl.cpp b/src/mongo/client/sasl_client_authenticate_impl.cpp index 860f913971b..f95ed39811d 100644 --- a/src/mongo/client/sasl_client_authenticate_impl.cpp +++ b/src/mongo/client/sasl_client_authenticate_impl.cpp @@ -48,6 +48,7 @@ #include "mongo/client/sasl_client_authenticate.h" #include "mongo/client/sasl_client_session.h" #include "mongo/db/auth/sasl_command_constants.h" +#include "mongo/logv2/log.h" #include "mongo/rpc/get_status_from_command_result.h" #include "mongo/util/base64.h" #include "mongo/util/log.h" @@ -181,7 +182,10 @@ Future<void> asyncSaslConversation(auth::RunCommandHook runCommand, if (!status.isOK()) return status; - LOG(saslLogLevel) << "sasl client input: " << base64::encode(payload) << endl; + LOGV2_DEBUG(20197, + logSeverityV1toV2(saslLogLevel).toInt(), + "sasl client input: {base64_encode_payload}", + "base64_encode_payload"_attr = base64::encode(payload)); // Create new payload for our response std::string responsePayload; @@ -189,7 +193,10 @@ Future<void> asyncSaslConversation(auth::RunCommandHook runCommand, if (!status.isOK()) return status; - LOG(saslLogLevel) << "sasl client output: " << base64::encode(responsePayload) << endl; + LOGV2_DEBUG(20198, + logSeverityV1toV2(saslLogLevel).toInt(), + "sasl client output: {base64_encode_responsePayload}", + "base64_encode_responsePayload"_attr = base64::encode(responsePayload)); // Handle a done from the server which comes before the client is complete. const bool serverDone = inputObj[saslCommandDoneFieldName].trueValue(); diff --git a/src/mongo/client/sdam/sdam_json_test_runner.cpp b/src/mongo/client/sdam/sdam_json_test_runner.cpp index 10027290a17..ec4b8e453d2 100644 --- a/src/mongo/client/sdam/sdam_json_test_runner.cpp +++ b/src/mongo/client/sdam/sdam_json_test_runner.cpp @@ -43,6 +43,7 @@ #include "mongo/client/sdam/sdam_json_test_runner_cli_options_gen.h" #include "mongo/client/sdam/topology_manager.h" #include "mongo/logger/logger.h" +#include "mongo/logv2/log.h" #include "mongo/stdx/unordered_set.h" #include "mongo/util/clock_source_mock.h" #include "mongo/util/log.h" @@ -126,10 +127,14 @@ public: } void LogParams() const { - log() << "Verbosity: " << _verbose << std::endl; - log() << "Source Directory: " << _sourceDirectory << std::endl; + LOGV2(20199, "Verbosity: {verbose}", "verbose"_attr = _verbose); + LOGV2(20200, + "Source Directory: {sourceDirectory}", + "sourceDirectory"_attr = _sourceDirectory); if (_testFilters.size()) { - log() << "Filters: " << boost::join(_testFilters, ", "); + LOGV2(20201, + "Filters: {boost_join_testFilters}", + "boost_join_testFilters"_attr = boost::join(_testFilters, ", ")); } } @@ -212,13 +217,18 @@ public: for (auto response : _isMasterResponses) { auto descriptionStr = (response.getResponse()) ? response.getResponse()->toString() : "[ Network Error ]"; - log() << "Sending server description: " << response.getServer() << " : " - << descriptionStr << std::endl; + LOGV2(20202, + "Sending server description: {response_getServer} : {descriptionStr}", + "response_getServer"_attr = response.getServer(), + "descriptionStr"_attr = descriptionStr); topology.onServerDescription(response); } - log() << "TopologyDescription after Phase " << _phaseNum << ": " - << topology.getTopologyDescription()->toString() << std::endl; + LOGV2(20203, + "TopologyDescription after Phase {phaseNum}: {topology_getTopologyDescription}", + "phaseNum"_attr = _phaseNum, + "topology_getTopologyDescription"_attr = + topology.getTopologyDescription()->toString()); validateServers( &testResult, topology.getTopologyDescription(), _topologyOutcome["servers"].Obj()); @@ -553,11 +563,16 @@ public: TestCaseResult result{{}, _testFilePath, _testName}; for (const auto& testPhase : _testPhases) { - log() << emphasize("Phase " + std::to_string(testPhase.getPhaseNum())); + LOGV2(20204, + "{emphasize_Phase_std_to_string_testPhase_getPhaseNum}", + "emphasize_Phase_std_to_string_testPhase_getPhaseNum"_attr = + emphasize("Phase " + std::to_string(testPhase.getPhaseNum()))); auto phaseResult = testPhase.execute(topology); result.phaseResults.push_back(phaseResult); if (!result.Success()) { - log() << "Phase " << phaseResult.phaseNumber << " failed."; + LOGV2(20205, + "Phase {phaseResult_phaseNumber} failed.", + "phaseResult_phaseNumber"_attr = phaseResult.phaseNumber); break; } } @@ -572,8 +587,11 @@ public: private: void parseTest(fs::path testFilePath) { _testFilePath = testFilePath.string(); - log() << ""; - log() << emphasize("Parsing " + testFilePath.string()); + LOGV2(20206, ""); + LOGV2(20207, + "{emphasize_Parsing_testFilePath_string}", + "emphasize_Parsing_testFilePath_string"_attr = + emphasize("Parsing " + testFilePath.string())); { std::ifstream testFile(_testFilePath); std::ostringstream json; @@ -636,7 +654,10 @@ public: for (auto jsonTest : testFiles) { auto testCase = JsonTestCase(jsonTest); try { - log() << emphasize("Executing " + testCase.Name()); + LOGV2(20208, + "{emphasize_Executing_testCase_Name}", + "emphasize_Executing_testCase_Name"_attr = + emphasize("Executing " + testCase.Name())); results.push_back(testCase.execute()); } catch (const DBException& ex) { std::stringstream error; @@ -661,7 +682,9 @@ public: results.begin(), results.end(), [](const JsonTestCase::TestCaseResult& result) { return !result.Success(); })) { - log() << emphasize("Failed Test Results"); + LOGV2(20209, + "{emphasize_Failed_Test_Results}", + "emphasize_Failed_Test_Results"_attr = emphasize("Failed Test Results")); } for (const auto result : results) { @@ -671,22 +694,31 @@ public: if (result.Success()) { ++numSuccess; } else { - log() << emphasize(testName); - log() << "error in file: " << file; + LOGV2( + 20210, "{emphasize_testName}", "emphasize_testName"_attr = emphasize(testName)); + LOGV2(20211, "error in file: {file}", "file"_attr = file); ++numFailed; for (auto phaseResult : phaseResults) { - log() << "Phase " << phaseResult.phaseNumber << ": " << std::endl; + LOGV2(20212, + "Phase {phaseResult_phaseNumber}: ", + "phaseResult_phaseNumber"_attr = phaseResult.phaseNumber); if (!phaseResult.Success()) { for (auto error : phaseResult.errorDescriptions) { - log() << "\t" << error.first << ": " << error.second << std::endl; + LOGV2(20213, + "\t{error_first}: {error_second}", + "error_first"_attr = error.first, + "error_second"_attr = error.second); } } } - log() << std::endl; + LOGV2(20214, ""); } } - log() << numTestCases << " test cases; " << numSuccess << " success; " << numFailed - << " failed."; + LOGV2(20215, + "{numTestCases} test cases; {numSuccess} success; {numFailed} failed.", + "numTestCases"_attr = numTestCases, + "numSuccess"_attr = numSuccess, + "numFailed"_attr = numFailed); return numFailed; } @@ -721,7 +753,10 @@ private: if (filePath.string().find(filter) != std::string::npos) { return true; } else { - LOG(2) << "'" << filePath.string() << "' skipped due to filter configuration."; + LOGV2_DEBUG(20216, + 2, + "'{filePath_string}' skipped due to filter configuration.", + "filePath_string"_attr = filePath.string()); } } diff --git a/src/mongo/client/sdam/topology_description_test.cpp b/src/mongo/client/sdam/topology_description_test.cpp index 1b6181562ae..3f580a9d415 100644 --- a/src/mongo/client/sdam/topology_description_test.cpp +++ b/src/mongo/client/sdam/topology_description_test.cpp @@ -26,6 +26,8 @@ * exception statement from all source files in the program, then also delete * it in the license file. */ +#define MONGO_LOG_DEFAULT_COMPONENT ::mongo::logger::LogComponent::kDefault + #include "mongo/client/sdam/sdam_test_base.h" #include "mongo/client/sdam/topology_description.h" @@ -34,7 +36,9 @@ #include "mongo/client/sdam/server_description.h" #include "mongo/client/sdam/server_description_builder.h" #include "mongo/db/wire_version.h" +#include "mongo/logv2/log.h" #include "mongo/unittest/death_test.h" +#include "mongo/util/log.h" namespace mongo { template std::ostream& operator<<(std::ostream& os, @@ -143,8 +147,9 @@ TEST_F(TopologyDescriptionTestFixture, ShouldOnlyAllowSingleAndRsNoPrimaryWithSe topologyTypes.end()); for (const auto topologyType : topologyTypes) { - unittest::log() << "Check TopologyType " << toString(topologyType) - << " with setName value."; + LOGV2(20217, + "Check TopologyType {topologyType} with setName value.", + "topologyType"_attr = toString(topologyType)); ASSERT_THROWS_CODE( SdamConfiguration(kOneServer, topologyType, mongo::Seconds(10), kSetName), DBException, diff --git a/src/mongo/client/sdam/topology_manager.cpp b/src/mongo/client/sdam/topology_manager.cpp index c2153ae667c..9cad8440f57 100644 --- a/src/mongo/client/sdam/topology_manager.cpp +++ b/src/mongo/client/sdam/topology_manager.cpp @@ -31,6 +31,7 @@ #include "mongo/client/sdam/topology_manager.h" #include "mongo/client/sdam/topology_state_machine.h" +#include "mongo/logv2/log.h" #include "mongo/util/log.h" namespace mongo::sdam { @@ -76,10 +77,12 @@ void TopologyManager::onServerDescription(const IsMasterOutcome& isMasterOutcome boost::optional<int> poolResetCounter = boost::none; if (isMasterOutcome.isSuccess()) { if (isStaleTopologyVersion(lastTopologyVersion, newTopologyVersion)) { - log() << "Ignoring this isMaster response because our topologyVersion: " - << lastTopologyVersion->toBSON() - << "is fresher than the provided topologyVersion: " - << newTopologyVersion->toBSON(); + LOGV2(20218, + "Ignoring this isMaster response because our topologyVersion: " + "{lastTopologyVersion}is fresher than the provided topologyVersion: " + "{newTopologyVersion}", + "lastTopologyVersion"_attr = lastTopologyVersion->toBSON(), + "newTopologyVersion"_attr = newTopologyVersion->toBSON()); return; } diff --git a/src/mongo/client/sdam/topology_state_machine.cpp b/src/mongo/client/sdam/topology_state_machine.cpp index dc793595b5c..c54053b2260 100644 --- a/src/mongo/client/sdam/topology_state_machine.cpp +++ b/src/mongo/client/sdam/topology_state_machine.cpp @@ -33,6 +33,7 @@ #include <ostream> #include "mongo/client/sdam/sdam_test_base.h" +#include "mongo/logv2/log.h" #include "mongo/util/log.h" namespace mongo::sdam { @@ -149,8 +150,11 @@ void mongo::sdam::TopologyStateMachine::initTransitionTable() { void TopologyStateMachine::onServerDescription(TopologyDescription& topologyDescription, const ServerDescriptionPtr& serverDescription) { if (!topologyDescription.containsServerAddress(serverDescription->getAddress())) { - LOG(0) << kLogPrefix << "ignoring ismaster reply from server that is not in the topology: " - << serverDescription->getAddress() << std::endl; + LOGV2(20219, + "{kLogPrefix}ignoring ismaster reply from server that is not in the topology: " + "{serverDescription_getAddress}", + "kLogPrefix"_attr = kLogPrefix, + "serverDescription_getAddress"_attr = serverDescription->getAddress()); return; } @@ -364,40 +368,59 @@ void TopologyStateMachine::setTopologyTypeAndUpdateRSWithoutPrimary( void TopologyStateMachine::removeServerDescription(TopologyDescription& topologyDescription, const ServerAddress serverAddress) { topologyDescription.removeServerDescription(serverAddress); - LOG(0) << kLogPrefix << "server '" << serverAddress << "' was removed from the topology." - << std::endl; + LOGV2(20220, + "{kLogPrefix}server '{serverAddress}' was removed from the topology.", + "kLogPrefix"_attr = kLogPrefix, + "serverAddress"_attr = serverAddress); } void TopologyStateMachine::modifyTopologyType(TopologyDescription& topologyDescription, TopologyType topologyType) { topologyDescription._type = topologyType; - LOG(0) << kLogPrefix << "the topology type was set to " << toString(topologyType) << std::endl; + LOGV2(20221, + "{kLogPrefix}the topology type was set to {topologyType}", + "kLogPrefix"_attr = kLogPrefix, + "topologyType"_attr = toString(topologyType)); } void TopologyStateMachine::modifySetName(TopologyDescription& topologyDescription, const boost::optional<std::string>& setName) { topologyDescription._setName = setName; - LOG(0) << kLogPrefix << "the topology setName was set to " << ((setName) ? *setName : "[null]") - << std::endl; + LOGV2(20222, + "{kLogPrefix}the topology setName was set to {setName_setName_null}", + "kLogPrefix"_attr = kLogPrefix, + "setName_setName_null"_attr = ((setName) ? *setName : "[null]")); } void TopologyStateMachine::installServerDescription(TopologyDescription& topologyDescription, ServerDescriptionPtr newServerDescription, bool newServer) { topologyDescription.installServerDescription(newServerDescription); - LOG(1) << kLogPrefix << ((newServer) ? "installed new" : "updated existing") - << " server description: " << newServerDescription->toString() << std::endl; + LOGV2_DEBUG(20223, + 1, + "{kLogPrefix}{newServer_installed_new_updated_existing} server description: " + "{newServerDescription}", + "kLogPrefix"_attr = kLogPrefix, + "newServer_installed_new_updated_existing"_attr = + ((newServer) ? "installed new" : "updated existing"), + "newServerDescription"_attr = newServerDescription->toString()); } void TopologyStateMachine::modifyMaxElectionId(TopologyDescription& topologyDescription, const OID& newMaxElectionId) { topologyDescription._maxElectionId = newMaxElectionId; - LOG(0) << kLogPrefix << "topology max election id set to " << newMaxElectionId << std::endl; + LOGV2(20224, + "{kLogPrefix}topology max election id set to {newMaxElectionId}", + "kLogPrefix"_attr = kLogPrefix, + "newMaxElectionId"_attr = newMaxElectionId); } void TopologyStateMachine::modifyMaxSetVersion(TopologyDescription& topologyDescription, int& newMaxSetVersion) { topologyDescription._maxSetVersion = newMaxSetVersion; - LOG(0) << kLogPrefix << "topology max set version set to " << newMaxSetVersion << std::endl; + LOGV2(20225, + "{kLogPrefix}topology max set version set to {newMaxSetVersion}", + "kLogPrefix"_attr = kLogPrefix, + "newMaxSetVersion"_attr = newMaxSetVersion); } } // namespace mongo::sdam |