MongoDB Log Message Analysis - Detailed guide for understanding MongoDB server logs

MONGO_LOGS_GUIDE.md

MongoDB Log Message Analysis Report

Overview

This report provides detailed analysis of MongoDB log messages to help developers understand logs retrieved from running MongoDB instances. Each entry includes the source code location, triggering conditions, logged attributes, and relevant context.

---

1. Slow query

Log ID: 51803 Source Location: src/mongo/db/curop.cpp:841 Component: Query execution / Operation profiling

When It Occurs

This log message is emitted when an operation completes and meets one of the following conditions:

• The operation duration exceeds the configured slowms threshold (default: 100ms)
• The profiling level is set to log slow operations
• A custom profile filter matches the operation
• The operation is forcefully logged (forceLog parameter)

Source Code Context

if (forceLog || shouldLogSlowOp) {
    logv2::DynamicAttributes attr = _reportDebugAndStats(logOptions, true);
    LOGV2_OPTIONS(51803, logOptions, "Slow query", attr);
}

Logged Attributes

The "Slow query" log includes extensive diagnostic information via OpDebug::report():

Core Information:

• type: Operation type ("command" or network operation type)
• isFromUserConnection: Whether this is from a user connection (vs. internal)
• ns: Namespace (database.collection)
• collectionType: Type of collection (standard, timeseries, view, etc.)
• appName: Application name from client metadata (if available)
• command: The actual command/query (redacted for sensitive fields)
• queryShapeHash: Hash identifying the query shape (for query stats)

Timing Metrics:

• executionTime: Total operation duration
• prepareConflictDurationMillis: Time spent waiting on prepare conflicts
• CPU time metrics (if available)

Lock Statistics:

• Lock acquisition times and counts (from SingleThreadedLockStats)
• Lock wait times per lock type

Storage Metrics:

• Documents examined, returned, modified
• Index keys examined
• Storage engine statistics
• Bytes read/written

Additional Context:

• Response length
• Plan summary
• User information
• Various execution-specific metrics

Important Notes

• Ticket Exemption: The code explicitly bypasses ticket acquisition when gathering storage statistics for slow query logging to prevent compounding performance issues
• Comment in code: "Slow query logs are critical for observability and should not wait for ticket acquisition"
• Operations in multi-document transactions may have different reporting behavior
• The slowms threshold can be configured per database or globally

---

2. Ingress TLS handshake complete

Log ID: 6723804 Source Location: src/mongo/transport/asio/asio_session_impl.cpp:836 Component: Transport layer / TLS security

When It Occurs

This log message is emitted when:

1. An incoming TLS/SSL handshake successfully completes
2. The enableDetailedConnectionHealthMetricLogLines parameter is set to true (default: true)

Source Code Context

if (gEnableDetailedConnectionHealthMetricLogLines.load()) {
    LOGV2(6723804,
          "Ingress TLS handshake complete",
          "durationMillis"_attr = handshakeDurationMillis);
}

Logged Attributes

• durationMillis: Time taken to complete the TLS handshake in milliseconds

Additional Effects

When this log is generated, the code also:

• Increments server metrics: totalIngressTLSConnections and totalIngressTLSHandshakeTimeMillis
• Calls IngressHandshakeMetrics::onTLSHandshakeCompleted() to track handshake timing
• Parses and validates the peer certificate (if applicable)

Important Notes

• Part of connection health monitoring introduced in MongoDB 6.0+
• Can be disabled by setting enableDetailedConnectionHealthMetricLogLines: false
• Helps diagnose TLS handshake performance issues
• Only logged for connections using TLS/SSL

---

3. client metadata

Log ID: 51800 Source Location: src/mongo/rpc/metadata/client_metadata.cpp:428 Component: RPC metadata / Client identification

When It Occurs

This log is emitted when:

1. Client metadata is finalized for a connection
2. The client has sent valid metadata in the initial hello command
3. This is the first time the metadata is being logged for this client

Source Code Context

