diff options
Diffstat (limited to 'src/mongo/db/service_entry_point_common.cpp')
-rw-r--r-- | src/mongo/db/service_entry_point_common.cpp | 131 |
1 files changed, 93 insertions, 38 deletions
diff --git a/src/mongo/db/service_entry_point_common.cpp b/src/mongo/db/service_entry_point_common.cpp index 413a113e782..bd4165f2fe2 100644 --- a/src/mongo/db/service_entry_point_common.cpp +++ b/src/mongo/db/service_entry_point_common.cpp @@ -144,8 +144,11 @@ void generateLegacyQueryErrorResponse(const AssertionException& exception, "ns"_attr = queryMessage.ns); if (queryMessage.ntoskip || queryMessage.ntoreturn) { - log(LogComponent::kQuery) << " ntoskip:" << queryMessage.ntoskip - << " ntoreturn:" << queryMessage.ntoreturn; + LOGV2_OPTIONS(21952, + {logComponentV1toV2(LogComponent::kQuery)}, + " ntoskip:{queryMessage_ntoskip} ntoreturn:{queryMessage_ntoreturn}", + "queryMessage_ntoskip"_attr = queryMessage.ntoskip, + "queryMessage_ntoreturn"_attr = queryMessage.ntoreturn); } BSONObjBuilder err; @@ -160,8 +163,11 @@ void generateLegacyQueryErrorResponse(const AssertionException& exception, const bool isStaleConfig = exception.code() == ErrorCodes::StaleConfig; if (isStaleConfig) { - log(LogComponent::kQuery) << "stale version detected during query over " << queryMessage.ns - << " : " << errObj; + LOGV2_OPTIONS(21953, + {logComponentV1toV2(LogComponent::kQuery)}, + "stale version detected during query over {queryMessage_ns} : {errObj}", + "queryMessage_ns"_attr = queryMessage.ns, + "errObj"_attr = errObj); } BufBuilder bb; @@ -265,7 +271,8 @@ StatusWith<repl::ReadConcernArgs> _extractReadConcern(OperationContext* opCtx, // shard/config server. if (!readConcernArgs.isSpecified()) { // TODO: Disabled until after SERVER-44539, to avoid log spam. - // log() << "Missing readConcern on " << invocation->definition()->getName(); + // LOGV2(21954, "Missing readConcern on {invocation_definition_getName}", + // "invocation_definition_getName"_attr = invocation->definition()->getName()); } } else { // A member in a regular replica set. Since these servers receive client queries, in @@ -277,8 +284,13 @@ StatusWith<repl::ReadConcernArgs> _extractReadConcern(OperationContext* opCtx, .getDefaultReadConcern(opCtx); if (rcDefault) { readConcernArgs = std::move(*rcDefault); - LOG(2) << "Applying default readConcern on " - << invocation->definition()->getName() << " of " << *rcDefault; + LOGV2_DEBUG(21955, + 2, + "Applying default readConcern on {invocation_definition_getName} " + "of {rcDefault}", + "invocation_definition_getName"_attr = + invocation->definition()->getName(), + "rcDefault"_attr = *rcDefault); // Update the readConcernSupport, since the default RC was applied. readConcernSupport = invocation->supportsReadConcern(readConcernArgs.getLevel()); @@ -364,7 +376,7 @@ LogicalTime computeOperationTime(OperationContext* opCtx, LogicalTime startOpera invariant(isReplSet); if (startOperationTime == LogicalTime::kUninitialized) { - LOG(5) << "startOperationTime is uninitialized"; + LOGV2_DEBUG(21956, 5, "startOperationTime is uninitialized"); return LogicalTime(replCoord->getMyLastAppliedOpTime().getTimestamp()); } @@ -413,8 +425,11 @@ void appendClusterAndOperationTime(OperationContext* opCtx, dassert(signedTime.getTime() >= operationTime); rpc::LogicalTimeMetadata(signedTime).writeToMetadata(metadataBob); - LOG(5) << "Appending operationTime to cmd response for authorized client: " - << operationTime; + LOGV2_DEBUG( + 21957, + 5, + "Appending operationTime to cmd response for authorized client: {operationTime}", + "operationTime"_attr = operationTime); operationTime.appendAsOperationTime(commandBodyFieldsBob); return; @@ -438,7 +453,10 @@ void appendClusterAndOperationTime(OperationContext* opCtx, dassert(signedTime.getTime() >= operationTime); rpc::LogicalTimeMetadata(signedTime).writeToMetadata(metadataBob); - LOG(5) << "Appending operationTime to cmd response: " << operationTime; + LOGV2_DEBUG(21958, + 5, + "Appending operationTime to cmd response: {operationTime}", + "operationTime"_attr = operationTime); operationTime.appendAsOperationTime(commandBodyFieldsBob); } @@ -483,9 +501,14 @@ void _abortUnpreparedOrStashPreparedTransaction( txnParticipant->abortTransaction(opCtx); } catch (...) { // It is illegal for this to throw so we catch and log this here for diagnosability. - severe() << "Caught exception during transaction " << opCtx->getTxnNumber() - << (isPrepared ? " stash " : " abort ") << opCtx->getLogicalSessionId()->toBSON() - << ": " << exceptionToStatus(); + LOGV2_FATAL(21974, + "Caught exception during transaction " + "{opCtx_getTxnNumber}{isPrepared_stash_abort}{opCtx_getLogicalSessionId}: " + "{exceptionToStatus}", + "opCtx_getTxnNumber"_attr = opCtx->getTxnNumber(), + "isPrepared_stash_abort"_attr = (isPrepared ? " stash " : " abort "), + "opCtx_getLogicalSessionId"_attr = opCtx->getLogicalSessionId()->toBSON(), + "exceptionToStatus"_attr = exceptionToStatus()); std::terminate(); } } @@ -668,7 +691,8 @@ bool runCommandImpl(OperationContext* opCtx, serverGlobalParams.clusterRole == ClusterRole::ConfigServer) && !request.body.hasField(WriteConcernOptions::kWriteConcernField)) { // TODO: Disabled until after SERVER-44539, to avoid log spam. - // log() << "Missing writeConcern on " << command->getName(); + // LOGV2(21959, "Missing writeConcern on {command_getName}", "command_getName"_attr + // = command->getName()); } extractedWriteConcern.emplace( uassertStatusOK(extractWriteConcern(opCtx, request.body))); @@ -709,9 +733,10 @@ bool runCommandImpl(OperationContext* opCtx, if (MONGO_unlikely(failWithErrorCodeInRunCommand.shouldFail())) { auto scoped = failWithErrorCodeInRunCommand.scoped(); const auto errorCode = scoped.getData()["errorCode"].numberInt(); - log() << "failWithErrorCodeInRunCommand enabled - failing command with error " - "code: " - << errorCode; + LOGV2(21960, + "failWithErrorCodeInRunCommand enabled - failing command with error " + "code: {errorCode}", + "errorCode"_attr = errorCode); BSONObjBuilder errorBuilder; errorBuilder.append("ok", 0.0); errorBuilder.append("code", errorCode); @@ -951,7 +976,10 @@ void execCommandDatabase(OperationContext* opCtx, } if (command->adminOnly()) { - LOG(2) << "command: " << request.getCommandName(); + LOGV2_DEBUG(21961, + 2, + "command: {request_getCommandName}", + "request_getCommandName"_attr = request.getCommandName()); } if (command->maintenanceMode()) { @@ -1124,11 +1152,17 @@ void execCommandDatabase(OperationContext* opCtx, } appendClusterAndOperationTime(opCtx, &extraFieldsBuilder, &metadataBob, startOperationTime); - LOG(1) << "assertion while executing command '" << request.getCommandName() << "' " - << "on database '" << request.getDatabase() << "' " - << "with arguments '" - << redact(ServiceEntryPointCommon::getRedactedCopyForLogging(command, request.body)) - << "': " << redact(e.toString()); + LOGV2_DEBUG( + 21962, + 1, + "assertion while executing command '{request_getCommandName}' on database " + "'{request_getDatabase}' with arguments " + "'{ServiceEntryPointCommon_getRedactedCopyForLogging_command_request_body}': {e}", + "request_getCommandName"_attr = request.getCommandName(), + "request_getDatabase"_attr = request.getDatabase(), + "ServiceEntryPointCommon_getRedactedCopyForLogging_command_request_body"_attr = + redact(ServiceEntryPointCommon::getRedactedCopyForLogging(command, request.body)), + "e"_attr = redact(e.toString())); generateErrorResponse(opCtx, replyBuilder, e, metadataBob.obj(), extraFieldsBuilder.obj()); } @@ -1174,7 +1208,8 @@ DbResponse receivedCommands(OperationContext* opCtx, // Otherwise, reply with the parse error. This is useful for cases where parsing fails // due to user-supplied input, such as the document too deep error. Since we failed // during parsing, we can't log anything about the command. - LOG(1) << "assertion while parsing command: " << ex.toString(); + LOGV2_DEBUG( + 21963, 1, "assertion while parsing command: {ex}", "ex"_attr = ex.toString()); generateErrorResponse( opCtx, replyBuilder.get(), ex, metadataBob.obj(), extraFieldsBuilder.obj()); @@ -1194,12 +1229,18 @@ DbResponse receivedCommands(OperationContext* opCtx, globalCommandRegistry()->incrementUnknownCommands(); std::string msg = str::stream() << "no such command: '" << request.getCommandName() << "'"; - LOG(2) << msg; + LOGV2_DEBUG(21964, 2, "{msg}", "msg"_attr = msg); uasserted(ErrorCodes::CommandNotFound, str::stream() << msg); } - LOG(2) << "run command " << request.getDatabase() << ".$cmd" << ' ' - << redact(ServiceEntryPointCommon::getRedactedCopyForLogging(c, request.body)); + LOGV2_DEBUG( + 21965, + 2, + "run command {request_getDatabase}.$cmd " + "{ServiceEntryPointCommon_getRedactedCopyForLogging_c_request_body}", + "request_getDatabase"_attr = request.getDatabase(), + "ServiceEntryPointCommon_getRedactedCopyForLogging_c_request_body"_attr = + redact(ServiceEntryPointCommon::getRedactedCopyForLogging(c, request.body))); { // Try to set this as early as possible, as soon as we have figured out the command. @@ -1218,8 +1259,13 @@ DbResponse receivedCommands(OperationContext* opCtx, appendClusterAndOperationTime( opCtx, &extraFieldsBuilder, &metadataBob, LogicalTime::kUninitialized); - LOG(1) << "assertion while executing command '" << request.getCommandName() << "' " - << "on database '" << request.getDatabase() << "': " << ex.toString(); + LOGV2_DEBUG(21966, + 1, + "assertion while executing command '{request_getCommandName}' on database " + "'{request_getDatabase}': {ex}", + "request_getCommandName"_attr = request.getCommandName(), + "request_getDatabase"_attr = request.getDatabase(), + "ex"_attr = ex.toString()); generateErrorResponse( opCtx, replyBuilder.get(), ex, metadataBob.obj(), extraFieldsBuilder.obj()); @@ -1308,7 +1354,11 @@ void receivedKillCursors(OperationContext* opCtx, const Message& m) { int found = runOpKillCursors(opCtx, static_cast<size_t>(n), cursorArray); if (shouldLog(logger::LogSeverity::Debug(1)) || found != n) { - LOG(found == n ? 1 : 0) << "killcursors: found " << found << " of " << n; + LOGV2_DEBUG(21967, + logSeverityV1toV2(found == n ? 1 : 0).toInt(), + "killcursors: found {found} of {n}", + "found"_attr = found, + "n"_attr = n); } } @@ -1523,7 +1573,9 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx, slowMsOverride = 10; receivedKillCursors(opCtx, m); } else if (op != dbInsert && op != dbUpdate && op != dbDelete) { - log() << " operation isn't supported: " << static_cast<int>(op); + LOGV2(21968, + " operation isn't supported: {static_cast_int_op}", + "static_cast_int_op"_attr = static_cast<int>(op)); currentOp.done(); forceLog = true; } else { @@ -1549,8 +1601,11 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx, } } catch (const AssertionException& ue) { LastError::get(c).setLastError(ue.code(), ue.reason()); - LOG(3) << " Caught Assertion in " << networkOpToString(op) << ", continuing " - << redact(ue); + LOGV2_DEBUG(21969, + 3, + " Caught Assertion in {networkOpToString_op}, continuing {ue}", + "networkOpToString_op"_attr = networkOpToString(op), + "ue"_attr = redact(ue)); debug.errInfo = ue.toStatus(); } // A NotMaster error can be set either within receivedInsert/receivedUpdate/receivedDelete @@ -1580,15 +1635,15 @@ DbResponse ServiceEntryPointCommon::handleRequest(OperationContext* opCtx, if (currentOp.shouldDBProfile(shouldSample)) { // Performance profiling is on if (opCtx->lockState()->isReadLocked()) { - LOG(1) << "note: not profiling because recursive read lock"; + LOGV2_DEBUG(21970, 1, "note: not profiling because recursive read lock"); } else if (c.isInDirectClient()) { - LOG(1) << "note: not profiling because we are in DBDirectClient"; + LOGV2_DEBUG(21971, 1, "note: not profiling because we are in DBDirectClient"); } else if (behaviors.lockedForWriting()) { // TODO SERVER-26825: Fix race condition where fsyncLock is acquired post // lockedForWriting() call but prior to profile collection lock acquisition. - LOG(1) << "note: not profiling because doing fsync+lock"; + LOGV2_DEBUG(21972, 1, "note: not profiling because doing fsync+lock"); } else if (storageGlobalParams.readOnly) { - LOG(1) << "note: not profiling because server is read-only"; + LOGV2_DEBUG(21973, 1, "note: not profiling because server is read-only"); } else { invariant(!opCtx->lockState()->inAWriteUnitOfWork()); profile(opCtx, op); |