DATAMONGO-2224 - Add trace logging to DBRef resolution.

We added trace logging to DefaultDbRefResolver.

<logger name="org.springframework.data.mongodb.core.convert.DefaultDbRefResolver" level="trace"/>

Original pull request: #659.

spring-data-mongodb/src/main/java/org/springframework/data/mongodb/core/convert/DefaultDbRefResolver.java

@@ -32,6 +32,8 @@ import java.util.stream.Stream;
 import org.aopalliance.intercept.MethodInterceptor;
 import org.aopalliance.intercept.MethodInvocation;
 import org.bson.Document;
+import org.slf4j.Logger;
+import org.slf4j.LoggerFactory;
 import org.springframework.aop.framework.ProxyFactory;
 import org.springframework.cglib.proxy.Callback;
 import org.springframework.cglib.proxy.Enhancer;
@@ -66,6 +68,8 @@ import com.mongodb.client.model.Filters;
  */
 public class DefaultDbRefResolver implements DbRefResolver {
 
+	private static final Logger LOGGER = LoggerFactory.getLogger(DefaultDbRefResolver.class);
+
 	private final MongoDbFactory mongoDbFactory;
 	private final PersistenceExceptionTranslator exceptionTranslator;
 	private final ObjenesisStd objenesis;
@@ -110,6 +114,12 @@ public class DefaultDbRefResolver implements DbRefResolver {
 	@Override
 	public Document fetch(DBRef dbRef) {
 
+		if (LOGGER.isTraceEnabled()) {
+			LOGGER.trace("Fetching DBRef '{}' from {}.{}.", dbRef.getId(),
+					StringUtils.hasText(dbRef.getDatabaseName()) ? dbRef.getDatabaseName() : mongoDbFactory.getDb().getName(),
+					dbRef.getCollectionName());
+		}
+
 		StringUtils.hasText(dbRef.getDatabaseName());
 		return getCollection(dbRef).find(Filters.eq("_id", dbRef.getId())).first();
 	}
@@ -141,7 +151,16 @@ public class DefaultDbRefResolver implements DbRefResolver {
 			ids.add(ref.getId());
 		}
 
-		List<Document> result = getCollection(refs.iterator().next()) //
+		DBRef databaseSource = refs.iterator().next();
+
+		if (LOGGER.isTraceEnabled()) {
+			LOGGER.trace("Bulk fetching DBRefs {} from {}.{}.", ids,
+					StringUtils.hasText(databaseSource.getDatabaseName()) ? databaseSource.getDatabaseName()
+							: mongoDbFactory.getDb().getName(),
+					databaseSource.getCollectionName());
+		}
+
+		List<Document> result = getCollection(databaseSource) //
 				.find(new Document("_id", new Document("$in", ids))) //
 				.into(new ArrayList<>());
 
@@ -438,26 +457,34 @@ public class DefaultDbRefResolver implements DbRefResolver {
 		@Nullable
 		private synchronized Object resolve() {
 
-			if (!resolved) {
+			if (resolved) {
 
-				try {
+				if (LOGGER.isTraceEnabled()) {
+					LOGGER.trace("Accessing already resolved lazy loading property {}.{}",
+							property.getOwner() != null ? property.getOwner().getName() : "unknown", property.getName());
+				}
+				return result;
+			}
 
-					return callback.resolve(property);
+			try {
+				if (LOGGER.isTraceEnabled()) {
+					LOGGER.trace("Resolving lazy loading property {}.{}",
+							property.getOwner() != null ? property.getOwner().getName() : "unknown", property.getName());
+				}
 
-				} catch (RuntimeException ex) {
+				return callback.resolve(property);
 
-					DataAccessException translatedException = this.exceptionTranslator.translateExceptionIfPossible(ex);
+			} catch (RuntimeException ex) {
 
-					if (translatedException instanceof ClientSessionException) {
-						throw new LazyLoadingException("Unable to lazily resolve DBRef! Invalid session state.", ex);
-					}
+				DataAccessException translatedException = this.exceptionTranslator.translateExceptionIfPossible(ex);
 
-					throw new LazyLoadingException("Unable to lazily resolve DBRef!",
-							translatedException != null ? translatedException : ex);
+				if (translatedException instanceof ClientSessionException) {
+					throw new LazyLoadingException("Unable to lazily resolve DBRef! Invalid session state.", ex);
 				}
-			}
 
-			return result;
+				throw new LazyLoadingException("Unable to lazily resolve DBRef!",
+						translatedException != null ? translatedException : ex);
+			}
 		}
 	}
 

src/main/asciidoc/reference/mapping.adoc

@@ -593,6 +593,9 @@ IMPORTANT: The mapping framework does not handle cascading saves. If you change
 ``DBRef``s can also be resolved lazily. In this case the actual `Object` or `Collection` of references is resolved on first access of the property. Use the `lazy` attribute of `@DBRef` to specify this.
 Required properties that are also defined as lazy loading ``DBRef`` and used as constructor arguments are also decorated with the lazy loading proxy making sure to put as little pressure on the database and network as possible.
 
+TIP: Lazily loaded ``DBRef``s can be hard to debug. Make sure tooling does not accidentally trigger proxy resolution by eg. calling `toString()` or some inline debug rendering invoking property getters.
+Please consider to enable _trace_ logging for `org.springframework.data.mongodb.core.convert.DefaultDbRefResolver` to gain insight on `DBRef` resolution.
+
 [[mapping-usage-events]]
 === Mapping Framework Events