Skip to content

Added more logging statements to MongoTemplate #4782

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

Open
wants to merge 3 commits into
base: 4.2.x
Choose a base branch
from
+138 −37
Open

Added more logging statements to MongoTemplate #4782

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
f28c4aa
WIP on logging improvements
marcingrzejszczak Sep 11, 2024
ccf7d1c
Added more logging
marcingrzejszczak Sep 12, 2024
56c8b37
Prepare issue branch
marcingrzejszczak Sep 12, 2024
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
2 changes: 1 addition & 1 deletion pom.xml
View file
Original file line number Diff line number Diff line change
@@ -5,7 +5,7 @@

<groupId>org.springframework.data</groupId>
<artifactId>spring-data-mongodb-parent</artifactId>
<version>4.2.10-SNAPSHOT</version>
<version>4.2.10-4755-SNAPSHOT</version>
<packaging>pom</packaging>

<name>Spring Data MongoDB</name>
2 changes: 1 addition & 1 deletion spring-data-mongodb-benchmarks/pom.xml
View file
Original file line number Diff line number Diff line change
@@ -7,7 +7,7 @@
<parent>
<groupId>org.springframework.data</groupId>
<artifactId>spring-data-mongodb-parent</artifactId>
<version>4.2.10-SNAPSHOT</version>
<version>4.2.10-4755-SNAPSHOT</version>
<relativePath>../pom.xml</relativePath>
</parent>

2 changes: 1 addition & 1 deletion spring-data-mongodb-distribution/pom.xml
View file
Original file line number Diff line number Diff line change
@@ -15,7 +15,7 @@
<parent>
<groupId>org.springframework.data</groupId>
<artifactId>spring-data-mongodb-parent</artifactId>
<version>4.2.10-SNAPSHOT</version>
<version>4.2.10-4755-SNAPSHOT</version>
<relativePath>../pom.xml</relativePath>
</parent>

2 changes: 1 addition & 1 deletion spring-data-mongodb/pom.xml
View file
Original file line number Diff line number Diff line change
@@ -13,7 +13,7 @@
<parent>
<groupId>org.springframework.data</groupId>
<artifactId>spring-data-mongodb-parent</artifactId>
<version>4.2.10-SNAPSHOT</version>
<version>4.2.10-4755-SNAPSHOT</version>
<relativePath>../pom.xml</relativePath>
</parent>

167 changes: 134 additions & 33 deletions spring-data-mongodb/src/main/java/org/springframework/data/mongodb/core/MongoTemplate.java
View file
Original file line number Diff line number Diff line change
@@ -99,6 +99,7 @@
import org.springframework.data.mongodb.core.query.Meta;
import org.springframework.data.mongodb.core.query.NearQuery;
import org.springframework.data.mongodb.core.query.Query;
import org.springframework.data.mongodb.core.query.SerializationUtils;
import org.springframework.data.mongodb.core.query.UpdateDefinition;
import org.springframework.data.mongodb.core.query.UpdateDefinition.ArrayFilter;
import org.springframework.data.mongodb.core.timeseries.Granularity;
@@ -179,6 +180,7 @@
* @author Bartłomiej Mazur
* @author Michael Krog
* @author Jakub Zurawa
* @author Marcin Grzejszczak
*/
public class MongoTemplate
implements MongoOperations, ApplicationContextAware, IndexOperationsProvider, ReadPreferenceAware {
@@ -491,6 +493,13 @@ protected <T> Stream<T> doStream(Query query, Class<?> entityType, String collec
Document mappedQuery = queryContext.getMappedQuery(persistentEntity);
Document mappedFields = queryContext.getMappedFields(persistentEntity, projection);

if (LOGGER.isDebugEnabled()) {
Document sort = getMappedSortObject(query, entityType);
LOGGER.debug(String.format(
"doStream using query: [%s] fields: [%s] sort: [%s] for class: [%s] in collection: [%s]",
serializeToJsonSafely(mappedQuery), mappedFields, serializeToJsonSafely(sort), entityType, collectionName));
}

CollectionPreparerDelegate readPreference = createDelegate(query);
FindIterable<Document> cursor = new QueryCursorPreparer(query, entityType).initiateFind(collection,
col -> readPreference.prepare(col).find(mappedQuery, Document.class).projection(mappedFields));
@@ -511,6 +520,11 @@ public Document executeCommand(String jsonCommand) {

Assert.hasText(jsonCommand, "JsonCommand must not be null nor empty");

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Executing command: [%s]", jsonCommand));
}

return execute(db -> db.runCommand(Document.parse(jsonCommand), Document.class));
}

@@ -520,6 +534,11 @@ public Document executeCommand(Document command) {

Assert.notNull(command, "Command must not be null");

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Executing command: [%s]", serializeToJsonSafely(command)));
}

return execute(db -> db.runCommand(command, Document.class));
}

