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
