Skip to content

Commit 745a803

Browse files
rozzarozza
authored
Added operation (aka command name) to structured logging (#1758)
JAVA-5197
1 parent b29b1e1 commit 745a803

File tree

53 files changed

+365
-158
lines changed

Some content is hidden

Large Commits have some content hidden by default. Use the searchbox below for content that may be hidden.

53 files changed

+365
-158
lines changed

‎driver-core/src/main/com/mongodb/internal/connection/BaseCluster.java

Lines changed: 23 additions & 43 deletions
Original file line numberDiff line numberDiff line change
@@ -145,7 +145,7 @@ public ServerTuple selectServer(final ServerSelector serverSelector, final Opera
145145
ServerDeprioritization serverDeprioritization = operationContext.getServerDeprioritization();
146146
boolean selectionWaitingLogged = false;
147147
Timeout computedServerSelectionTimeout = operationContext.getTimeoutContext().computeServerSelectionTimeout();
148-
logServerSelectionStarted(clusterId, operationContext.getId(), serverSelector, description);
148+
logServerSelectionStarted(operationContext, clusterId, serverSelector, description);
149149
while (true) {
150150
CountDownLatch currentPhaseLatch = phase.get();
151151
ClusterDescription currentDescription = description;
@@ -154,24 +154,19 @@ public ServerTuple selectServer(final ServerSelector serverSelector, final Opera
154154
computedServerSelectionTimeout, operationContext.getTimeoutContext());
155155

156156
if (!currentDescription.isCompatibleWithDriver()) {
157-
logAndThrowIncompatibleException(operationContext.getId(), serverSelector, currentDescription);
157+
logAndThrowIncompatibleException(operationContext, serverSelector, currentDescription);
158158
}
159159
if (serverTuple != null) {
160160
ServerAddress serverAddress = serverTuple.getServerDescription().getAddress();
161-
logServerSelectionSucceeded(
162-
clusterId,
163-
operationContext.getId(),
164-
serverAddress,
165-
serverSelector,
166-
currentDescription);
161+
logServerSelectionSucceeded(operationContext, clusterId, serverAddress, serverSelector, currentDescription);
167162
serverDeprioritization.updateCandidate(serverAddress);
168163
return serverTuple;
169164
}
170165
computedServerSelectionTimeout.onExpired(() ->
171166
logAndThrowTimeoutException(operationContext, serverSelector, currentDescription));
172167

173168
if (!selectionWaitingLogged) {
174-
logServerSelectionWaiting(clusterId, operationContext.getId(), computedServerSelectionTimeout, serverSelector, currentDescription);
169+
logServerSelectionWaiting(operationContext, clusterId, computedServerSelectionTimeout, serverSelector, currentDescription);
175170
selectionWaitingLogged = true;
176171
}
177172
connect();
@@ -197,11 +192,7 @@ public void selectServerAsync(final ServerSelector serverSelector, final Operati
197192
CountDownLatch currentPhase = phase.get();
198193
ClusterDescription currentDescription = description;
199194

200-
logServerSelectionStarted(
201-
clusterId,
202-
operationContext.getId(),
203-
serverSelector,
204-
currentDescription);
195+
logServerSelectionStarted(operationContext, clusterId, serverSelector, currentDescription);
205196

206197
if (!handleServerSelectionRequest(request, currentPhase, currentDescription)) {
207198
notifyWaitQueueHandler(request);
@@ -290,12 +281,11 @@ private boolean handleServerSelectionRequest(
290281

291282
try {
292283
OperationContext operationContext = request.getOperationContext();
293-
long operationId = operationContext.getId();
294284
if (currentPhase != request.phase) {
295285
CountDownLatch prevPhase = request.phase;
296286
request.phase = currentPhase;
297287
if (!description.isCompatibleWithDriver()) {
298-
logAndThrowIncompatibleException(operationId, request.originalSelector, description);
288+
logAndThrowIncompatibleException(operationContext, request.originalSelector, description);
299289
}
300290

301291

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

310300
if (serverTuple != null) {
311301
ServerAddress serverAddress = serverTuple.getServerDescription().getAddress();
312-
logServerSelectionSucceeded(
313-
clusterId,
314-
operationId,
315-
serverAddress,
316-
request.originalSelector,
317-
description);
302+
logServerSelectionSucceeded(operationContext, clusterId, serverAddress, request.originalSelector, description);
318303
serverDeprioritization.updateCandidate(serverAddress);
319304
request.onResult(serverTuple, null);
320305
return true;
321306
}
322307
if (prevPhase == null) {
323-
logServerSelectionWaiting(
324-
clusterId,
325-
operationId,
326-
request.getTimeout(),
327-
request.originalSelector,
328-
description);
308+
logServerSelectionWaiting(operationContext, clusterId, request.getTimeout(), request.originalSelector, description);
329309
}
330310
}
331311

@@ -410,11 +390,11 @@ protected ClusterableServer createServer(final ServerAddress serverAddress) {
410390
}
411391

412392
private void logAndThrowIncompatibleException(
413-
final long operationId,
393+
final OperationContext operationContext,
414394
final ServerSelector serverSelector,
415395
final ClusterDescription clusterDescription) {
416396
MongoIncompatibleDriverException exception = createIncompatibleException(clusterDescription);
417-
logServerSelectionFailed(clusterId, operationId, exception, serverSelector, clusterDescription);
397+
logServerSelectionFailed(operationContext, clusterId, exception, serverSelector, clusterDescription);
418398
throw exception;
419399
}
420400

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

451-
logServerSelectionFailed(clusterId, operationContext.getId(), exception, serverSelector, clusterDescription);
431+
logServerSelectionFailed(operationContext, clusterId, exception, serverSelector, clusterDescription);
452432
throw exception;
453433
}
454434

@@ -557,34 +537,34 @@ public void run() {
557537
}
558538

559539
static void logServerSelectionStarted(
540+
final OperationContext operationContext,
560541
final ClusterId clusterId,
561-
final long operationId,
562542
final ServerSelector serverSelector,
563543
final ClusterDescription clusterDescription) {
564544
if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
565545
STRUCTURED_LOGGER.log(new LogMessage(
566546
SERVER_SELECTION, DEBUG, "Server selection started", clusterId,
567547
asList(
568-
new Entry(OPERATION, null),
569-
new Entry(OPERATION_ID, operationId),
548+
new Entry(OPERATION, operationContext.getOperationName()),
549+
new Entry(OPERATION_ID, operationContext.getId()),
570550
new Entry(SELECTOR, serverSelector.toString()),
571551
new Entry(TOPOLOGY_DESCRIPTION, clusterDescription.getShortDescription())),
572552
"Server selection started for operation[ {}] with ID {}. Selector: {}, topology description: {}"));
573553
}
574554
}
575555

576556
private static void logServerSelectionWaiting(
557+
final OperationContext operationContext,
577558
final ClusterId clusterId,
578-
final long operationId,
579559
final Timeout timeout,
580560
final ServerSelector serverSelector,
581561
final ClusterDescription clusterDescription) {
582562
if (STRUCTURED_LOGGER.isRequired(INFO, clusterId)) {
583563
STRUCTURED_LOGGER.log(new LogMessage(
584564
SERVER_SELECTION, INFO, "Waiting for suitable server to become available", clusterId,
585565
asList(
586-
new Entry(OPERATION, null),
587-
new Entry(OPERATION_ID, operationId),
566+
new Entry(OPERATION, operationContext.getOperationName()),
567+
new Entry(OPERATION_ID, operationContext.getId()),
588568
timeout.call(MILLISECONDS,
589569
() -> new Entry(REMAINING_TIME_MS, "infinite"),
590570
(ms) -> new Entry(REMAINING_TIME_MS, ms),
@@ -597,8 +577,8 @@ private static void logServerSelectionWaiting(
597577
}
598578

599579
private static void logServerSelectionFailed(
580+
final OperationContext operationContext,
600581
final ClusterId clusterId,
601-
final long operationId,
602582
final MongoException failure,
603583
final ServerSelector serverSelector,
604584
final ClusterDescription clusterDescription) {
@@ -612,8 +592,8 @@ private static void logServerSelectionFailed(
612592
STRUCTURED_LOGGER.log(new LogMessage(
613593
SERVER_SELECTION, DEBUG, "Server selection failed", clusterId,
614594
asList(
615-
new Entry(OPERATION, null),
616-
new Entry(OPERATION_ID, operationId),
595+
new Entry(OPERATION, operationContext.getOperationName()),
596+
new Entry(OPERATION_ID, operationContext.getId()),
617597
new Entry(FAILURE, failureDescription),
618598
new Entry(SELECTOR, serverSelector.toString()),
619599
new Entry(TOPOLOGY_DESCRIPTION, clusterDescription.getShortDescription())),
@@ -622,17 +602,17 @@ private static void logServerSelectionFailed(
622602
}
623603

624604
static void logServerSelectionSucceeded(
605+
final OperationContext operationContext,
625606
final ClusterId clusterId,
626-
final long operationId,
627607
final ServerAddress serverAddress,
628608
final ServerSelector serverSelector,
629609
final ClusterDescription clusterDescription) {
630610
if (STRUCTURED_LOGGER.isRequired(DEBUG, clusterId)) {
631611
STRUCTURED_LOGGER.log(new LogMessage(
632612
SERVER_SELECTION, DEBUG, "Server selection succeeded", clusterId,
633613
asList(
634-
new Entry(OPERATION, null),
635-
new Entry(OPERATION_ID, operationId),
614+
new Entry(OPERATION, operationContext.getOperationName()),
615+
new Entry(OPERATION_ID, operationContext.getId()),
636616
new Entry(SERVER_HOST, serverAddress.getHost()),
637617
new Entry(SERVER_PORT, serverAddress instanceof UnixServerAddress ? null : serverAddress.getPort()),
638618
new Entry(SELECTOR, serverSelector.toString()),

‎driver-core/src/main/com/mongodb/internal/connection/LoadBalancedCluster.java

Lines changed: 7 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -222,9 +222,9 @@ public ServerTuple selectServer(final ServerSelector serverSelector, final Opera
222222
throw createResolvedToMultipleHostsException();
223223
}
224224
ClusterDescription curDescription = description;
225-
logServerSelectionStarted(clusterId, operationContext.getId(), serverSelector, curDescription);
225+
logServerSelectionStarted(operationContext, clusterId, serverSelector, curDescription);
226226
ServerTuple serverTuple = new ServerTuple(assertNotNull(server), curDescription.getServerDescriptions().get(0));
227-
logServerSelectionSucceeded(clusterId, operationContext.getId(), serverTuple.getServerDescription().getAddress(),
227+
logServerSelectionSucceeded(operationContext, clusterId, serverTuple.getServerDescription().getAddress(),
228228
serverSelector, curDescription);
229229
return serverTuple;
230230
}
@@ -254,8 +254,8 @@ public void selectServerAsync(final ServerSelector serverSelector, final Operati
254254
return;
255255
}
256256
Timeout computedServerSelectionTimeout = operationContext.getTimeoutContext().computeServerSelectionTimeout();
257-
ServerSelectionRequest serverSelectionRequest = new ServerSelectionRequest(operationContext.getId(), serverSelector,
258-
operationContext, computedServerSelectionTimeout, callback);
257+
ServerSelectionRequest serverSelectionRequest = new ServerSelectionRequest(serverSelector, operationContext,
258+
computedServerSelectionTimeout, callback);
259259
if (initializationCompleted) {
260260
handleServerSelectionRequest(serverSelectionRequest);
261261
} else {
@@ -309,9 +309,9 @@ private void handleServerSelectionRequest(final ServerSelectionRequest serverSel
309309
} else {
310310
ClusterDescription curDescription = description;
311311
logServerSelectionStarted(
312-
clusterId, serverSelectionRequest.operationId, serverSelectionRequest.serverSelector, curDescription);
312+
serverSelectionRequest.operationContext, clusterId, serverSelectionRequest.serverSelector, curDescription);
313313
ServerTuple serverTuple = new ServerTuple(assertNotNull(server), curDescription.getServerDescriptions().get(0));
314-
logServerSelectionSucceeded(clusterId, serverSelectionRequest.operationId,
314+
logServerSelectionSucceeded(serverSelectionRequest.operationContext, clusterId,
315315
serverTuple.getServerDescription().getAddress(), serverSelectionRequest.serverSelector, curDescription);
316316
serverSelectionRequest.onSuccess(serverTuple);
317317
}
@@ -416,15 +416,13 @@ public void run() {
416416
}
417417

418418
private static final class ServerSelectionRequest {
419-
private final long operationId;
420419
private final ServerSelector serverSelector;
421420
private final SingleResultCallback<ServerTuple> callback;
422421
private final Timeout timeout;
423422
private final OperationContext operationContext;
424423

425-
private ServerSelectionRequest(final long operationId, final ServerSelector serverSelector, final OperationContext operationContext,
424+
private ServerSelectionRequest(final ServerSelector serverSelector, final OperationContext operationContext,
426425
final Timeout timeout, final SingleResultCallback<ServerTuple> callback) {
427-
this.operationId = operationId;
428426
this.serverSelector = serverSelector;
429427
this.timeout = timeout;
430428
this.operationContext = operationContext;

‎driver-core/src/main/com/mongodb/internal/connection/OperationContext.java

Lines changed: 28 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -49,10 +49,17 @@ public class OperationContext {
4949
private final TimeoutContext timeoutContext;
5050
@Nullable
5151
private final ServerApi serverApi;
52+
@Nullable
53+
private final String operationName;
5254

5355
public OperationContext(final RequestContext requestContext, final SessionContext sessionContext, final TimeoutContext timeoutContext,
5456
@Nullable final ServerApi serverApi) {
55-
this(NEXT_ID.incrementAndGet(), requestContext, sessionContext, timeoutContext, new ServerDeprioritization(), serverApi);
57+
this(requestContext, sessionContext, timeoutContext, serverApi, null);
58+
}
59+
60+
public OperationContext(final RequestContext requestContext, final SessionContext sessionContext, final TimeoutContext timeoutContext,
61+
@Nullable final ServerApi serverApi, @Nullable final String operationName) {
62+
this(NEXT_ID.incrementAndGet(), requestContext, sessionContext, timeoutContext, new ServerDeprioritization(), serverApi, operationName);
5663
}
5764

5865
public static OperationContext simpleOperationContext(
@@ -61,23 +68,29 @@ public static OperationContext simpleOperationContext(
6168
IgnorableRequestContext.INSTANCE,
6269
NoOpSessionContext.INSTANCE,
6370
new TimeoutContext(timeoutSettings),
64-
serverApi);
71+
serverApi,
72+
null);
6573
}
6674

6775
public static OperationContext simpleOperationContext(final TimeoutContext timeoutContext) {
6876
return new OperationContext(
6977
IgnorableRequestContext.INSTANCE,
7078
NoOpSessionContext.INSTANCE,
7179
timeoutContext,
80+
null,
7281
null);
7382
}
7483

7584
public OperationContext withSessionContext(final SessionContext sessionContext) {
76-
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi);
85+
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi, operationName);
7786
}
7887

7988
public OperationContext withTimeoutContext(final TimeoutContext timeoutContext) {
80-
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi);
89+
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi, operationName);
90+
}
91+
92+
public OperationContext withOperationName(final String operationName) {
93+
return new OperationContext(id, requestContext, sessionContext, timeoutContext, serverDeprioritization, serverApi, operationName);
8194
}
8295

8396
public long getId() {
@@ -101,33 +114,42 @@ public ServerApi getServerApi() {
101114
return serverApi;
102115
}
103116

117+
@Nullable
118+
public String getOperationName() {
119+
return operationName;
120+
}
121+
104122
@VisibleForTesting(otherwise = VisibleForTesting.AccessModifier.PRIVATE)
105123
public OperationContext(final long id,
106124
final RequestContext requestContext,
107125
final SessionContext sessionContext,
108126
final TimeoutContext timeoutContext,
109127
final ServerDeprioritization serverDeprioritization,
110-
@Nullable final ServerApi serverApi) {
128+
@Nullable final ServerApi serverApi,
129+
@Nullable final String operationName) {
111130
this.id = id;
112131
this.serverDeprioritization = serverDeprioritization;
113132
this.requestContext = requestContext;
114133
this.sessionContext = sessionContext;
115134
this.timeoutContext = timeoutContext;
116135
this.serverApi = serverApi;
136+
this.operationName = operationName;
117137
}
118138

119139
@VisibleForTesting(otherwise = VisibleForTesting.AccessModifier.PRIVATE)
120140
public OperationContext(final long id,
121141
final RequestContext requestContext,
122142
final SessionContext sessionContext,
123143
final TimeoutContext timeoutContext,
124-
@Nullable final ServerApi serverApi) {
144+
@Nullable final ServerApi serverApi,
145+
@Nullable final String operationName) {
125146
this.id = id;
126147
this.serverDeprioritization = new ServerDeprioritization();
127148
this.requestContext = requestContext;
128149
this.sessionContext = sessionContext;
129150
this.timeoutContext = timeoutContext;
130151
this.serverApi = serverApi;
152+
this.operationName = operationName;
131153
}
132154

133155

‎driver-core/src/main/com/mongodb/internal/logging/LogMessage.java

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -104,9 +104,6 @@ public enum Name {
104104
COMMAND_NAME("commandName"),
105105
REQUEST_ID("requestId"),
106106
OPERATION_ID("operationId"),
107-
/**
108-
* Not supported.
109-
*/
110107
OPERATION("operation"),
111108
AWAITED("awaited"),
112109
SERVICE_ID("serviceId"),

‎driver-core/src/main/com/mongodb/internal/operation/AbortTransactionOperation.java

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -31,6 +31,7 @@
3131
* <p>This class is not part of the public API and may be removed or changed at any time</p>
3232
*/
3333
public class AbortTransactionOperation extends TransactionOperation {
34+
private static final String COMMAND_NAME = "abortTransaction";
3435
private BsonDocument recoveryToken;
3536

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

4546
@Override
46-
protected String getCommandName() {
47-
return "abortTransaction";
47+
public String getCommandName() {
48+
return COMMAND_NAME;
4849
}
4950

5051
@Override

0 commit comments

Comments
 (0)