4

The encoder pattern in logback.xml like

<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

allows to enhance logging messages with context information like the current thread and the class name. Is there a possibility to display the identity hash code (returned by System.identityHashcode(Object)) in the messages? I wouldn't mind a custom extension in form of a subclass, even though a configuration per class or package would be nice. I just have no idea where to start.

I'm aware that I can work around the problem by adding System.identityHashcode to each log message. The idea for this question is to provide a configurable approach.

I'm accessing logback-classic 1.2.3 through SLF4J API 1.7.25, but wouldn't mind to upgrade to a 1.8.x snapshot.

Kalle Richter
  • 8,008
  • 26
  • 77
  • 177

1 Answers1

2

Logback's PatternLayout contains defaultConverterMap which maps conversion words (%n, %msg, %d etc) to implementations of ch.qos.logback.core.pattern.Converter. This is what you referred to as:

enhance logging messages with context information like the current thread and the class name

To include a hashCode in the log output you could provide your own implementation of ch.qos.logback.core.pattern.Converter and associate it with a custom conversion word as follows ...

  1. Add this to logback.xml

    <conversionRule conversionWord="hc" converterClass="some.package.HashCodeConverter" />
    
  2. Implement some.package.HashCodeConverter as follows:

    import ch.qos.logback.classic.pattern.ClassicConverter;
    import ch.qos.logback.classic.spi.ILoggingEvent;
    import ch.qos.logback.classic.spi.CallerData;
    
    public class HashCodeConverter extends ClassicConverter {
        @Override
        public String convert(ILoggingEvent le) {
            StackTraceElement[] cda = le.getCallerData();
            if (cda != null && cda.length > 0) {
                return Integer.toString(System.identityHashCode(cda[0]));
            } else {
                return CallerData.NA;
            }
        }
    }
    
  3. Update your encoder pattern to use the conversion word hc:

    <encoder>
        <pattern>%d{yyyy-MM-dd HH:mm:ss}|[%thread]|%-5level|%logger{36}|%hc|%msg %n</pattern>
    </encoder>
    

With these changes in place your custom converter will be engaged and the output will look like this ...

2018-05-29 09:30:09|[main]|INFO |o.g.sandbox.logback.LogbackTest|1847637306|hello! 

Where 1847637306 is the hashCode for the class which emitted the log event.

Notes:

  • In the above implementation I am assuming that the hashCode you are interested in is the hashCode of the class which emitted the log event. If that is not what you are interested in then you would change the implementation of HashCodeConverter
  • Although the above approach for getting the class which emitted the logging event is standard practice within Logback, it does require the generation of a stacktrace and doing this for every log event could be prohibitively expensive in a high volume logging environment. If so, then including the hashCode in each message might be your only option.
glytching
  • 44,936
  • 9
  • 114
  • 120
  • There seems to be an issue with the uniqueness of the identity hash code appearing in the messages. Identity hash code is not guaranteed to be different, e.g. after gc, but here it's different for every log message which can't be right. I provide you working unit and failing integration tests for the implementation at https://github.com/glytching/sandbox/pull/1 for you to investigate. I have no idea why the implementation doesn't work in the integration test environment. – Kalle Richter May 29 '18 at 19:03
  • The current implementation is returning the hashCode for the first element in a stacktrace which Logback creates in order to identify the invoking class. Each logger call (and hence each pass through the converter) causes a new stacktrace to be generated hence you get a different hashCode each time. I have changed this behaviour now but I'm not sure if the new impl meets you needs, see the [comment here](https://github.com/glytching/sandbox/blob/033b31d8b3a5f847c418eabfb68fdf5e839a8c31/src/main/java/org/glytching/sandbox/logging/HashCodeConverter.java#L14). – glytching May 30 '18 at 07:32