SERVER-47073 Clean up log lines in mongo/client and mongo/executor

Author: bcaimano

src/mongo/client/async_client.cpp

@@ -112,8 +112,9 @@ void AsyncDBClient::_parseIsMasterResponse(BSONObj request,
         rpc::validateWireVersion(WireSpec::instance().outgoing, protocolSet.version);
     if (!validateStatus.isOK()) {
         LOGV2_WARNING(23741,
-                      "remote host has incompatible wire version: {validateStatus}",
-                      "validateStatus"_attr = validateStatus);
+                      "Remote host has incompatible wire version: {error}",
+                      "Remote host has incompatible wire version",
+                      "error"_attr = validateStatus);
         uasserted(validateStatus.code(),
                   str::stream() << "remote host has incompatible wire version: "
                                 << validateStatus.reason());

src/mongo/client/authenticate.cpp

@@ -151,8 +151,8 @@ Future<void> authenticateClient(const BSONObj& params,
         if (serverGlobalParams.transitionToAuth && !ErrorCodes::isNetworkError(status)) {
             // If auth failed in transitionToAuth, just pretend it succeeded.
             LOGV2(20108,
-                  "Failed to authenticate in transitionToAuth, falling back to no "
-                  "authentication.");
+                  "Failed to authenticate in transitionToAuth, "
+                  "falling back to no authentication");
 
             return Status::OK();
         }

src/mongo/client/connection_string_connect.cpp

@@ -61,12 +61,15 @@ std::unique_ptr<DBClientBase> ConnectionString::connect(StringData applicationNa
                 auto c = std::make_unique<DBClientConnection>(true, 0, newURI);
 
                 c->setSoTimeout(socketTimeout);
-                LOGV2_DEBUG(
-                    20109, 1, "creating new connection to:{server}", "server"_attr = server);
+                LOGV2_DEBUG(20109,
+                            1,
+                            "Creating new connection to: {hostAndPort}",
+                            "Creating new connection",
+                            "hostAndPort"_attr = server);
                 if (!c->connect(server, applicationName, errmsg)) {
                     continue;
                 }
-                LOGV2_DEBUG(20110, 1, "connected connection!");
+                LOGV2_DEBUG(20110, 1, "Connected connection!");
                 return std::move(c);
             }
             return nullptr;
@@ -98,10 +101,10 @@ std::unique_ptr<DBClientBase> ConnectionString::connect(StringData applicationNa
             auto replacementConn = _connectHook->connect(*this, errmsg, socketTimeout);
 
             LOGV2(20111,
-                  "replacing connection to {this} with "
-                  "{replacementConn_replacementConn_getServerAddress_empty}",
-                  "this"_attr = this->toString(),
-                  "replacementConn_replacementConn_getServerAddress_empty"_attr =
+                  "Replacing connection to {oldConnString} with {newConnString}",
+                  "Replacing connection string",
+                  "oldConnString"_attr = this->toString(),
+                  "newConnString"_attr =
                       (replacementConn ? replacementConn->getServerAddress() : "(empty)"));
 
             return replacementConn;

src/mongo/client/connpool.cpp

@@ -62,6 +62,10 @@ namespace mongo {
 namespace {
 const int kDefaultIdleTimeout = std::numeric_limits<int>::max();
 const int kDefaultMaxInUse = std::numeric_limits<int>::max();
+
+auto makeDuration(double secs) {
+    return Milliseconds(static_cast<Milliseconds::rep>(1000 * secs));
+}
 }  // namespace
 
 using std::endl;
@@ -91,10 +95,11 @@ PoolForHost::~PoolForHost() {
 void PoolForHost::clear() {
     if (!_parentDestroyed) {
         LOGV2(24124,
-              "Dropping all pooled connections to {hostName}(with timeout of {socketTimeoutSecs} "
-              "seconds)",
-              "hostName"_attr = _hostName,
-              "socketTimeoutSecs"_attr = _socketTimeoutSecs);
+              "Dropping all pooled connections to {connString} "
+              "(with timeout of {timeoutSecs} seconds)",
+              "Dropping all pooled connections to a host",
+              "connString"_attr = _hostName,
+              "socketTimeout"_attr = makeDuration(_socketTimeoutSecs));
     }
 
     _pool = decltype(_pool){};
@@ -114,23 +119,24 @@ auto PoolForHost::done(DBConnectionPool* pool, DBClientBase* c) -> ConnectionHea
     bool isBroken = c->getSockCreationMicroSec() < _minValidCreationTimeMicroSec;
     if (isFailed || isBroken) {
         _badConns++;
-        LOGV2(
-            24125,
-            "Ending connection to host {hostName}(with timeout of {socketTimeoutSecs} seconds) due "
-            "to bad connection status; {openConnections} connections to that host remain open",
-            "hostName"_attr = _hostName,
-            "socketTimeoutSecs"_attr = _socketTimeoutSecs,
-            "openConnections"_attr = openConnections());
+        LOGV2(24125,
+              "Ending connection to {connString} (with timeout of {socketTimeout}) "
+              "due to bad connection status; {numOpenConns} connections to that host remain open",
+              "Ending connection to a host due to a bad connection status",
+              "connString"_attr = _hostName,
+              "socketTimeout"_attr = makeDuration(_socketTimeoutSecs),
+              "numOpenConns"_attr = openConnections());
         return ConnectionHealth::kFailed;
     } else if (_maxPoolSize >= 0 && static_cast<int>(_pool.size()) >= _maxPoolSize) {
         // We have a pool size that we need to enforce
         LOGV2(24126,
-              "Ending idle connection to host {hostName}(with timeout of {socketTimeoutSecs} "
-              "seconds) because the pool meets constraints; {openConnections} connections to that "
-              "host remain open",
-              "hostName"_attr = _hostName,
-              "socketTimeoutSecs"_attr = _socketTimeoutSecs,
-              "openConnections"_attr = openConnections());
+              "Ending idle connection to {connString} (with timeout of {socketTimeout}) "
+              "because its pool meets constraints; "
+              "{numOpenConns} connections to that host remain open",
+              "Ending idle connection to a host because its pool mees constraints",
+              "connString"_attr = _hostName,
+              "socketTimeout"_attr = makeDuration(_socketTimeoutSecs),
+              "numOpenConns"_attr = openConnections());
         return ConnectionHealth::kTooMany;
     }
 
@@ -144,11 +150,13 @@ void PoolForHost::reportBadConnectionAt(uint64_t microSec) {
         microSec > _minValidCreationTimeMicroSec) {
         _minValidCreationTimeMicroSec = microSec;
         LOGV2(24127,
-              "Detected bad connection created at {minValidCreationTimeMicroSec} microSec, "
-              "clearing pool for {hostName} of {openConnections} connections",
-              "minValidCreationTimeMicroSec"_attr = _minValidCreationTimeMicroSec,
-              "hostName"_attr = _hostName,
-              "openConnections"_attr = openConnections());
+              "Detected bad connection created at {currentTime}, "
+              "clearing pool for {connString} of {numOpenConns} connections",
+              "Detected bad connection, clearing pool for host",
+              "currentTime"_attr =
+                  Microseconds(static_cast<Microseconds::rep>(_minValidCreationTimeMicroSec)),
+              "connString"_attr = _hostName,
+              "numOpenConns"_attr = openConnections());
         clear();
     }
 }
@@ -280,9 +288,10 @@ class DBConnectionPool::Detail {
 
                 if (p.openConnections() >= _this->_maxInUse) {
                     LOGV2(20112,
-                          "Too many in-use connections; waiting until there are fewer than "
-                          "{this_maxInUse}",
-                          "this_maxInUse"_attr = _this->_maxInUse);
+                          "Too many in-use connections; "
+                          "waiting until there are fewer than {maxInUseConns}",
+                          "Too many in-use connections; waiting until there are fewer than maximum",
+                          "maxInUseConns"_attr = _this->_maxInUse);
                     p.waitForFreeConnection(timeout, lk);
                 } else {
                     // Drop the lock here, so we can connect without holding it.
@@ -367,12 +376,13 @@ DBClientBase* DBConnectionPool::_finishCreate(const string& ident,
     }
 
     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);
+          "Successfully connected to {connString} "
+          "({numOpenConns} connections now open to that host "
+          "with a {socketTimeoutSecs} second timeout)",
+          "Successfully connected to host",
+          "connString"_attr = ident,
+          "numOpenConns"_attr = openConnections(ident, socketTimeout),
+          "socketTimeoutSecs"_attr = socketTimeout);
 
     return conn;
 }