LOGV2(51800,
      "client metadata",
      "remote"_attr = client->getRemote(),
      "client"_attr = client->desc(),
      "negotiatedCompressors"_attr = negotiatedCompressorNames,
      "doc"_attr = getDocument());

Logged Attributes

• remote: Remote endpoint address (IP:port)
• client: Client connection description
• negotiatedCompressors: List of compression algorithms negotiated for this connection
• doc: Full client metadata document containing:
  • driver: Driver name and version
  • os: Operating system type and details
  • application.name: Application name (optional, max 128 bytes)
  • mongos: Router information (if connection went through mongos)

Client Metadata Structure

The metadata document must include:

• Required: driver subdocument with name and version
• Required: os subdocument with type field
• Optional: application subdocument with name field
• Maximum size: 1024 bytes for mongod, 512 bytes for mongos

Important Notes

• Client metadata can only be sent once in the first hello command
• Attempting to send metadata again results in error ClientMetadataCannotBeMutated
• mongos adds additional routing information to client metadata before forwarding
• Used for diagnostics, monitoring, and understanding client driver distribution

---

4. Connection not authenticating

Log ID: 10483900 Source Location: src/mongo/db/repl/hello/hello_auth.cpp:73 Component: Authentication / Hello command processing

When It Occurs

This log is emitted when:

1. A hello (or legacy isMaster) command is received as the initial handshake
2. The command does not include speculative authentication
3. The enableDetailedConnectionHealthMetricLogLines parameter is true

Source Code Context

if (isInitialHandshake && gEnableDetailedConnectionHealthMetricLogLines.load()) {
    auto client = opCtx->getClient();
    auto metadata = ClientMetadata::get(client);
    LOGV2(10483900,
          "Connection not authenticating",
          "client"_attr = client->getRemote(),
          "doc"_attr = metadata ? metadata->getDocument() : BSONObj());
}

Logged Attributes

• client: Remote client address
• doc: Client metadata document (if available, otherwise empty BSON object)

Circumstances

This indicates a connection is being established but:

• Not using speculative authentication (auth piggybacked on hello command)
• Will require separate authenticate or SASL commands for authentication
• Common with older drivers or certain authentication mechanisms

Important Notes

• Part of connection health monitoring
• Helps track authentication patterns and driver behavior
• Does not indicate an error - just documents the authentication flow chosen
• Can be disabled via enableDetailedConnectionHealthMetricLogLines: false

---

5. Auth metrics report

Log ID: 6788604 (SCRAM-SHA) or 6788606 (PLAIN) Source Location:

• src/mongo/db/auth/sasl_scram_server_conversation.cpp:234
• src/mongo/db/auth/sasl_plain_server_conversation.cpp:146 Component: Authentication / Performance monitoring

When It Occurs

This log is emitted during authentication when:

1. The server is acquiring user credentials from the authentication database
2. The enableDetailedConnectionHealthMetricLogLines parameter is true
3. Using SCRAM-SHA or PLAIN authentication mechanisms

Source Code Context (SCRAM example)

if (gEnableDetailedConnectionHealthMetricLogLines.load()) {
    ScopedCallbackTimer timer([&](Microseconds elapsed) {
        LOGV2(6788604,
              "Auth metrics report",
              "metric"_attr = "acquireUser",
              "micros"_attr = elapsed.count());
    });
}

Logged Attributes

• metric: The operation being measured
  • "acquireUser" for SCRAM-SHA mechanisms
  • "plain_acquireUser" for PLAIN mechanism
• micros: Duration of the user acquisition in microseconds

Purpose

This metric helps identify performance issues in authentication, specifically:

• Slow user lookups in the authentication database
• Authorization system bottlenecks
• Database contention during authentication

Important Notes

• Uses ScopedCallbackTimer to measure precise timing
• Only logged if connection health metrics are enabled
• User acquisition involves querying admin.system.users and processing credentials
• High values may indicate:
  • Slow disk I/O on auth database
  • Large user credential documents
  • Lock contention on the auth database

---

6. Successfully authenticated