@@ -529,6 +548,11 @@ public Document executeCommand(Document command, @Nullable ReadPreference readPr

Assert.notNull(command, "Command must not be null");

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Executing command: [%s]%s", serializeToJsonSafely(command), readPreference != null ? (" with read preference: [" + readPreference + "]") : ""));
}

return execute(db -> readPreference != null //
? db.runCommand(command, readPreference, Document.class) //
: db.runCommand(command, Document.class));
@@ -562,7 +586,7 @@ protected void executeQuery(Query query, String collectionName, DocumentCallback
Document fieldsObject = query.getFieldsObject();

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Executing query: %s fields: %s sort: %s in collection: %s",
LOGGER.debug(String.format("Executing query: [%s] fields: [%s] sort: [%s] in collection: [%s]",
serializeToJsonSafely(queryObject), fieldsObject, serializeToJsonSafely(sortObject), collectionName));
}

@@ -596,6 +620,11 @@ public <T> T execute(String collectionName, CollectionCallback<T> callback) {
Assert.notNull(collectionName, "CollectionName must not be null");
Assert.notNull(callback, "CollectionCallback must not be null");

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Executing collection callback for collection: [%s]", collectionName));
}

try {
MongoCollection<Document> collection = getAndPrepareCollection(doGetDatabase(), collectionName);
return callback.doInCollection(collection);
@@ -956,7 +985,7 @@ public <T> List<T> findDistinct(Query query, String field, String collectionName
MongoIterable<?> result = execute(collectionName, (collection) -> {

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Executing findDistinct using query %s for field: %s in collection: %s",
LOGGER.debug(String.format("Executing findDistinct using query [%s] for field: [%s] in collection: [%s]",
serializeToJsonSafely(mappedQuery), field, collectionName));
}

@@ -1188,7 +1217,7 @@ protected long doCount(CollectionPreparer collectionPreparer, String collectionN

if (LOGGER.isDebugEnabled()) {
LOGGER
.debug(String.format("Executing count: %s in collection: %s", serializeToJsonSafely(filter), collectionName));
.debug(String.format("Executing count: [%s] in collection: [%s]", serializeToJsonSafely(filter), collectionName));
}

return countExecution.countDocuments(collectionPreparer, collectionName, filter, options);
@@ -1524,7 +1553,7 @@ protected <T> T doSave(String collectionName, T objectToSave, MongoWriter<T> wri
protected Object insertDocument(String collectionName, Document document, Class<?> entityClass) {

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Inserting Document containing fields: %s in collection: %s", document.keySet(),
LOGGER.debug(String.format("Inserting Document containing fields: [%s] in collection: [%s]", document.keySet(),
collectionName));
}

@@ -1553,7 +1582,7 @@ protected List<Object> insertDocumentList(String collectionName, List<Document>
}

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Inserting list of Documents containing %s items", documents.size()));
LOGGER.debug(String.format("Inserting list of Documents containing [%s] items", documents.size()));
}

execute(collectionName, collection -> {
@@ -1577,7 +1606,7 @@ protected List<Object> insertDocumentList(String collectionName, List<Document>
protected Object saveDocument(String collectionName, Document dbDoc, Class<?> entityClass) {

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Saving Document containing fields: %s", dbDoc.keySet()));
LOGGER.debug(String.format("Saving Document containing fields: [%s]", dbDoc.keySet()));
}

return execute(collectionName, collection -> {
@@ -1707,7 +1736,7 @@ protected UpdateResult doUpdate(String collectionName, Query query, UpdateDefini
return execute(collectionName, collection -> {

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Calling update using query: %s and update: %s in collection: %s",
LOGGER.debug(String.format("Calling update using query: [%s] and update: [%s] in collection: [%s]",
serializeToJsonSafely(queryObj), serializeToJsonSafely(pipeline), collectionName));
}

@@ -1725,7 +1754,7 @@ protected UpdateResult doUpdate(String collectionName, Query query, UpdateDefini
return execute(collectionName, collection -> {

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Calling update using query: %s and update: %s in collection: %s",
LOGGER.debug(String.format("Calling update using query: [%s] and update: [%s] in collection: [%s]",
serializeToJsonSafely(queryObj), serializeToJsonSafely(updateObj), collectionName));
}

@@ -1816,7 +1845,7 @@ protected <T> DeleteResult doRemove(String collectionName, Query query, @Nullabl
Document removeQuery = queryObject;

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Remove using query: %s in collection: %s.", serializeToJsonSafely(removeQuery),
LOGGER.debug(String.format("Remove using query: [%s] in collection: [%s].", serializeToJsonSafely(removeQuery),
collectionName));
}

@@ -2162,7 +2191,7 @@ protected <O> AggregationResults<O> doAggregate(Aggregation aggregation, String
Document command = aggregationUtil.createCommand(collectionName, aggregation, context);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Executing aggregation: %s", serializeToJsonSafely(command)));
LOGGER.debug(String.format("Executing aggregation: [%s]", serializeToJsonSafely(command)));
}

Document commandResult = executeCommand(command);
@@ -2174,7 +2203,7 @@ protected <O> AggregationResults<O> doAggregate(Aggregation aggregation, String

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(
String.format("Executing aggregation: %s in collection %s", serializeToJsonSafely(pipeline), collectionName));
String.format("Executing aggregation: [%s] in collection [%s]", serializeToJsonSafely(pipeline), collectionName));
}

return execute(collectionName, collection -> {
@@ -2244,7 +2273,7 @@ protected <O> Stream<O> aggregateStream(Aggregation aggregation, String collecti

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(
String.format("Streaming aggregation: %s in collection %s", serializeToJsonSafely(pipeline), collectionName));
String.format("Streaming aggregation: [%s] in collection [%s]", serializeToJsonSafely(pipeline), collectionName));
}

ReadDocumentCallback<O> readCallback = new ReadDocumentCallback<>(mongoConverter, outputType, collectionName);
@@ -2436,8 +2465,8 @@ protected MongoCollection<Document> doCreateCollection(String collectionName,

// TODO: Emit a collection created event
if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("Created collection [%s]",
coll.getNamespace() != null ? coll.getNamespace().getCollectionName() : collectionName));
LOGGER.debug(String.format("Created collection [%s] with options [%s]",
coll.getNamespace() != null ? coll.getNamespace().getCollectionName() : collectionName, collectionOptions));
}
return coll;
});
@@ -2533,8 +2562,9 @@ protected <T> T doFindOne(String collectionName, CollectionPreparer<MongoCollect
Document mappedQuery = queryContext.getMappedQuery(entity);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("findOne using query: %s fields: %s for class: %s in collection: %s",
serializeToJsonSafely(query), mappedFields, entityClass, collectionName));
Document sort = getMappedSortObject(query, entityClass);
LOGGER.debug(String.format("findOne using query: [%s] fields: [%s] sort: [%s] for class: [%s] in collection: [%s]",
serializeToJsonSafely(query), mappedFields, sort, entityClass, collectionName));
}

return executeFindOneInternal(new FindOneCallback(collectionPreparer, mappedQuery, mappedFields, preparer),
@@ -2590,7 +2620,7 @@ protected <S, T> List<T> doFind(String collectionName,
Document mappedSort = getMappedSortObject(query, entityClass);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("find using query: %s fields: %s sort: %s for class: %s in collection: %s",
LOGGER.debug(String.format("find using query: [%s] fields: [%s] sort: [%s] for class: [%s] in collection: [%s]",
serializeToJsonSafely(mappedQuery), mappedFields, serializeToJsonSafely(mappedSort), entityClass,
collectionName));
}
@@ -2617,7 +2647,7 @@ <S, T> List<T> doFind(CollectionPreparer<MongoCollection<Document>> collectionPr
Document mappedSort = getMappedSortObject(query, sourceClass);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("find using query: %s fields: %s sort: %s for class: %s in collection: %s",
LOGGER.debug(String.format("find using query: [%s] fields: [%s] sort: [%s] for class: [%s] in collection: [%s]",
serializeToJsonSafely(mappedQuery), mappedFields, serializeToJsonSafely(mappedSort), sourceClass,
collectionName));
}
@@ -2700,7 +2730,7 @@ protected <T> T doFindAndRemove(CollectionPreparer collectionPreparer, String co
Document fields, Document sort, @Nullable Collation collation, Class<T> entityClass) {

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("findAndRemove using query: %s fields: %s sort: %s for class: %s in collection: %s",
LOGGER.debug(String.format("findAndRemove using query: [%s] fields: [%s] sort: [%s] for class: [%s] in collection: [%s]",
serializeToJsonSafely(query), fields, serializeToJsonSafely(sort), entityClass, collectionName));
}

@@ -2731,7 +2761,7 @@ protected <T> T doFindAndModify(CollectionPreparer collectionPreparer, String co

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"findAndModify using query: %s fields: %s sort: %s for class: %s and update: %s in collection: %s",
"findAndModify using query: [%s] fields: [%s] sort: [%s] for class: [%s] and update: [%s] in collection: [%s]",
serializeToJsonSafely(mappedQuery), fields, serializeToJsonSafely(sort), entityClass,
serializeToJsonSafely(mappedUpdate),
collectionName));
@@ -2808,8 +2838,8 @@ private <T> T doFindAndReplace(CollectionPreparer collectionPreparer, String col
if (LOGGER.isDebugEnabled()) {
LOGGER
.debug(String.format(
"findAndReplace using query: %s fields: %s sort: %s for class: %s and replacement: %s "
+ "in collection: %s",
"findAndReplace using query: [%s] fields: [%s] sort: [%s] for class: [%s] and replacement: [%s] "
+ "in collection: [%s]",
serializeToJsonSafely(mappedQuery), serializeToJsonSafely(mappedFields),
serializeToJsonSafely(mappedSort), entityType, serializeToJsonSafely(replacement), collectionName));
}
@@ -2830,7 +2860,7 @@ private <S> UpdateResult doReplace(ReplaceOptions options, Class<S> entityType,
it.upsert(options.isUpsert());
}));
if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format("replace one using query: %s for class: %s in collection: %s",
LOGGER.debug(String.format("replace one using query: [%s] for class: [%s] in collection: [%s]",
serializeToJsonSafely(updateContext.getMappedQuery(persistentEntity)), entityType, collectionName));
}

@@ -3039,6 +3069,12 @@ public Document doInCollection(MongoCollection<Document> collection) throws Mong
iterable = iterable.projection(fields.get());
}

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] query [%s], fields [%s]", getClass().getSimpleName(), serializeToJsonSafely(query), fields.map(
SerializationUtils::serializeToJsonSafely).orElse("")));
}

return iterable.first();
}
}
@@ -3080,6 +3116,12 @@ public FindIterable<Document> doInCollection(MongoCollection<Document> collectio
if (collation != null) {
findIterable = findIterable.collation(collation);
}

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] query [%s], collation [%s]", getClass().getSimpleName(), serializeToJsonSafely(query), serializeToJsonSafely(collation)));
}

return findIterable;
}
}
@@ -3107,9 +3149,15 @@ private class ExistsCallback implements CollectionCallback<Boolean> {

@Override
public Boolean doInCollection(MongoCollection<Document> collection) throws MongoException, DataAccessException {

return doCount(collectionPreparer, collection.getNamespace().getCollectionName(), mappedQuery,
boolean positiveCount = doCount(collectionPreparer, collection.getNamespace().getCollectionName(), mappedQuery,
new CountOptions().limit(1).collation(collation)) > 0;

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] query [%s], collation [%s]", getClass().getSimpleName(), serializeToJsonSafely(mappedQuery), serializeToJsonSafely(collation)));
}

return positiveCount;
}
}

