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
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
