Andrew, I have pushed a fix to the `release-2.x` branch with commit `2dd7063fb6c6fe73070aded6607a2e2d53613b46`. Mind giving it a try, please?
For the records, created LOG4J2-3183 <https://issues.apache.org/jira/browse/LOG4J2-3183>. On Thu, Oct 28, 2021 at 11:02 AM Volkan Yazıcı <vol...@yazi.ci> wrote: > 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 >> >