@@ -3143,7 +3191,14 @@ public Document doInCollection(MongoCollection<Document> collection) throws Mong
FindOneAndDeleteOptions opts = new FindOneAndDeleteOptions().sort(sort).projection(fields);
collation.map(Collation::toMongoCollation).ifPresent(opts::collation);

return collectionPreparer.prepare(collection).findOneAndDelete(query, opts);
Document oneAndDelete = collectionPreparer.prepare(collection).findOneAndDelete(query, opts);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] query [%s], fields [%s], sort [%s], collation [%s]", getClass().getSimpleName(), serializeToJsonSafely(query), serializeToJsonSafely(fields), serializeToJsonSafely(sort), serializeToJsonSafely(collation)));
}

return oneAndDelete;
}
}

@@ -3188,13 +3243,21 @@ public Document doInCollection(MongoCollection<Document> collection) throws Mong
opts.arrayFilters(arrayFilters);
}

Document result;
if (update instanceof Document document) {
return collectionPreparer.prepare(collection).findOneAndUpdate(query, document, opts);
result = collectionPreparer.prepare(collection).findOneAndUpdate(query, document, opts);
} else if (update instanceof List) {
return collectionPreparer.prepare(collection).findOneAndUpdate(query, (List<Document>) update, opts);
result = collectionPreparer.prepare(collection).findOneAndUpdate(query, (List<Document>) update, opts);
} else {
throw new IllegalArgumentException(String.format("Using %s is not supported in findOneAndUpdate", update));
}

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] query [%s], fields [%s], sort [%s], update [%s], arrayFilters [%s], options [%s]", getClass().getSimpleName(), serializeToJsonSafely(query), serializeToJsonSafely(fields), serializeToJsonSafely(sort), serializeToJsonSafely(update), serializeToJsonSafely(arrayFilters), serializeToJsonSafely(options)));
}

