Re: Question regarding JSON Template timestamp rendering

"Andrew Harris (andharr2)" <[email protected]>
Newsgroups gmane.comp.jakarta.log4j.user
Message-ID <BYAPR11MB363703CEDF2BDAFDF444D8ECE4869@BYAPR11MB3637.namprd11.prod.outlook.com>
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
lmpx.com only provides a reader for public news (NNTP) servers. It is not affiliated with the servers or forums shown here and is not responsible for the content of articles, which is written by their respective authors.