Home > Enterprise >  Method resolution during logging: Why is ()->String.format(...) not recoginzed as Supplier<Str
Method resolution during logging: Why is ()->String.format(...) not recoginzed as Supplier<Str

Time:02-03

I have made a call to the log4j-v2-API like this:

Logger logger = LogManager.getLogger("MyLogger");

/**
 * syntactic sugar as part of a facade
 */
private void logAtLevel(String level, Supplier<String> messageSupplier, Throwable thrown){
      Level priority = Level.toLevel(level, Level.ALL);
      if (null == thrown) {
         logger.log(priority, messageSupplier);
      } else {
         logger.log(priority, messageSupplier, thrown);
      }

}

/**
 * method calling logger
 */
private void callLogging(Object value){
   logAtLevel("Debug", ()->String.format("something or other: %s", value), null);

}

My expectations would have been that the above call creates a log entry "something or other: <object.toString()>" however I got "lambda@1223454" instead.

This suggests to me that the method that was executed is log(level, object) rather than the expected log(level, supplier)

Why are the methods resolved the way they are and how can I prevent this (preferably without casting)?

CodePudding user response:

Your Supplier is not Log4j2's Supplier!

java.util.function.Supplier was introduced in Java 8. At around the same time (version 2.4, cf. LOG4J2-599) Log4j2 introduced org.apache.logging.log4j.util.Supplier so that the library can be used on Java 7.

That is why your code does not call log(Level, Supplier<?>, Throwable) but log(Level, Object, Throwable) and you end up with Supplier#toString() being logged instead of Supplier#get().

This is probably something that should change and I filed a wish list bug about it (cf. #1262).

Remark: Wrapping well established logging APIs like Log4j2 API and SLF4J into custom wrappers is not a good idea (cf. this question). While it is not rocket science to write a good wrapper, there are many details you should consider. For example your wrapper breaks location information.

CodePudding user response:

Doing a level lookup for every call, when your intent is to avoid every nanosecond for levels that don't matter, is probably something you need to reconsider.

At any rate, there is nothing immediately obvious about your snippet that would explain what you observe. Thus, let's get into debugging it, and likely causes.

  1. The code you are running isn't the code you wrote. For example, because you haven't (re)compiled.

  2. logger.log is overloaded, and older versions of slf4j exist that contain only the 'object' variant, which just calls toString(), which would lead to precisely the behaviour you are now witnessing.

You can do some debugging on both of these problems by applying the following trick:

  • Add System.out.println(TheClassThisCodeIsIn.class.getResource("TheClassThisCodeIsIn.class")); - this will tell you exactly where the class file is at.
  • Then use javap -v -c path/to/that/file.class and check the actual call to logger.log - is the 'signature' that it links to the Supplier variant or the Object variant?

The different effects and what it means:

  • The sysout call isn't showing up. Then you aren't running the code you are looking at, and you need to investigate your toolstack. How are you compiling it, because it's not working.
  • The javap output shows that the 'Object' variant is invoked. In which case the compilation step is using an old version of log4j2 in its classpath. It's not about the slf4j version that exists at runtime, it's what the compiler is using, as that determines which overload is chosen.
  • Everything looks fine and yet you are still seeing lambda@... - then I would start suspecting that this is the actual output of your lambda code somehow, or something really, really wonky is going on. The only things I can think of that get you here are ridiculously exotic, not worth mentioning.
  • Related