Skip to content

Commit 0efc78c

Browse files
vbabaninvbabanin
authored
Add operation identifier to retry logs. (#1112)
JAVA-4939
1 parent 5848cf5 commit 0efc78c

File tree

5 files changed

+37
-27
lines changed

5 files changed

+37
-27
lines changed

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

Lines changed: 23 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -44,6 +44,7 @@
4444
import com.mongodb.internal.binding.WriteBinding;
4545
import com.mongodb.internal.connection.AsyncConnection;
4646
import com.mongodb.internal.connection.Connection;
47+
import com.mongodb.internal.connection.OperationContext;
4748
import com.mongodb.internal.operation.OperationHelper.ResourceSupplierInternalException;
4849
import com.mongodb.internal.operation.retry.AttachmentKeys;
4950
import com.mongodb.internal.validator.NoOpFieldNameValidator;
@@ -183,19 +184,20 @@ static RetryState initialRetryState(final boolean retry) {
183184
return new RetryState(retry ? RetryState.RETRIES : 0);
184185
}
185186

186-
static <R> Supplier<R> decorateReadWithRetries(final RetryState retryState, final Supplier<R> readFunction) {
187+
static <R> Supplier<R> decorateReadWithRetries(final RetryState retryState, final OperationContext operationContext,
188+
final Supplier<R> readFunction) {
187189
return new RetryingSyncSupplier<>(retryState, CommandOperationHelper::chooseRetryableReadException,
188190
CommandOperationHelper::shouldAttemptToRetryRead, () -> {
189-
logRetryExecute(retryState);
191+
logRetryExecute(retryState, operationContext);
190192
return readFunction.get();
191193
});
192194
}
193195

194-
static <R> AsyncCallbackSupplier<R> decorateReadWithRetries(final RetryState retryState,
196+
static <R> AsyncCallbackSupplier<R> decorateReadWithRetries(final RetryState retryState, final OperationContext operationContext,
195197
final AsyncCallbackSupplier<R> asyncReadFunction) {
196198
return new RetryingAsyncCallbackSupplier<>(retryState, CommandOperationHelper::chooseRetryableReadException,
197199
CommandOperationHelper::shouldAttemptToRetryRead, callback -> {
198-
logRetryExecute(retryState);
200+
logRetryExecute(retryState, operationContext);
199201
asyncReadFunction.get(callback);
200202
});
201203
}
@@ -219,7 +221,7 @@ static <D, T> T executeRetryableRead(
219221
final CommandReadTransformer<D, T> transformer,
220222
final boolean retryReads) {
221223
RetryState retryState = initialRetryState(retryReads);
222-
Supplier<T> read = decorateReadWithRetries(retryState, () ->
224+
Supplier<T> read = decorateReadWithRetries(retryState, binding.getOperationContext(), () ->
223225
withSourceAndConnection(readConnectionSourceSupplier, false, (source, connection) -> {
224226
retryState.breakAndThrowIfRetryAnd(() -> !canRetryRead(source.getServerDescription(), binding.getSessionContext()));
225227
return createReadCommandAndExecute(retryState, binding, source, database, commandCreator, decoder, transformer, connection);
@@ -288,7 +290,8 @@ static <D, T> void executeRetryableReadAsync(
288290
final SingleResultCallback<T> callback) {
289291
RetryState retryState = initialRetryState(retryReads);
290292
binding.retain();
291-
AsyncCallbackSupplier<T> asyncRead = CommandOperationHelper.<T>decorateReadWithRetries(retryState, funcCallback ->
293+
AsyncCallbackSupplier<T> asyncRead = CommandOperationHelper.<T>decorateReadWithRetries(retryState, binding.getOperationContext(),
294+
funcCallback ->
292295
withAsyncSourceAndConnection(sourceAsyncSupplier, false, funcCallback,
293296
(source, connection, releasingCallback) -> {
294297
if (retryState.breakAndCompleteIfRetryAnd(() -> !canRetryRead(source.getServerDescription(),
@@ -375,19 +378,20 @@ static <T> void executeCommandAsync(final AsyncWriteBinding binding,
375378
binding, transformingWriteCallback(transformer, connection, addingRetryableLabelCallback));
376379
}
377380

378-
static <R> Supplier<R> decorateWriteWithRetries(final RetryState retryState, final Supplier<R> writeFunction) {
381+
static <R> Supplier<R> decorateWriteWithRetries(final RetryState retryState,
382+
final OperationContext operationContext, final Supplier<R> writeFunction) {
379383
return new RetryingSyncSupplier<>(retryState, CommandOperationHelper::chooseRetryableWriteException,
380384
CommandOperationHelper::shouldAttemptToRetryWrite, () -> {
381-
logRetryExecute(retryState);
385+
logRetryExecute(retryState, operationContext);
382386
return writeFunction.get();
383387
});
384388
}
385389

386-
static <R> AsyncCallbackSupplier<R> decorateWriteWithRetries(final RetryState retryState,
390+
static <R> AsyncCallbackSupplier<R> decorateWriteWithRetries(final RetryState retryState, final OperationContext operationContext,
387391
final AsyncCallbackSupplier<R> asyncWriteFunction) {
388392
return new RetryingAsyncCallbackSupplier<>(retryState, CommandOperationHelper::chooseRetryableWriteException,
389393
CommandOperationHelper::shouldAttemptToRetryWrite, callback -> {
390-
logRetryExecute(retryState);
394+
logRetryExecute(retryState, operationContext);
391395
asyncWriteFunction.get(callback);
392396
});
393397
}
@@ -402,7 +406,7 @@ static <T, R> R executeRetryableWrite(
402406
final CommandWriteTransformer<T, R> transformer,
403407
final Function<BsonDocument, BsonDocument> retryCommandModifier) {
404408
RetryState retryState = initialRetryState(true);
405-
Supplier<R> retryingWrite = decorateWriteWithRetries(retryState, () -> {
409+
Supplier<R> retryingWrite = decorateWriteWithRetries(retryState, binding.getOperationContext(), () -> {
406410
boolean firstAttempt = retryState.isFirstAttempt();
407411
if (!firstAttempt && binding.getSessionContext().hasActiveTransaction()) {
408412
binding.getSessionContext().clearTransactionContext();
@@ -451,7 +455,8 @@ static <T, R> void executeRetryableWriteAsync(
451455
final SingleResultCallback<R> callback) {
452456
RetryState retryState = initialRetryState(true);
453457
binding.retain();
454-
AsyncCallbackSupplier<R> asyncWrite = CommandOperationHelper.<R>decorateWriteWithRetries(retryState, funcCallback -> {
458+
AsyncCallbackSupplier<R> asyncWrite = CommandOperationHelper.<R>decorateWriteWithRetries(retryState,
459+
binding.getOperationContext(), funcCallback -> {
455460
boolean firstAttempt = retryState.isFirstAttempt();
456461
if (!firstAttempt && binding.getSessionContext().hasActiveTransaction()) {
457462
binding.getSessionContext().clearTransactionContext();
@@ -601,15 +606,17 @@ static void addRetryableWriteErrorLabel(final MongoException exception, final in
601606
}
602607
}
603608

604-
static void logRetryExecute(final RetryState retryState) {
609+
static void logRetryExecute(final RetryState retryState, final OperationContext operationContext) {
605610
if (LOGGER.isDebugEnabled() && !retryState.isFirstAttempt()) {
606611
String commandDescription = retryState.attachment(AttachmentKeys.commandDescriptionSupplier()).map(Supplier::get).orElse(null);
607612
Throwable exception = retryState.exception().orElseThrow(Assertions::fail);
608613
int oneBasedAttempt = retryState.attempt() + 1;
614+
long operationId = operationContext.getId();
609615
LOGGER.debug(commandDescription == null
610-
? format("Retrying the operation due to the error \"%s\"; attempt #%d", exception, oneBasedAttempt)
611-
: format("Retrying the operation '%s' due to the error \"%s\"; attempt #%d",
612-
commandDescription, exception, oneBasedAttempt));
616+
? format("Retrying the operation with operation ID %s due to the error \"%s\". Attempt number: #%d",
617+
operationId, exception, oneBasedAttempt)
618+
: format("Retrying the operation '%s' with operation ID %s due to the error \"%s\". Attempt number: #%d",
619+
commandDescription, operationId, exception, oneBasedAttempt));
613620
}
614621
}
615622

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -317,7 +317,7 @@ public FindOperation<T> allowDiskUse(@Nullable final Boolean allowDiskUse) {
317317
@Override
318318
public BatchCursor<T> execute(final ReadBinding binding) {
319319
RetryState retryState = initialRetryState(retryReads);
320-
Supplier<BatchCursor<T>> read = decorateReadWithRetries(retryState, () ->
320+
Supplier<BatchCursor<T>> read = decorateReadWithRetries(retryState, binding.getOperationContext(), () ->
321321
withSourceAndConnection(binding::getReadConnectionSource, false, (source, connection) -> {
322322
retryState.breakAndThrowIfRetryAnd(() -> !canRetryRead(source.getServerDescription(), binding.getSessionContext()));
323323
try {
@@ -338,7 +338,7 @@ public void executeAsync(final AsyncReadBinding binding, final SingleResultCallb
338338
RetryState retryState = initialRetryState(retryReads);
339339
binding.retain();
340340
AsyncCallbackSupplier<AsyncBatchCursor<T>> asyncRead = CommandOperationHelper.<AsyncBatchCursor<T>>decorateReadWithRetries(
341-
retryState, funcCallback ->
341+
retryState, binding.getOperationContext(), funcCallback ->
342342
withAsyncSourceAndConnection(binding::getReadConnectionSource, false, funcCallback,
343343
(source, connection, releasingCallback) -> {
344344
if (retryState.breakAndCompleteIfRetryAnd(() -> !canRetryRead(source.getServerDescription(),

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -141,7 +141,7 @@ public ListCollectionsOperation<T> comment(@Nullable final BsonValue comment) {
141141
@Override
142142
public BatchCursor<T> execute(final ReadBinding binding) {
143143
RetryState retryState = initialRetryState(retryReads);
144-
Supplier<BatchCursor<T>> read = decorateReadWithRetries(retryState, () ->
144+
Supplier<BatchCursor<T>> read = decorateReadWithRetries(retryState, binding.getOperationContext(), () ->
145145
withSourceAndConnection(binding::getReadConnectionSource, false, (source, connection) -> {
146146
retryState.breakAndThrowIfRetryAnd(() -> !canRetryRead(source.getServerDescription(), binding.getSessionContext()));
147147
try {
@@ -161,7 +161,7 @@ public void executeAsync(final AsyncReadBinding binding, final SingleResultCallb
161161
RetryState retryState = initialRetryState(retryReads);
162162
binding.retain();
163163
AsyncCallbackSupplier<AsyncBatchCursor<T>> asyncRead = CommandOperationHelper.<AsyncBatchCursor<T>>decorateReadWithRetries(
164-
retryState, funcCallback ->
164+
retryState, binding.getOperationContext(), funcCallback ->
165165
withAsyncSourceAndConnection(binding::getReadConnectionSource, false, funcCallback,
166166
(source, connection, releasingCallback) -> {
167167
if (retryState.breakAndCompleteIfRetryAnd(() -> !canRetryRead(source.getServerDescription(),

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

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -119,7 +119,7 @@ public ListIndexesOperation<T> comment(@Nullable final BsonValue comment) {
119119
@Override
120120
public BatchCursor<T> execute(final ReadBinding binding) {
121121
RetryState retryState = initialRetryState(retryReads);
122-
Supplier<BatchCursor<T>> read = decorateReadWithRetries(retryState, () ->
122+
Supplier<BatchCursor<T>> read = decorateReadWithRetries(retryState, binding.getOperationContext(), () ->
123123
withSourceAndConnection(binding::getReadConnectionSource, false, (source, connection) -> {
124124
retryState.breakAndThrowIfRetryAnd(() -> !canRetryRead(source.getServerDescription(), binding.getSessionContext()));
125125
try {
@@ -139,7 +139,7 @@ public void executeAsync(final AsyncReadBinding binding, final SingleResultCallb
139139
RetryState retryState = initialRetryState(retryReads);
140140
binding.retain();
141141
AsyncCallbackSupplier<AsyncBatchCursor<T>> asyncRead = CommandOperationHelper.<AsyncBatchCursor<T>>decorateReadWithRetries(
142-
retryState, funcCallback ->
142+
retryState, binding.getOperationContext(), funcCallback ->
143143
withAsyncSourceAndConnection(binding::getReadConnectionSource, false, funcCallback,
144144
(source, connection, releasingCallback) -> {
145145
if (retryState.breakAndCompleteIfRetryAnd(() -> !canRetryRead(source.getServerDescription(),

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

Lines changed: 8 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -36,6 +36,7 @@
3636
import com.mongodb.internal.connection.AsyncConnection;
3737
import com.mongodb.internal.connection.Connection;
3838
import com.mongodb.internal.connection.MongoWriteConcernWithResponseException;
39+
import com.mongodb.internal.connection.OperationContext;
3940
import com.mongodb.internal.connection.ProtocolHelper;
4041
import com.mongodb.internal.operation.retry.AttachmentKeys;
4142
import com.mongodb.internal.session.SessionContext;
@@ -137,19 +138,20 @@ public Boolean getRetryWrites() {
137138
return retryWrites;
138139
}
139140

140-
private <R> Supplier<R> decorateWriteWithRetries(final RetryState retryState, final Supplier<R> writeFunction) {
141+
private <R> Supplier<R> decorateWriteWithRetries(final RetryState retryState, final OperationContext operationContext,
142+
final Supplier<R> writeFunction) {
141143
return new RetryingSyncSupplier<>(retryState, CommandOperationHelper::chooseRetryableWriteException,
142144
this::shouldAttemptToRetryWrite, () -> {
143-
logRetryExecute(retryState);
145+
logRetryExecute(retryState, operationContext);
144146
return writeFunction.get();
145147
});
146148
}
147149

148-
private <R> AsyncCallbackSupplier<R> decorateWriteWithRetries(final RetryState retryState,
150+
private <R> AsyncCallbackSupplier<R> decorateWriteWithRetries(final RetryState retryState, final OperationContext operationContext,
149151
final AsyncCallbackSupplier<R> writeFunction) {
150152
return new RetryingAsyncCallbackSupplier<>(retryState, CommandOperationHelper::chooseRetryableWriteException,
151153
this::shouldAttemptToRetryWrite, callback -> {
152-
logRetryExecute(retryState);
154+
logRetryExecute(retryState, operationContext);
153155
writeFunction.get(callback);
154156
});
155157
}
@@ -182,7 +184,7 @@ public BulkWriteResult execute(final WriteBinding binding) {
182184
* and the code related to the attempt tracking in `BulkWriteTracker` will be removed. */
183185
RetryState retryState = new RetryState();
184186
BulkWriteTracker.attachNew(retryState, retryWrites);
185-
Supplier<BulkWriteResult> retryingBulkWrite = decorateWriteWithRetries(retryState, () ->
187+
Supplier<BulkWriteResult> retryingBulkWrite = decorateWriteWithRetries(retryState, binding.getOperationContext(), () ->
186188
withSourceAndConnection(binding::getWriteConnectionSource, true, (source, connection) -> {
187189
ConnectionDescription connectionDescription = connection.getDescription();
188190
// attach `maxWireVersion` ASAP because it is used to check whether we can retry
@@ -214,6 +216,7 @@ public void executeAsync(final AsyncWriteBinding binding, final SingleResultCall
214216
BulkWriteTracker.attachNew(retryState, retryWrites);
215217
binding.retain();
216218
AsyncCallbackSupplier<BulkWriteResult> retryingBulkWrite = this.<BulkWriteResult>decorateWriteWithRetries(retryState,
219+
binding.getOperationContext(),
217220
funcCallback ->
218221
withAsyncSourceAndConnection(binding::getWriteConnectionSource, true, funcCallback,
219222
(source, connection, releasingCallback) -> {

0 commit comments

Comments
 (0)