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