I am trying to change the way results from DataObjectQueries are logged. We have a few queries that return large result sets (250k - 350k DataObjects). Currently the resulting logs look like this:
{
"timeMillis": 1692287794885,
"thread": "qtp680971479-558",
"level": "INFO",
"loggerName": "com.leidos.aspr.personnel.PersonnelDataServiceDirector",
"message": "LEAF traceId=REDACTED, OpenTracing traceId=REDACTED, OpenTracing spanId=REDACTED, username=REDACTED called IDataObjectService.loadByQuery with arguments (dataObjectQuery = DataObjectQuery [name=RecentlyUpdatedRespondersWidget: load personnel, id=null]) which returned [ExtendedPersonnelAssignment (PersonnelAssignment-367820) { }, ...REDACTED... , ExtendedPersonnelAssignment (PersonnelAssignment-367728) { }]",
"endOfBatch": false,
"loggerFqcn": "org.apache.logging.log4j.spi.AbstractLogger",
"contextMap":
{},
"threadId": 558,
"threadPriority": 5
}
We really have no need to display all those results, since they junk up the logs and tie up memory unnecessarily. Ideally, we could just calculate some basic statistics for the return part of the log statement, something like
"... which returned 123 DataObjects: 3 Roster, 120 ExtendedPersonnelAssignment"
Our log hooks are pretty basic and are set up as follows:
LogHook logHook =
LogHook.newBuilder()
.withLogConsumer(LOGGER::info)
.withMetadataService(dataService.getMetadataService())
.build();
I this something I have control over?
Two main options here:
- I think this is worthy of a feature request to LEAF. For collection-like args or results, it would be ideal if LEAF had an option to log a count instead of values.
- You could disable LEAF’s LogHook for specific methods, and then write your own custom LogHook for the problematic methods. Going to focus on that for the rest of my answer so you have a quicker solution.
When making a custom LogHook, you can extend LEAF’s and override the serializeValue function. My example below shows how to apply LogHook to all methods but DataObjectService’s load by query, and then applies a custom extension of LogHook to load by query.
Setting up hooks and testing
// Example for slf4j, but change to LogManager if using log4j2.
private static final Logger LOGGER = LoggerFactory.getLogger(LogHook.class);
public static void main(String[] args) {
// LogHook that will be applied so all services' methods except DataObjectService.load(query, ctx).
LogHook logHook = LogHook.newBuilder()
.withLogConsumer(LOGGER::info)
.withShouldHook(method -> !(IDataObjectService.class.isAssignableFrom(method.getServiceClass())
&& DataObjectServiceExtensible.LOAD_BY_QUERY.equals(method.getIdentifier())))
.build();
// LogHook that will be applied only to DataObjectService.load(query, ctx).
QueryLogHook queryLogHook = new QueryLogHook();
// Quick test to see log.
IEventService eventService = EventServiceLocal.newBuilder()
.build();
eventService.start();
IDataService dataService = DataServiceTransient.newBuilder(eventService)
.build();
dataService.addHooks(IDataService.SERVICE_PRED, List.of(logHook, queryLogHook));
// Uses normal LogHook
dataService.getDataObjectService()
.loadCount(DataObjectQueries.dataObjectQuery(), Context.makeSystemContext());
// Uses custom QueryLogHook
dataService.getDataObjectService()
.load(DataObjectQueries.dataObjectQuery(), Context.makeSystemContext());
}
Custom Hook
public class QueryLogHook extends LogHook {
// Example for slf4j, but change to LogManager if using log4j2.
private static final Logger LOGGER = LoggerFactory.getLogger(QueryLogHook.class);
public QueryLogHook() {
super(LOGGER::info, LOGGER::error, Map.of()); // Change levels to whatever you want for non-error and error logs.
}
@Override
public boolean shouldHook(IMethod<?> method) {
return IDataObjectService.class.isAssignableFrom(method.getServiceClass())
&& DataObjectServiceExtensible.LOAD_BY_QUERY.equals(method.getIdentifier());
}
@Override
protected <T> String serializeValue(T value, IContext context) {
// For the return result, which is a collection of DataObjects.
if (value instanceof Collection<?> c) {
// You can change this to log the types in the collection with counts for each type if useful. Or make this whatever you want.
return "a collection of DataObjects with " + c.size() + " objects,";
}
// For the passed-in query arg, use normal serialization.
return super.serializeValue(value, context);
}
}
Which outputs these logs:
09:38:14.978 [main] INFO [] c.l.l.h.d.h.LogHook - LEAF traceId=80bd1c16d0b54d6788e97aca2e3b0deb, username=AnonymousSystemUser called IDataObjectService.loadCount with arguments (dataObjectQuery = DataObjectQuery [name=<Unnamed Query>, id=null]) which returned 0 which took 16 milliseconds
09:38:14.981 [main] INFO [] c.l.QueryLogHook - LEAF traceId=d6f435a557d44644a3acadde30c2f32b, username=AnonymousSystemUser called IDataObjectService.loadByQuery with arguments (dataObjectQuery = DataObjectQuery [name=<Unnamed Query>, id=null]) which returned a collection of DataObjects with 0 objects, which took 3 milliseconds
Also just a heads up, since it looks like you’re using structured logs, in LEAF 3.6, we added StructuredLogHook. I don’t think it lets you customize how things are serialized the same way I showed above, but might be a better option for other logging.
I linked to the 3.11 page which uses slf4j and logback above. When we first added it, we were still using log4j2. So here’s a link to the 3.6 page.
Ok, so this ended up working great for logging results of queries. Is there any way to inject a log statement after receiving the results from the database query but before any in-memory filtering has been done by LEAF?
I think in general the answer here is no as the DAO load method is probably the lowest hookable method as far as reads are concerned, and the DAO performs in-memory filtering if the DAO knows it can’t handle some filters at the db-level.
It’s tricky to allow hooks to intercept internal private methods, so I’m not optimistic we could even add this feature. We could probably add logging directly to the DAOs specifically (most likely at debug or trace, but you could customize your logger to include them).
I think there is a calculation service method the DAO calls before filtering is performed, but it’s invoked once per object.
That makes sense. Thanks for the quick reply