[LOG4J2-3183] JsonTemplateLayout epoch resolver renders incorrect values

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.14.0, 2.14.1
• Fix Version/s: 2.15.0
• Component/s: JsonTemplateLayout
• Assignee: Volkan Yazici
• Reporter: Volkan Yazici
• Created: 28/Oct/21 09:08
• Updated: 01/Nov/21 20:46
• Resolved: 28/Oct/21 13:16

Description

JTL epoch resolver renders the same timestamp repeatedly. See the following application using log4j-layout-template-json 2.14.1:

public static void main(String[] args) throws InterruptedException {
    initLog4j();
    Logger logger = LogManager.getLogger();
    for (int i = 0; i < 5; i++) {
        logger.info("{}", i);
        Thread.sleep(100);
    }
}

private static LoggerContext initLog4j() {

    // Create the configuration builder.
    ConfigurationBuilder<BuiltConfiguration> configBuilder = ConfigurationBuilderFactory
            .newConfigurationBuilder()
            .setStatusLevel(Level.ERROR)
            .setConfigurationName(TimeDriftDemo.class.getSimpleName());

    // Create the configuration.
    String appenderName = "Console";
    String eventTemplate = "" +
            "[{\"$resolver\":\"timestamp\",\"epoch\":{\"unit\":\"nanos\"}}" +
            ",{\"$resolver\":\"timestamp\",\"pattern\":{\"format\":\"ss.SSS'Z'\",\"timeZone\":\"UTC\",\"locale\":\"en_US\"}}" +
            "]";
    Configuration config = configBuilder
            .add(configBuilder
                    .newAppender(appenderName, "Console")
                    .add(configBuilder
                            .newLayout("JsonTemplateLayout")
                            .addAttribute(
                                    "eventTemplate",
                                    eventTemplate)))
            .add(configBuilder.newLogger("com.vlkan", Level.TRACE))
            .add(configBuilder
                    .newRootLogger(Level.ERROR)
                    .add(configBuilder.newAppenderRef(appenderName)))
            .build(false);

    // Initialize the configuration.
    return Configurator.initialize(config);

}

Note the identical epochs in the output:

[1635411617932465000,"17.932Z"]
[1635411617932465000,"18.034Z"]
[1635411617932465000,"18.134Z"]
[1635411617932465000,"18.234Z"]
[1635411617932465000,"18.335Z"]

The issue was originally reported by Andrew Harris in a log4j-user post.