Log ID: 5286306 Source Location: src/mongo/db/auth/authentication_session.cpp:372 Component: Authentication / Security audit

When It Occurs

This log is emitted when:

1. A client successfully completes authentication
2. All authentication steps have been verified
3. The user has been authorized

Source Code Context

LOGV2(5286306,
      "Successfully authenticated",
      "client"_attr = _client->getRemote(),
      "isSpeculative"_attr = _isSpeculative,
      "isClusterMember"_attr = _isClusterMember,
      "mechanism"_attr = _mechName,
      "user"_attr = _userName.getUser(),
      "db"_attr = _userName.getDB(),
      "result"_attr = Status::OK().code(),
      "metrics"_attr = metrics,
      "doc"_attr = metadata ? metadata->getDocument() : BSONObj(),
      "extraInfo"_attr = extraInfoBob.obj());

Logged Attributes

• client: Remote client address (IP:port)
• isSpeculative: Boolean indicating if this was speculative authentication (piggybacked on hello)
• isClusterMember: Boolean indicating if the authenticated user is a cluster member (internal auth)
• mechanism: Authentication mechanism used (e.g., "SCRAM-SHA-256", "MONGODB-X509", "PLAIN")
• user: Authenticated username
• db: Authentication database
• result: Status code (0 for OK)
• metrics: Authentication metrics captured during the process
• doc: Client metadata document
• extraInfo: Mechanism-specific extra information

Authentication Flow Context

This log appears at the end of successful authentication, which may involve:

• Speculative auth: Authentication data sent with initial hello command
• Regular auth: Separate authenticate or SASL commands
• Mechanisms: SCRAM-SHA-1/256, MONGODB-X509, PLAIN, GSSAPI, etc.

Important Notes

• Critical for security auditing and monitoring
• Always logged (not controlled by enableDetailedConnectionHealthMetricLogLines)
• Complements authentication failure logs
• Metrics may include timing information captured by AuthMetricsRecorder
• Used for compliance and security monitoring

---

7. Connection ended

Log ID: 22944 Source Location: src/mongo/transport/session_manager_common.cpp:419 Component: Transport layer / Session management

When It Occurs

This log is emitted when:

1. A client connection is being terminated
2. The session workflow has completed
3. The server is not in "quiet" mode

Source Code Context

if (!quiet()) {
    LOGV2(22944,
          "Connection ended",
          logv2::DynamicAttributes{logAttrs(summary), "connectionCount"_attr = sync.size()});
}

Logged Attributes

• Dynamic attributes from connection summary (logAttrs(summary)), which may include:
  • Connection duration
  • Remote address
  • Connection ID
  • Other connection-specific metrics
• connectionCount: Number of active connections remaining after this one ends

Circumstances

Connection termination occurs when:

• Client disconnects normally
• Network error or timeout
• Server shutdown
• Connection killed by administrator
• Maximum connection time exceeded
• Authentication failure requiring connection closure

Important Notes

• Suppressed in "quiet" mode (typically during shutdown)
• Helps track connection lifecycle
• Paired with connection establishment logs
• The connectionCount helps monitor server load
• Workflow termination happens before the log to ensure cleanup

---

8. Received first command on ingress connection since session start or auth handshake

Log ID: 6788700 Source Location: src/mongo/transport/ingress_handshake_metrics.cpp:121 Component: Transport metrics / Connection handshake tracking

When It Occurs

This log is emitted when:

1. The first non-authentication command is received on a connection
2. This happens after either:
   • Session start (if no authentication required)
   • Completion of authentication handshake
3. The enableDetailedConnectionHealthMetricLogLines parameter is true

Source Code Context

if (connHealthMetricsLoggingEnabled()) {
    LOGV2(6788700,
          "Received first command on ingress connection since session start or auth handshake",
          "elapsed"_attr = _tickSource->ticksTo<Milliseconds>(now - relativeStart));
}

Logged Attributes

• elapsed: Time elapsed since session start (or since authentication handshake began) in milliseconds

Connection Handshake State Machine

The IngressHandshakeMetrics class tracks this sequence:

