Log retryable writes at DEBUG level

JAVA-2964

Author: jstewart148

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

@@ -53,9 +53,11 @@
 import static com.mongodb.operation.OperationHelper.CallableWithConnectionAndSource;
 import static com.mongodb.operation.OperationHelper.LOGGER;
 import static com.mongodb.operation.OperationHelper.canRetryWrite;
+import static com.mongodb.operation.OperationHelper.isRetryableWrite;
 import static com.mongodb.operation.OperationHelper.releasingCallback;
 import static com.mongodb.operation.OperationHelper.withConnection;
 import static com.mongodb.operation.OperationHelper.withReleasableConnection;
+import static java.lang.String.format;
 import static java.util.Arrays.asList;
 
 final class CommandOperationHelper {
@@ -454,6 +456,9 @@ public R call(final ConnectionSource source, final Connection connection) {
                 } catch (MongoException e) {
                     exception = e;
                     if (!shouldAttemptToRetry(command, e)) {
+                        if (isRetryWritesEnabled(command)) {
+                            logUnableToRetry(command.getFirstKey(), e);
+                        }
                         throw exception;
                     }
                 } finally {
@@ -469,6 +474,7 @@ public R call(final ConnectionSource source, final Connection connection) {
                             if (!canRetryWrite(source.getServerDescription(), connection.getDescription(), binding.getSessionContext())) {
                                 throw originalException;
                             }
+                            logRetryExecute(originalCommand.getFirstKey(), originalException);
                             return transformer.apply(connection.command(database, originalCommand, fieldNameValidator,
                                     readPreference, commandResultDecoder, binding.getSessionContext()),
                                     connection.getDescription().getServerAddress());
@@ -545,6 +551,9 @@ public void onResult(final T result, final Throwable originalError) {
 
             private void checkRetryableException(final Throwable originalError, final SingleResultCallback<R> releasingCallback) {
                 if (!shouldAttemptToRetry(command, originalError)) {
+                    if (isRetryWritesEnabled(command)) {
+                        logUnableToRetry(command.getFirstKey(), originalError);
+                    }
                     releasingCallback.onResult(null, originalError);
                 } else {
                     oldConnection.release();
@@ -554,6 +563,7 @@ private void checkRetryableException(final Throwable originalError, final Single
             }
 
             private void retryableCommand(final Throwable originalError) {
+                logRetryExecute(command.getFirstKey(), originalError);
                 withConnection(binding, new AsyncCallableWithConnectionAndSource() {
                     @Override
                     public void call(final AsyncConnectionSource source, final AsyncConnection connection, final Throwable t) {
@@ -702,16 +712,30 @@ public void onResult(final D response, final Throwable t) {
     }
 
     private static boolean shouldAttemptToRetry(@Nullable final BsonDocument command, final Throwable exception) {
-        return shouldAttemptToRetry(command != null
-                        && (command.containsKey("txnNumber")
-                        || command.getFirstKey().equals("commitTransaction") || command.getFirstKey().equals("abortTransaction")),
-                exception);
+        return isRetryWritesEnabled(command) && isRetryableException(exception);
+    }
+
+    private static boolean isRetryWritesEnabled(@Nullable final BsonDocument command) {
+        return (command != null && (command.containsKey("txnNumber")
+                || command.getFirstKey().equals("commitTransaction") || command.getFirstKey().equals("abortTransaction")));
     }
 
     static boolean shouldAttemptToRetry(final boolean retryWritesEnabled, final Throwable exception) {
         return retryWritesEnabled && isRetryableException(exception);
     }
 
+    static void logRetryExecute(final String operation, final Throwable originalError) {
+        if (LOGGER.isDebugEnabled()) {
+            LOGGER.debug(format("Retrying operation %s due to an error \"%s\"", operation, originalError));
+        }
+    }
+
+    static void logUnableToRetry(final String operation, final Throwable originalError) {
+        if (LOGGER.isDebugEnabled()) {
+            LOGGER.debug(format("Unable to retry operation %s due to error \"%s\"", operation, originalError));
+        }
+    }
+
     private CommandOperationHelper() {
     }
 }

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

@@ -48,6 +48,8 @@
 import static com.mongodb.bulk.WriteRequest.Type.UPDATE;
 import static com.mongodb.internal.async.ErrorHandlingResultCallback.errorHandlingCallback;
 import static com.mongodb.internal.operation.ServerVersionHelper.serverIsAtLeastVersionThreeDotSix;
+import static com.mongodb.operation.CommandOperationHelper.logRetryExecute;
+import static com.mongodb.operation.CommandOperationHelper.logUnableToRetry;
 import static com.mongodb.operation.CommandOperationHelper.shouldAttemptToRetry;
 import static com.mongodb.operation.OperationHelper.AsyncCallableWithConnection;
 import static com.mongodb.operation.OperationHelper.AsyncCallableWithConnectionAndSource;
@@ -274,9 +276,19 @@ private BulkWriteResult executeBulkWriteBatch(final WriteBinding binding, final
         }
 
         if (exception == null) {
-            return currentBatch.getResult();
+            try {
+                return currentBatch.getResult();
+            } catch (MongoException e) {
+                if (originalBatch.getRetryWrites()) {
+                    logUnableToRetry(originalBatch.getPayload().getPayloadType().toString(), e);
+                }
+                throw e;
+            }
         } else if (!(exception instanceof MongoWriteConcernWithResponseException)
                 && !shouldAttemptToRetry(originalBatch.getRetryWrites(), exception)) {
+            if (originalBatch.getRetryWrites()) {
+                logUnableToRetry(originalBatch.getPayload().getPayloadType().toString(), exception);
+            }
             throw exception;
         } else {
             return retryExecuteBatches(binding, currentBatch, exception);
@@ -285,6 +297,7 @@ private BulkWriteResult executeBulkWriteBatch(final WriteBinding binding, final
 
     private BulkWriteResult retryExecuteBatches(final WriteBinding binding, final BulkWriteBatch retryBatch,
                                                 final MongoException originalError) {
+        logRetryExecute(retryBatch.getPayload().getPayloadType().toString(), originalError);
         return withReleasableConnection(binding, originalError, new CallableWithConnectionAndSource<BulkWriteResult>() {
             @Override
             public BulkWriteResult call(final ConnectionSource source, final Connection connection) {
@@ -338,6 +351,7 @@ private void executeBatchesAsync(final AsyncWriteBinding binding, final AsyncCon
 
     private void retryExecuteBatchesAsync(final AsyncWriteBinding binding, final BulkWriteBatch retryBatch,
                                           final Throwable originalError, final SingleResultCallback<BulkWriteResult> callback) {
+        logRetryExecute(retryBatch.getPayload().getPayloadType().toString(), originalError);
         withConnection(binding, new AsyncCallableWithConnectionAndSource() {
             @Override
             public void call(final AsyncConnectionSource source, final AsyncConnection connection, final Throwable t) {
@@ -446,6 +460,9 @@ private SingleResultCallback<BsonDocument> getCommandCallback(final AsyncWriteBi
             public void onResult(final BsonDocument result, final Throwable t) {
                 if (t != null) {
                     if (isSecondAttempt || !shouldAttemptToRetry(retryWrites, t)) {
+                        if (retryWrites && !isSecondAttempt) {
+                            logUnableToRetry(batch.getPayload().getPayloadType().toString(), t);
+                        }
                         if (t instanceof MongoWriteConcernWithResponseException) {
                             addBatchResult((BsonDocument) ((MongoWriteConcernWithResponseException) t).getResponse(), binding, connection,
                                     batch, retryWrites, callback);
@@ -481,6 +498,9 @@ private void addBatchResult(final BsonDocument result, final AsyncWriteBinding b
             executeBatchesAsync(binding, connection, nextBatch, retryWrites, callback);
         } else {
             if (batch.hasErrors()) {
+                if (retryWrites) {
+                    logUnableToRetry(batch.getPayload().getPayloadType().toString(), batch.getError());
+                }
                 callback.onResult(null, batch.getError());
             } else {
                 callback.onResult(batch.getResult(), null);