throw new IllegalArgumentException(String.format("Using %s is not supported in findOneAndUpdate", update));
return result;
}
}

@@ -3243,7 +3306,14 @@ public Document doInCollection(MongoCollection<Document> collection) throws Mong
opts.returnDocument(ReturnDocument.AFTER);
}

return collectionPreparer.prepare(collection).findOneAndReplace(query, update, opts);
Document document = collectionPreparer.prepare(collection).findOneAndReplace(query, update, opts);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] query [%s], fields [%s], sort [%s], update [%s], collation [%s], options [%s]", getClass().getSimpleName(), serializeToJsonSafely(query), serializeToJsonSafely(fields), serializeToJsonSafely(sort), serializeToJsonSafely(update), serializeToJsonSafely(collation), serializeToJsonSafely(options)));
}

return document;
}
}

@@ -3293,6 +3363,11 @@ public T doWith(Document document) {
maybeEmitEvent(new AfterConvertEvent<>(document, entity, collectionName));
entity = maybeCallAfterConvert(entity, document, collectionName);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] reader [%s], type [%s], collectionName [%s]", getClass().getSimpleName(), serializeToJsonSafely(reader), serializeToJsonSafely(type), serializeToJsonSafely(collectionName)));
}

return entity;
}
}
@@ -3335,7 +3410,14 @@ public T doWith(Document document) {
}