@@ -490,16 +500,23 @@ void DBConnectionPool::flush() {
 
 void DBConnectionPool::clear() {
     stdx::lock_guard<Latch> L(_mutex);
-    LOGV2_DEBUG(20114, 2, "Removing connections on all pools owned by {name}", "name"_attr = _name);
+    LOGV2_DEBUG(20114,
+                2,
+                "Removing connections on all pools owned by {poolName}",
+                "Removing all connectionns associated with this set of pools",
+                "poolName"_attr = _name);
     for (PoolMap::iterator iter = _pools.begin(); iter != _pools.end(); ++iter) {
         iter->second.clear();
     }
 }
 
 void DBConnectionPool::removeHost(const string& host) {
     stdx::lock_guard<Latch> L(_mutex);
-    LOGV2_DEBUG(
-        20115, 2, "Removing connections from all pools for host: {host}", "host"_attr = host);
+    LOGV2_DEBUG(20115,
+                2,
+                "Removing connections from all pools to {connString}",
+                "Removing connections from all pools to a host",
+                "connString"_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)) {
@@ -701,8 +718,9 @@ ScopedDbConnection::~ScopedDbConnection() {
         } else {
             /* see done() comments above for why we log this line */
             LOGV2(24128,
-                  "scoped connection to {conn_getServerAddress} not being returned to the pool",
-                  "conn_getServerAddress"_attr = _conn->getServerAddress());
+                  "Scoped connection to {connString} not being returned to the pool",
+                  "Scoped connection not being returned to the pool",
+                  "connString"_attr = _conn->getServerAddress());
             kill();
         }
     }

