[slf4j-user] When more parameters than placeholders, extra parameters are not logged

[jo at durchholz.org]

On 25.01.25 02:38, Russ Block via slf4j-user wrote:
> With this method or any similar method,
>      public void info(String format, Object... arguments) {
>          if (isInfoEnabled()) {
>              handleArgArrayCall(Level.INFO, null, format, arguments);
>          }
>      }
> If the number of objects in 'arguments' is more than the number of 
> placeholders, {}, the extra argument objects are not logged.  Is there a 
> reason for that?

I can't answer authoritatively, but I guess it is outside the scope of 
the specification as-is.

For people using IntelliJ it is not a problem as it knows about SLF4J 
and flags log lines with extra or missing arguments.
Even better, IntelliJ will give you a refactoring option to replace
   logger.log("foo is: " + foo)
with
   logger.log("foo is: {}", foo)
It also correctly handles the case with multiple parameters, and there's 
even a hotkey for making it happen that my brain does not remember 
anymore but my fingers do.

I hope other IDEs have started offering similar functionality, but I 
don't know specifics.
IntelliJ does have some deficits, in particular its cache management if 
pretty flaky compared to Eclipse's, but I found IntelliJ's refactoring 
support such a time-save that I embraced it and never looked back, 
though other IDEs might (should, actually!) have caught up since.

> If I get into a situation where I have sent more argument objects than 
> placeholders that it should append those un-placed arguments to the end 
> of the logged string.  The intent of the developer is to have the 
> parameter logged.  Finding this out from production is not good.  What 
> is sent to be logged is important information, depending on the log level.

The knee-jerk answer to that would be "you have a bug in your code, just 
fix it".
(I believe that you want something sensible but your arguments are not 
strong enough. I.e. I'm going to strike down the arguments and 
suggesting a solution, so don't get disappointed before the end.)

> My use case is that I want to push some legacy code to start looking 
> like SLF4J so we can migrate away from the older pattern filled with 
> isLogTraceEnabled calls.

I'd assume that you had extra parameters in the legacy code as well, so 
your situation did not get worse, did it?

 > I learned of the above when I was writing > JUnit tests to see all 
the things the code would do and not do.
 >
> I feel that https://www.slf4j.org/faq.html#logging_performance is 
> telling me that, in some way, the placeholder string substitution is 
> faster than appending multiple strings together.  I understood the main 
> point of the argument as converting items to string before I needed them 
> was where the overhead was.  Keeping them as type Object reduces that 
> overhead.

Actually, while the placeholder substitution _is_ faster than a string 
append, the real advantage is this:
With logger.debug("foo is: " + foo), the + operator will be called 
before logger.debug starts, and foo.toString() and string concatenation 
happen whether logger.debug does anything with it or not.
With logger.debug("foo is: {}", foo), logger.debug will FIRST check if 
it needs to do anything, and ONLY THEN will it do string substitution.

The string substitution can actually be slightly slower than the 
concatenation, because there's the extra step of extracting the 
substitution markers and copying the text to the left and right of them. 
However, the substitution code is heavily optimized and should still be 
faster anyway in the vast majority of the cases.
This is, however, just for the do-log case. The main speedup comes from 
the no-log case doing less work.


> I understand there are Sonarqube rules and PMD to prevent me from not 
> having the correct number of argument objects.  This would help, but I 
> feel like there are still going to be misses.  Since my code is custom, 
> Sonarqube and PMD do not feel like options.
You can configure these things to report only those bugs that you are 
interested in.
The main deterrent is that the setup takes time.

Now to the promised solution, should you still need it:

You can do your own Formatter that appends any the extraneous parameters.

Caveat: Formatters do not live in SLF4J, they live in the logging 
backend - typically Logback. (SLF4J has a different and somewhat 
confusing terminology for "backend" that I don't remember.) SLF4J merely 
manages all the information needed to decide whether a log message 
should actually be output, and leaves the actual outputting to the backend.

Anyway, you'll have to dive into the code of the existing standard 
formatter, find out how it's working and how to make it append the extra 
parameters.
For Logback, you do not have to write your own backend, you can 
configure your Formatter, and even inherit from Logback's standard 
Formatter so you do not have to do a lot; however, you'll want to make 
150% sure that you do not introduce any bugs, so plan a lot of review 
(if possible) and testing. Fortunately it is more time reading docs and 
code than actual coding, so the extra effort for quality control will 
not be very noticeable.

Still, I believe the refactoring support of an IDE, if possible, will be 
easier :-)

HTH!
Jo