maybeEmitEvent(new AfterConvertEvent<>(document, entity, collectionName));
return (T) maybeCallAfterConvert(entity, document, collectionName);
T maybeConverted = (T) maybeCallAfterConvert(entity, document, collectionName);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] converter [%s], projection [%s], collectionName [%s]", getClass().getSimpleName(), serializeToJsonSafely(mongoConverter), serializeToJsonSafely(projection), serializeToJsonSafely(collectionName)));
}

return maybeConverted;
}
}

@@ -3434,6 +3516,11 @@ public FindIterable<Document> prepare(FindIterable<Document> iterable) {
throw potentiallyConvertRuntimeException(e, exceptionTranslator);
}

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Prepared cursor with [%s] query [%s], sortObject [%s], limit [%s], skip [%s], type [%s]", getClass().getSimpleName(), serializeToJsonSafely(query), serializeToJsonSafely(sortObject), serializeToJsonSafely(limit), serializeToJsonSafely(skip), serializeToJsonSafely(type)));
}

return cursorToUse;
}

@@ -3479,7 +3566,14 @@ public GeoResult<T> doWith(Document object) {

T doWith = delegate.doWith(object);

return new GeoResult<>(doWith, new Distance(distance, metric));
GeoResult<T> tGeoResult = new GeoResult<>(doWith, new Distance(distance, metric));

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] distanceField [%s], delegate [%s], metric [%s]", getClass().getSimpleName(), serializeToJsonSafely(distanceField), serializeToJsonSafely(delegate), serializeToJsonSafely(metric)));
}

return tGeoResult;
}
}

@@ -3644,7 +3738,14 @@ private static class ReplaceCallback implements CollectionCallback<UpdateResult>
@Override
public UpdateResult doInCollection(MongoCollection<Document> collection)
throws MongoException, DataAccessException {
return collectionPreparer.prepare(collection).replaceOne(query, update, options);
UpdateResult updateResult = collectionPreparer.prepare(collection).replaceOne(query, update, options);

if (LOGGER.isDebugEnabled()) {
LOGGER.debug(String.format(
"Applied callback [%s] collectionPreparer [%s], query [%s], update [%s], options [%s]", getClass().getSimpleName(), collectionPreparer.getClass().getSimpleName(), serializeToJsonSafely(query), serializeToJsonSafely(update), serializeToJsonSafely(options)));
}

return updateResult;
}
}
}