src/mongo/client/dbclient_base.cpp

@@ -501,11 +501,12 @@ Status DBClientBase::authenticateInternalUser() {
         return status;
     }
 
-    if (serverGlobalParams.quiet.load()) {
+    if (!serverGlobalParams.quiet.load()) {
         LOGV2(20117,
-              "can't authenticate to {} as internal user, error: {status_reason}",
-              ""_attr = toString(),
-              "status_reason"_attr = status.reason());
+              "Can't authenticate to {connString} as internal user, error: {error}",
+              "Can't authenticate as internal user",
+              "connString"_attr = toString(),
+              "error"_attr = status);
     }
 
     return status;
@@ -999,6 +1000,7 @@ void DBClientBase::dropIndex(const string& ns,
         LOGV2_DEBUG(20118,
                     logSeverityV1toV2(_logLevel).toInt(),
                     "dropIndex failed: {info}",
+                    "dropIndex failed",
                     "info"_attr = info);
         uassert(10007, "dropIndex failed", 0);
     }

src/mongo/client/dbclient_connection.cpp

@@ -342,8 +342,9 @@ Status DBClientConnection::connect(const HostAndPort& serverAddress, StringData
         rpc::validateWireVersion(WireSpec::instance().outgoing, swProtocolSet.getValue().version);
     if (!validateStatus.isOK()) {
         LOGV2_WARNING(20126,
-                      "remote host has incompatible wire version: {validateStatus}",
-                      "validateStatus"_attr = validateStatus);
+                      "Remote host has incompatible wire version: {error}",
+                      "Remote host has incompatible wire version",
+                      "error"_attr = validateStatus);
 
         return validateStatus;
     }
@@ -426,7 +427,11 @@ Status DBClientConnection::connectSocketOnly(const HostAndPort& serverAddress) {
     _lastConnectivityCheck = Date_t::now();
     _session->setTimeout(_socketTimeout);
     _session->setTags(_tagMask);
-    LOGV2_DEBUG(20119, 1, "connected to server {}", ""_attr = toString());
+    LOGV2_DEBUG(20119,
+                1,
+                "Connected to host {connString}",
+                "Connected to host",
+                "connString"_attr = toString());
     return Status::OK();
 }
 
