Volkan,

I must be making a mistake somewhere. As a check on basic assumptions, I sought 
to craft a simple Java application that emits logs via a Logger, using a 
logging configuration like in my first message. I found that the 
pattern-formatted timestamp resolver operates as expected, whereas the epoch 
resolver gets "stuck" after the first emitted timestamp.

This test application is running outside of Docker. My machine is running MacOS 
11.6, and the test application is configured to use Azul JDK 11.0.12.

Log lines appear like:
```
{"timestamp.epoch":1635297200141169000,"timestamp.iso8601":"2021-10-27T01:13:20.141Z","severityText":"INFO","body":"Starting
 count"}
{"timestamp.epoch":1635297200141169000,"timestamp.iso8601":"2021-10-27T01:13:20.148Z","severityText":"INFO","body":"Event
 0"}
{"timestamp.epoch":1635297200141169000,"timestamp.iso8601":"2021-10-27T01:13:21.151Z","severityText":"INFO","body":"Event
 1"}
...
```
Notice that the epoch and ISO timestamp align correctly in the first log line 
and diverge thereafter. The epoch timestamp never advances, in several rounds 
of tests and after toggling from epoch nanos to rounded epoch seconds in the 
template.

The test application:
```
public class Log4jApp {
    public static final Logger LOGGER = LogManager.getLogger(Log4jApp.class);

    public static void main(String[] args) {
        LOGGER.info("Starting count");
        IntStream.range(0, 100).forEach(i -> {
            LOGGER.info("Event {}", i);
            try { Thread.sleep(1000); } catch (InterruptedException e) {};
        });
        LOGGER.info("End count");
    }
}
```
I found also that a test application written using SLF4J's logger exhibits the 
same behavior. The SLF4J implementation I tested swaps the LOGGER construction 
for SLF4J objects and is otherwise equivalent.

The logging configuration:
```
?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
    <Appenders>
        <Console name="LogToConsole" target="SYSTEM_OUT">
            <JsonTemplateLayout eventTemplateUri="classpath:Log4jLayout.json"/>
        </Console>
    </Appenders>
    <Loggers>
        <Root level="debug">
            <AppenderRef ref="LogToConsole"/>
        </Root>
    </Loggers>
</Configuration>
```

The template:
```
{
  "timestamp.epoch": {
    "$resolver": "timestamp",
    "epoch": {
      "unit": "nanos"
    }
  },
  "timestamp.iso8601": {
    "$resolver": "timestamp",
    "pattern": {
      "format": "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'",
      "timeZone": "UTC",
      "locale": "en_US"
    }
  },
  "severityText": {
    "$resolver": "level",
    "field": "name"
  },
  "body": {
    "$resolver": "message",
    "stringified": true
  }
}
```

The Gradle dependencies driving the app:
```
dependencies {
    annotationProcessor platform('org.apache.logging.log4j:log4j-bom:2.14.1')
    annotationProcessor 'org.apache.logging.log4j:log4j-core'

    implementation 'org.slf4j:slf4j-api:1.7.32'
    implementation platform('org.apache.logging.log4j:log4j-bom:2.14.1')
    implementation 'org.apache.logging.log4j:log4j-api'
    implementation 'org.apache.logging.log4j:log4j-core'
    runtimeOnly 'org.apache.logging.log4j:log4j-slf4j-impl'
    runtimeOnly 'org.apache.logging.log4j:log4j-layout-template-json'

    testImplementation 'org.junit.jupiter:junit-jupiter:5.7.2'
}
```
No web frameworks, no concurrency extensions. Just logging.

I'll seek to create a repeatable test case tomorrow for this behavior. Happy to 
package this work if you'd like to run it on your end.

Thoughts here? Thank you again, and hope you've recovered.

Andrew

Reply via email to