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) <
andrew.har...@appdynamics.com> 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
>