1. kWaitingForSessionStart → Session begins
2. kWaitingForFirstCommand → Waiting for any command
3. kWaitingForHelloOrNonAuthCommand → After first command (might be hello)
4. kWaitingForNonAuthCommand → After hello, waiting for first real command
5. kDone → This log fires, metrics recorded

Metrics Recorded

When this log fires, the system also:

• Updates totalTimeToFirstNonAuthCommandMillis metric
• Calculates average time to completed auth
• Finalizes handshake timing measurements

Important Notes

• Part of connection health observability (MongoDB 6.0+)
• Helps identify slow authentication or connection setup
• Retroactively determines authentication duration (state machine doesn't know last auth command until first non-auth arrives)
• Auth-related commands include: hello, isMaster, authenticate, saslStart, saslContinue
• High elapsed times may indicate:
  • Slow authentication database lookups
  • Network latency
  • Client-side delays between commands
  • TLS handshake performance issues

---

Configuration Parameters

enableDetailedConnectionHealthMetricLogLines

IDL Definition: src/mongo/db/connection_health_metrics_parameter.idl Default: true Can be changed: Startup or runtime

This parameter controls several of the log messages in this report:

• "Ingress TLS handshake complete" (6723804)
• "Connection not authenticating" (10483900)
• "Auth metrics report" (6788604, 6788606)
• "Received first command on ingress connection..." (6788700)

To disable at runtime:

db.adminCommand({setParameter: 1, enableDetailedConnectionHealthMetricLogLines: false})

---

Summary Table

Log Message	Log ID	When Enabled	Typical Frequency
Slow query	51803	Always	Based on slowms threshold
Ingress TLS handshake complete	6723804	enableDetailedConnectionHealthMetricLogLines	Once per TLS connection
client metadata	51800	Always	Once per connection with metadata
Connection not authenticating	10483900	enableDetailedConnectionHealthMetricLogLines	Once per non-speculative auth connection
Auth metrics report	6788604/6788606	enableDetailedConnectionHealthMetricLogLines	Once per authentication (during user acquisition)
Successfully authenticated	5286306	Always	Once per successful authentication
Connection ended	22944	Always (except quiet mode)	Once per connection termination
Received first command	6788700	enableDetailedConnectionHealthMetricLogLines	Once per connection

---

Diagnostic Use Cases

Connection Issues

• Check "Ingress TLS handshake complete" for TLS performance
• Check "Received first command" for overall connection setup time
• Compare "Connection ended" count with connection establishment logs

Authentication Problems

• Review "Auth metrics report" for slow user acquisition
• Check "Connection not authenticating" to understand auth flow
• Verify "Successfully authenticated" for auth mechanism and user

Performance Analysis

• "Slow query" logs are primary source for query performance issues
• High "Auth metrics report" micros indicates auth database bottleneck
• Long "Received first command" elapsed time indicates handshake delays

Security Monitoring

• "Successfully authenticated" provides audit trail
• "client metadata" identifies client applications and drivers
• "Connection ended" tracks connection lifecycle

---

Source Code References

All analysis based on MongoDB source code at commit 6686b37e:

• src/mongo/db/curop.cpp - Current operation tracking and slow query logging
• src/mongo/db/op_debug.cpp - Operation debug information reporting
• src/mongo/transport/asio/asio_session_impl.cpp - ASIO transport layer implementation
• src/mongo/rpc/metadata/client_metadata.cpp - Client metadata handling
• src/mongo/db/repl/hello/hello_auth.cpp - Hello command authentication handling
• src/mongo/db/auth/sasl_scram_server_conversation.cpp - SCRAM authentication
• src/mongo/db/auth/sasl_plain_server_conversation.cpp - PLAIN authentication
• src/mongo/db/auth/authentication_session.cpp - Authentication session management
• src/mongo/transport/session_manager_common.cpp - Session lifecycle management
• src/mongo/transport/ingress_handshake_metrics.cpp - Connection handshake metrics
• src/mongo/db/connection_health_metrics_parameter.idl - Connection health parameter definitions