Skip to content

Added operation (aka command name) to structured logging #1758

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Jul 8, 2025
Merged

Added operation (aka command name) to structured logging #1758

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
03e860b
Added operation (aka command name) to structured logging
rozza Jul 7, 2025
7db12f4
Add overrides
rozza Jul 7, 2025
1de5a19
Renamed commandName to operationName in operation context
rozza Jul 7, 2025
cd60841
Ensure bulk operations use and operationContext with the batches comm…
rozza Jul 7, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
66 changes: 23 additions & 43 deletions driver-core/src/main/com/mongodb/internal/connection/BaseCluster.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -145,7 +145,7 @@ public ServerTuple selectServer(final ServerSelector serverSelector, final Opera
ServerDeprioritization serverDeprioritization = operationContext.getServerDeprioritization();
boolean selectionWaitingLogged = false;
Timeout computedServerSelectionTimeout = operationContext.getTimeoutContext().computeServerSelectionTimeout();
logServerSelectionStarted(clusterId, operationContext.getId(), serverSelector, description);
logServerSelectionStarted(operationContext, clusterId, serverSelector, description);
while (true) {
CountDownLatch currentPhaseLatch = phase.get();
ClusterDescription currentDescription = description;
Expand All @@ -154,24 +154,19 @@ public ServerTuple selectServer(final ServerSelector serverSelector, final Opera
computedServerSelectionTimeout, operationContext.getTimeoutContext());

if (!currentDescription.isCompatibleWithDriver()) {
logAndThrowIncompatibleException(operationContext.getId(), serverSelector, currentDescription);
logAndThrowIncompatibleException(operationContext, serverSelector, currentDescription);
}
if (serverTuple != null) {
ServerAddress serverAddress = serverTuple.getServerDescription().getAddress();
logServerSelectionSucceeded(
clusterId,
operationContext.getId(),
serverAddress,
serverSelector,
currentDescription);
logServerSelectionSucceeded(operationContext, clusterId, serverAddress, serverSelector, currentDescription);
serverDeprioritization.updateCandidate(serverAddress);
return serverTuple;
}
computedServerSelectionTimeout.onExpired(() ->
logAndThrowTimeoutException(operationContext, serverSelector, currentDescription));

if (!selectionWaitingLogged) {
logServerSelectionWaiting(clusterId, operationContext.getId(), computedServerSelectionTimeout, serverSelector, currentDescription);
logServerSelectionWaiting(operationContext, clusterId, computedServerSelectionTimeout, serverSelector, currentDescription);
selectionWaitingLogged = true;
}
connect();
Expand All @@ -197,11 +192,7 @@ public void selectServerAsync(final ServerSelector serverSelector, final Operati
CountDownLatch currentPhase = phase.get();
ClusterDescription currentDescription = description;

logServerSelectionStarted(
clusterId,
operationContext.getId(),
serverSelector,
currentDescription);
logServerSelectionStarted(operationContext, clusterId, serverSelector, currentDescription);

if (!handleServerSelectionRequest(request, currentPhase, currentDescription)) {
notifyWaitQueueHandler(request);
Expand Down Expand Up @@ -290,12 +281,11 @@ private boolean handleServerSelectionRequest(

try {
OperationContext operationContext = request.getOperationContext();
long operationId = operationContext.getId();
if (currentPhase != request.phase) {
CountDownLatch prevPhase = request.phase;
request.phase = currentPhase;
if (!description.isCompatibleWithDriver()) {
logAndThrowIncompatibleException(operationId, request.originalSelector, description);
logAndThrowIncompatibleException(operationContext, request.originalSelector, description);
}


Expand All @@ -309,23 +299,13 @@ private boolean handleServerSelectionRequest(

if (serverTuple != null) {
ServerAddress serverAddress = serverTuple.getServerDescription().getAddress();
logServerSelectionSucceeded(
clusterId,
operationId,
serverAddress,
request.originalSelector,
description);
logServerSelectionSucceeded(operationContext, clusterId, serverAddress, request.originalSelector, description);
serverDeprioritization.updateCandidate(serverAddress);
request.onResult(serverTuple, null);
return true;
}
if (prevPhase == null) {
logServerSelectionWaiting(
clusterId,
operationId,
request.getTimeout(),
request.originalSelector,
description);
logServerSelectionWaiting(operationContext, clusterId, request.getTimeout(), request.originalSelector, description);
}
}

Expand Down Expand Up @@ -410,11 +390,11 @@ protected ClusterableServer createServer(final ServerAddress serverAddress) {
}

private void logAndThrowIncompatibleException(
final long operationId,
final OperationContext operationContext,
final ServerSelector serverSelector,
final ClusterDescription clusterDescription) {
MongoIncompatibleDriverException exception = createIncompatibleException(clusterDescription);
logServerSelectionFailed(clusterId, operationId, exception, serverSelector, clusterDescription);
logServerSelectionFailed(operationContext, clusterId, exception, serverSelector, clusterDescription);
throw exception;
}

Expand Down Expand Up @@ -448,7 +428,7 @@ private void logAndThrowTimeoutException(
MongoTimeoutException exception = operationContext.getTimeoutContext().hasTimeoutMS()
? new MongoOperationTimeoutException(message) : new MongoTimeoutException(message);

logServerSelectionFailed(clusterId, operationContext.getId(), exception, serverSelector, clusterDescription);
logServerSelectionFailed(operationContext, clusterId, exception, serverSelector, clusterDescription);
throw exception;
}

Expand Down Expand Up @@ -557,34 +537,34 @@ public void run() {
}

static void logServerSelectionStarted(
final OperationContext operationContext,
final ClusterId clusterId,
final long operationId,
final ServerSelector serverSelector,
final ClusterDescription clusterDescription) {
if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
STRUCTURED_LOGGER.log(new LogMessage(
SERVER_SELECTION, DEBUG, "Server selection started", clusterId,
asList(
new Entry(OPERATION, null),
new Entry(OPERATION_ID, operationId),
new Entry(OPERATION, operationContext.getOperationName()),
new Entry(OPERATION_ID, operationContext.getId()),
new Entry(SELECTOR, serverSelector.toString()),
new Entry(TOPOLOGY_DESCRIPTION, clusterDescription.getShortDescription())),
"Server selection started for operation[ {}] with ID {}. Selector: {}, topology description: {}"));
}
}

private static void logServerSelectionWaiting(
final OperationContext operationContext,
final ClusterId clusterId,
final long operationId,
final Timeout timeout,
final ServerSelector serverSelector,
final ClusterDescription clusterDescription) {
if (STRUCTURED_LOGGER.isRequired(INFO, clusterId)) {
STRUCTURED_LOGGER.log(new LogMessage(
SERVER_SELECTION, INFO, "Waiting for suitable server to become available", clusterId,
asList(
new Entry(OPERATION, null),
new Entry(OPERATION_ID, operationId),
new Entry(OPERATION, operationContext.getOperationName()),
new Entry(OPERATION_ID, operationContext.getId()),
timeout.call(MILLISECONDS,
() -> new Entry(REMAINING_TIME_MS, "infinite"),
(ms) -> new Entry(REMAINING_TIME_MS, ms),
Expand All @@ -597,8 +577,8 @@ private static void logServerSelectionWaiting(
}

private static void logServerSelectionFailed(
final OperationContext operationContext,
final ClusterId clusterId,
final long operationId,
final MongoException failure,
final ServerSelector serverSelector,
final ClusterDescription clusterDescription) {
Expand All @@ -612,8 +592,8 @@ private static void logServerSelectionFailed(
STRUCTURED_LOGGER.log(new LogMessage(
SERVER_SELECTION, DEBUG, "Server selection failed", clusterId,
asList(
new Entry(OPERATION, null),
new Entry(OPERATION_ID, operationId),
new Entry(OPERATION, operationContext.getOperationName()),
new Entry(OPERATION_ID, operationContext.getId()),
new Entry(FAILURE, failureDescription),
new Entry(SELECTOR, serverSelector.toString()),
new Entry(TOPOLOGY_DESCRIPTION, clusterDescription.getShortDescription())),
Expand All @@ -622,17 +602,17 @@ private static void logServerSelectionFailed(
}

static void logServerSelectionSucceeded(
final OperationContext operationContext,
final ClusterId clusterId,
final long operationId,
final ServerAddress serverAddress,
final ServerSelector serverSelector,
final ClusterDescription clusterDescription) {
if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
STRUCTURED_LOGGER.log(new LogMessage(
SERVER_SELECTION, DEBUG, "Server selection succeeded", clusterId,
asList(
new Entry(OPERATION, null),
new Entry(OPERATION_ID, operationId),
new Entry(OPERATION, operationContext.getOperationName()),
new Entry(OPERATION_ID, operationContext.getId()),
new Entry(SERVER_HOST, serverAddress.getHost()),
new Entry(SERVER_PORT, serverAddress instanceof UnixServerAddress ? null : serverAddress.getPort()),
new Entry(SELECTOR, serverSelector.toString()),
Expand Down
16 changes: 7 additions & 9 deletions driver-core/src/main/com/mongodb/internal/connection/LoadBalancedCluster.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -222,9 +222,9 @@ public ServerTuple selectServer(final ServerSelector serverSelector, final Opera
throw createResolvedToMultipleHostsException();
}
ClusterDescription curDescription = description;
logServerSelectionStarted(clusterId, operationContext.getId(), serverSelector, curDescription);
logServerSelectionStarted(operationContext, clusterId, serverSelector, curDescription);
ServerTuple serverTuple = new ServerTuple(assertNotNull(server), curDescription.getServerDescriptions().get(0));
logServerSelectionSucceeded(clusterId, operationContext.getId(), serverTuple.getServerDescription().getAddress(),
logServerSelectionSucceeded(operationContext, clusterId, serverTuple.getServerDescription().getAddress(),
serverSelector, curDescription);
return serverTuple;
}
Expand Down Expand Up @@ -254,8 +254,8 @@ public void selectServerAsync(final ServerSelector serverSelector, final Operati
return;
}
Timeout computedServerSelectionTimeout = operationContext.getTimeoutContext().computeServerSelectionTimeout();
ServerSelectionRequest serverSelectionRequest = new ServerSelectionRequest(operationContext.getId(), serverSelector,
operationContext, computedServerSelectionTimeout, callback);
ServerSelectionRequest serverSelectionRequest = new ServerSelectionRequest(serverSelector, operationContext,
computedServerSelectionTimeout, callback);
if (initializationCompleted) {
handleServerSelectionRequest(serverSelectionRequest);
} else {
Expand Down Expand Up @@ -309,9 +309,9 @@ private void handleServerSelectionRequest(final ServerSelectionRequest serverSel
} else {
ClusterDescription curDescription = description;
logServerSelectionStarted(
clusterId, serverSelectionRequest.operationId, serverSelectionRequest.serverSelector, curDescription);
serverSelectionRequest.operationContext, clusterId, serverSelectionRequest.serverSelector, curDescription);
ServerTuple serverTuple = new ServerTuple(assertNotNull(server), curDescription.getServerDescriptions().get(0));
logServerSelectionSucceeded(clusterId, serverSelectionRequest.operationId,
logServerSelectionSucceeded(serverSelectionRequest.operationContext, clusterId,
serverTuple.getServerDescription().getAddress(), serverSelectionRequest.serverSelector, curDescription);
serverSelectionRequest.onSuccess(serverTuple);
}
Expand Down Expand Up @@ -416,15 +416,13 @@ public void run() {
}

private static final class ServerSelectionRequest {
private final long operationId;
private final ServerSelector serverSelector;
private final SingleResultCallback<ServerTuple> callback;
private final Timeout timeout;
private final OperationContext operationContext;

private ServerSelectionRequest(final long operationId, final ServerSelector serverSelector, final OperationContext operationContext,
private ServerSelectionRequest(final ServerSelector serverSelector, final OperationContext operationContext,
final Timeout timeout, final SingleResultCallback<ServerTuple> callback) {
this.operationId = operationId;
this.serverSelector = serverSelector;
this.timeout = timeout;
this.operationContext = operationContext;
Expand Down
34 changes: 28 additions & 6 deletions driver-core/src/main/com/mongodb/internal/connection/OperationContext.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,10 +49,17 @@ public class OperationContext {
private final TimeoutContext timeoutContext;
@Nullable
private final ServerApi serverApi;
@Nullable
private final String operationName;

public OperationContext(final RequestContext requestContext, final SessionContext sessionContext, final TimeoutContext timeoutContext,
@Nullable final ServerApi serverApi) {
this(NEXT_ID.incrementAndGet(), requestContext, sessionContext, timeoutContext, new ServerDeprioritization(), serverApi);
this(requestContext, sessionContext, timeoutContext, serverApi, null);
}

public OperationContext(final RequestContext requestContext, final SessionContext sessionContext, final TimeoutContext timeoutContext,
@Nullable final ServerApi serverApi, @Nullable final String operationName) {
this(NEXT_ID.incrementAndGet(), requestContext, sessionContext, timeoutContext, new ServerDeprioritization(), serverApi, operationName);
}

public static OperationContext simpleOperationContext(
Expand All @@ -61,23 +68,29 @@ public static OperationContext simpleOperationContext(
IgnorableRequestContext.INSTANCE,
NoOpSessionContext.INSTANCE,
new TimeoutContext(timeoutSettings),
serverApi);
serverApi,
null);
}

public static OperationContext simpleOperationContext(final TimeoutContext timeoutContext) {
return new OperationContext(
IgnorableRequestContext.INSTANCE,
NoOpSessionContext.INSTANCE,
timeoutContext,
null,
null);
}

public OperationContext withSessionContext(final SessionContext sessionContext) {
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi);
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi, operationName);
}

public OperationContext withTimeoutContext(final TimeoutContext timeoutContext) {
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi);
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi, operationName);
}

public OperationContext withOperationName(final String operationName) {
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi, operationName);
}

public long getId() {
Expand All @@ -101,33 +114,42 @@ public ServerApi getServerApi() {
return serverApi;
}

@Nullable
public String getOperationName() {
return operationName;
}

@VisibleForTesting(otherwise = VisibleForTesting.AccessModifier.PRIVATE)
public OperationContext(final long id,
final RequestContext requestContext,
final SessionContext sessionContext,
final TimeoutContext timeoutContext,
final ServerDeprioritization serverDeprioritization,
@Nullable final ServerApi serverApi) {
@Nullable final ServerApi serverApi,
@Nullable final String operationName) {
this.id = id;
this.serverDeprioritization = serverDeprioritization;
this.requestContext = requestContext;
this.sessionContext = sessionContext;
this.timeoutContext = timeoutContext;
this.serverApi = serverApi;
this.operationName = operationName;
}

@VisibleForTesting(otherwise = VisibleForTesting.AccessModifier.PRIVATE)
public OperationContext(final long id,
final RequestContext requestContext,
final SessionContext sessionContext,
final TimeoutContext timeoutContext,
@Nullable final ServerApi serverApi) {
@Nullable final ServerApi serverApi,
@Nullable final String operationName) {
this.id = id;
this.serverDeprioritization = new ServerDeprioritization();
this.requestContext = requestContext;
this.sessionContext = sessionContext;
this.timeoutContext = timeoutContext;
this.serverApi = serverApi;
this.operationName = operationName;
}


Expand Down
3 changes: 0 additions & 3 deletions driver-core/src/main/com/mongodb/internal/logging/LogMessage.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -104,9 +104,6 @@ public enum Name {
COMMAND_NAME("commandName"),
REQUEST_ID("requestId"),
OPERATION_ID("operationId"),
/**
* Not supported.
*/
OPERATION("operation"),
AWAITED("awaited"),
SERVICE_ID("serviceId"),
Expand Down
5 changes: 3 additions & 2 deletions driver-core/src/main/com/mongodb/internal/operation/AbortTransactionOperation.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -31,6 +31,7 @@
* <p>This class is not part of the public API and may be removed or changed at any time</p>
*/
public class AbortTransactionOperation extends TransactionOperation {
private static final String COMMAND_NAME = "abortTransaction";
private BsonDocument recoveryToken;

public AbortTransactionOperation(final WriteConcern writeConcern) {
Expand All @@ -43,8 +44,8 @@ public AbortTransactionOperation recoveryToken(@Nullable final BsonDocument reco
}

@Override
protected String getCommandName() {
return "abortTransaction";
public String getCommandName() {
return COMMAND_NAME;
}

@Override
Expand Down
Loading