@@ -555,26 +560,31 @@ void DBClientConnection::_checkConnection() {
 
     LOGV2_DEBUG(20120,
                 logSeverityV1toV2(_logLevel).toInt(),
-                "trying reconnect to {}",
-                ""_attr = toString());
+                "Trying to reconnect to {connString}",
+                "Trying to reconnnect",
+                "connString"_attr = toString());
     string errmsg;
     auto connectStatus = connect(_serverAddress, _applicationName);
     if (!connectStatus.isOK()) {
         _markFailed(kSetFlag);
         LOGV2_DEBUG(20121,
                     logSeverityV1toV2(_logLevel).toInt(),
-                    "reconnect {} failed {errmsg}",
-                    ""_attr = toString(),
-                    "errmsg"_attr = errmsg);
+                    "Reconnect attempt to {connString} failed: {reason}",
+                    "Reconnect attempt failed",
+                    "connString"_attr = toString(),
+                    "error"_attr = errmsg);
         if (connectStatus == ErrorCodes::IncompatibleCatalogManager) {
             uassertStatusOK(connectStatus);  // Will always throw
         } else {
             throwSocketError(SocketErrorKind::CONNECT_ERROR, connectStatus.reason());
         }
     }
 
-    LOGV2_DEBUG(
-        20122, logSeverityV1toV2(_logLevel).toInt(), "reconnect {} ok", ""_attr = toString());
+    LOGV2_DEBUG(20122,
+                logSeverityV1toV2(_logLevel).toInt(),
+                "Reconnected to {connString}",
+                "Reconnected",
+                "connString"_attr = toString());
     if (_internalAuthOnReconnect) {
         uassertStatusOK(authenticateInternalUser());
     } else {
@@ -584,14 +594,11 @@ void DBClientConnection::_checkConnection() {
             } catch (ExceptionFor<ErrorCodes::AuthenticationFailed>& ex) {
                 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());
+                            "Reconnect: auth failed for on {db} using {user}: {reason}",
+                            "Reconnect: auth failed",
+                            "db"_attr = kv.second[auth::getSaslCommandUserDBFieldName()],
+                            "user"_attr = kv.second[auth::getSaslCommandUserFieldName()],
+                            "error"_attr = ex.what());
             }
         }
     }
@@ -747,9 +754,10 @@ bool DBClientConnection::call(Message& toSend,
     auto sinkStatus = _session->sinkMessage(swm.getValue());
     if (!sinkStatus.isOK()) {
         LOGV2(20124,
-              "DBClientConnection failed to send message to {getServerAddress} - {sinkStatus}",
-              "getServerAddress"_attr = getServerAddress(),
-              "sinkStatus"_attr = redact(sinkStatus));
+              "DBClientConnection failed to send message to {connString}: {error}",
+              "DBClientConnection failed to send message",
+              "connString"_attr = getServerAddress(),
+              "error"_attr = redact(sinkStatus));
         return maybeThrow(sinkStatus);
     }
 
@@ -758,10 +766,10 @@ bool DBClientConnection::call(Message& toSend,
         response = std::move(swm.getValue());
     } else {
         LOGV2(20125,
-              "DBClientConnection failed to receive message from {getServerAddress} - "
-              "{swm_getStatus}",
-              "getServerAddress"_attr = getServerAddress(),
-              "swm_getStatus"_attr = redact(swm.getStatus()));
+              "DBClientConnection failed to receive message from {connString}: {error}",
+              "DBClientConnection failed to receive message",
+              "connString"_attr = getServerAddress(),
+              "error"_attr = redact(swm.getStatus()));
         return maybeThrow(swm.getStatus());
     }
 

src/mongo/client/dbclient_cursor.cpp

@@ -242,8 +242,9 @@ bool DBClientCursor::initLazyFinish(bool& retry) {
     if (!recvStatus.isOK() || reply.empty()) {
         if (!recvStatus.isOK())
             LOGV2(20129,
-                  "DBClientCursor::init lazy say() failed: {recvStatus}",
-                  "recvStatus"_attr = redact(recvStatus));
+                  "DBClientCursor::init lazy say() failed: {error}",
+                  "DBClientCursor::init lazy say() failed",
+                  "error"_attr = redact(recvStatus));
         if (reply.empty())
             LOGV2(20130, "DBClientCursor::init message from say() was empty");