Question regarding JSON Template timestamp rendering

"Andrew Harris (andharr2)" <[email protected]>
Newsgroups gmane.comp.jakarta.log4j.user
Message-ID <BYAPR11MB3637A93956B8BD175B340B1EE4839@BYAPR11MB3637.namprd11.prod.outlook.com>
Hi friends,

I have a JSON Template layout in a project I maintain, and I have noticed a behavior in how timestamps are rendered that I did not expect. I went through the JSON Template resolver source for a few minutes last week and did not find an explanation, nor did I find any open issues or related messages on this list. I would greatly appreciate your help!

I am using Log4J 2.14.1 in a Java 11 project, and the following log lines were generated via a Docker-based test environment. I have a JSON Template configuration like:

```
{
  "timestamp": {
    "$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"
    }
  },
  ...
}
```

My log4j2.xml is fairly unremarkable, I think, like:

```
<Configuration status="WARN" packages="path.to.an.unrelated.custom.lookup">
    <Appenders>
        <Console name="LogToConsole" target="SYSTEM_OUT">
            <JsonTemplateLayout eventTemplateUri="classpath:myJsonTemplateLayout.json"/>
        </Console>
    </Appenders>
    <Loggers>
        <Logger name="package.specific.logger" level="info" additivity="false">
            <AppenderRef ref="LogToConsole"/>
        </Logger>
        ...
        <Root level="debug">
            <AppenderRef ref="LogToConsole"/>
        </Root>
    </Loggers>
</Configuration>
```

Normally, the JSON template above produces log lines like:

```
{"timestamp.epoch":1634943559640000000,"timestamp.iso8601":"2021-10-22T22:59:19.640Z",...}
```

And as expected, the epoch timestamp matches the ISO timestamp shown.

Sometimes however, and frequently enough to prompt this message, I see the timestamps diverge by several milliseconds:

```
{"timestamp.epoch":1634943499616000000,"timestamp.iso8601":"2021-10-22T22:58:19.644Z",...}
```

The epoch shown here corresponds to 22:58:19.616, a drift of 28ms.

Additionally, I have seen that sometimes logs will share the same epoch timestamp, while their ISO timestamp increments:

```
{"timestamp.epoch":1634943424218000000,"timestamp.iso8601":"2021-10-22T22:57:04.533Z",...}
{"timestamp.epoch":1634943424218000000,"timestamp.iso8601":"2021-10-22T22:57:05.622Z",...}
```

The epoch shown here corresponds to 22:57:04.218, a drift of more than 300ms. In testing elsewhere, I also witnessed the same epoch timestamp used across logs up to 20 seconds apart.

Is this divergence and timestamp-repeating a known behavior? What might be occurring here?

Please let me know if I can provide more information to help clarify the situation, and thank you for any help on the matter.

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.