Re: Question regarding JSON Template timestamp rendering

I sadly am able to reproduce the issue Andrew:

public final class TimeDriftDemo {

    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);

    }

}

I will create a ticket and act on it.
Thanks so much for the report!


On Thu, Oct 28, 2021 at 3:19 AM Andrew Harris (andharr2) <
[email protected]> wrote:

> Volkan,
>
> I was able to get the test case you supplied running in
> JsonTemplateLayoutTest. I confirm that it passes on my system as well. In
> fact, all the tests in `log4j-layout-template-json` at `rel/2.14.1` pass
> (except JsonTemplateLayoutGcFreeTest, which I'm willing to believe is a
> quirk of that test vis-a-vis my setup). That tells me that log rendering in
> unit-test isolation operates as expected.
>
> I extended the test case to use SystemClock to generate two Instants with
> a short pause between generation, like:
> ```
>         final Clock systemClock = new SystemClock();
>         final MutableInstant instant3 = new MutableInstant();
>         instant3.initFrom(systemClock);
>         try { Thread.sleep(100); } catch (InterruptedException e) {};
>         final MutableInstant instant4 = new MutableInstant();
>         instant4.initFrom(systemClock);
>
>         final LogEvent logEvent3 =
> Log4jLogEvent.newBuilder().setInstant(instant3).build();
>         final LogEvent logEvent4 =
> Log4jLogEvent.newBuilder().setInstant(instant4).build();
>
>         usingSerializedLogEventAccessor(layout, logEvent3, accessor3 -> {
>             usingSerializedLogEventAccessor(layout, logEvent4, accessor4
> -> {
>                 Long epoch3 = accessor3.getObject("timestamp.epoch",
> Long.class);
>                 String iso3 = accessor3.getString("timestamp.iso8601");
>
>                 Long epoch4 = accessor4.getObject("timestamp.epoch",
> Long.class);
>                 String iso4 = accessor4.getString("timestamp.iso8601");
>
>                 assertThat(epoch4 - epoch3).isGreaterThanOrEqualTo(100L);
>                 assertThat(iso3).isNotEqualTo(iso4);
>             });
>         });
> ```
>
> This test portion also passed. This tells me that the act of deriving the
> time from a provided clock operates as expected.
>
> Back in my example application, I did some more experimentation and found
> the following:
>
> - Removing the timestamp pattern resolver from the JSON template does not
> change behavior. Epoch timestamps continue to be repeated.
> - Changing the timestamp epoch resolver to use millis or seconds does not
> change behavior. Epoch timestamps are correctly rounded and rendered, they
> just don't appear to advance.
>
> Seeking to rule out whether this was due to behavior in the logger, I
> switched to an async logger using Disruptor 3.4.4:
> - Passing
> '-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector'
> does not appear to change behavior.
> - Using an AsyncLogger does not appear to change behavior.
> - Changing `log4j2.clock` to use CachedClock (vs SystemClock) does not
> change behavior. Some precision in the nano timestamp is lost, as I believe
> is expected.
>
> I sought to rule out JDK differences, so I ran my bench application
> against Azul Zulu 8, 11, and 16, as well as AdoptOpenJDK 11 on J9. No
> change in behavior between these, the epoch was still repeated between runs.
>
> Using a PatternLayout allows both Unix epoch and pattern-derived
> timestamps to be rendered as expected:
> ```
> <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} - %logger{36} - %msg
> timestamp=%d{UNIX_MILLIS} %n"/>
> ```
>
> """
> 2021-10-27 18:07:28.111 - example.Log4jApp - Starting count
> timestamp=1635383248111
> 2021-10-27 18:07:28.118 - example.Log4jApp - Event 0
> timestamp=1635383248118
> 2021-10-27 18:07:29.123 - example.Log4jApp - Event 1
> timestamp=1635383249123
> """
>
> I confirmed the behavior of the PatternLayout with an AsyncLogger as well,
> and it too worked as expected.
>
> Please let me know what might be worth trying next here, and thank you for
> your ideas up to now. I'm quite confused at this point. :)
>
> Andrew
>