Cannot change log message via logging filter

[manofthepeace]

Describe the bug

Apologies if this is not a quarkus issue. Sometimes it is hard to distinguish. I am trying to change an internal quarkus' log message via a logging filter. I can change the Log level no problem (oddly JUL uses WARNING and quarkus uses WARN not sure if it's normal), but the changing the message, breaks the formatting.

The JUL LogRecord::setMessage api states; Set the "raw" log message, before localization or formatting. However when I try to update the raw message, formatting does not happen.

Expected behavior

Just doing the following in the logging filter breaks the message; record.setMessage(record.getMessage());

The reproducer just goes through the logging filter for the error log level, here's the output;

2022-09-09 13:24:52,934 INFO  [org.acm.GreetingResource] (Quarkus Main Thread) This is a message with variable: test
2022-09-09 13:24:52,936 ERROR [org.acm.GreetingResource] (Quarkus Main Thread) This is a message with variable: %s

Actual behavior

Both messages should be the same

How to Reproduce?

Reproducer: https://github.com/manofthepeace/quarkus-loggingfilter-issue

Steps to reproduce;
1- mvn quarkus:dev
2-both logs will be printed at startup

Output of uname -a or ver

Darwin Kernel Version 21.6.0

Output of java -version

OpenJDK 64-Bit Server VM Temurin-17.0.4.1+1

GraalVM version (if different from Java)

n/a

Quarkus version or git rev

2.12

Build tool (ie. output of mvnw --version or gradlew --version)

maven 3.8.4

Additional information

Changing only the log parameters via LogRecord::setParameters does work as expected

[mkouba]

Hm, the GreetingResource injects and logs messages via org.jboss.logging.Logger but the filter is set using the java.util.logging.Logger. I don't think that this is something that is supported because internally quarkus jboss-logmanager-embedded to write the log messages.

[manofthepeace]

Yes, it does seem like a odd configuration, but the only one that seem to work, before #27864 gets merged.

I am using the above to change some logs level, and also some log parameters, for instance, in the code in the reproducer, I could replace the "test" string parameter with "test2" within the filter, and the log would print test2 fine. Looks like only the setMessage does not work properly.

[geoand]

java.util.logging.Filter is meant to decide whether a handler should log a message or not, it's not really meant to change the LogRecord, so I would say that what you are doing is probably unspecified.

[manofthepeace]

@geoand To be honest I did expect that outcome as I know I am abusing the filter at the moment. But I would still think it would be nice to have a way to change internal log messages I will explain my 2 use case, maybe it could be raised as an enhancement, without using filter, or maybe there's a way I just do now know, or maybe my case is just unrealistic and just wrong :) .

1- smallrye/smallrye-fault-tolerance#641
In that fault tolerance case, for debugging purpose, we want to know when retry actually happens. This is logged as debug. Everything below info, in our setup, does not reach elasticsearch. Hence why I had to change it to WARN so we can, if needed troubleshoot it.

2-Using the rest-client reactive, it's a bit hard to log well the headers/body for request and response manualy. The simpler is to use quarkus.log.category."org.jboss.resteasy.reactive.client.logging".level=DEBUG problem is that can contain sensitive informations such as huge auth token (which clogs the logs) and login credentials. I use the filter to remove some parameters or change some via regex to <REDACTED> so there is no sensitive information leaked to the logs.

I am really glad this works, maybe until it breaks though, but thats why I think changing the message, could be useful in some case.

Thank you.

[geoand]

Thanks for explaining the use case. I agree that it does seem useful at times, unfortunately java.util.logging does not seem to have a mechanism for updating the record.

[manofthepeace]

Hi guys, I really don't want to eat up your time on this. I just want to give a bit more info in case anywone stumbles on the issue.

I did look into jboss loggmanager sources, and it looks like modifying the logrecord, within the filter is actually supported, and the logmanager uses it itself in it's own provided JUL Filter like shown here
https://github.com/jboss-logging/jboss-logmanager/blob/1de3c91785a54f0a9431e452a12fc39a02387e25/src/main/java/org/jboss/logmanager/filters/SubstituteFilter.java#L78

so basically the only thing needed is to manually format the message then use setMessage and it all works. So I think the behaviour is not unspecified but actually somewhat ok.

Thanks.