Hey Andrew,
Thanks so much for reaching out. I have tried to reproduce your issue via
unit tests, but had no luck so far:
@Test
void test_conflicting_timestamps() {
// Create the event template.
final String eventTemplate = writeJson(asMap(
"timestamp.epoch", asMap(
"$resolver", "timestamp",
"epoch", asMap("unit", "nanos")),
"timestamp.iso8601", asMap(
"$resolver", "timestamp",
"pattern", asMap(
"format", "yyyy-MM-dd'T'HH:mm:ss.SSS'Z'",
"timeZone", "UTC",
"locale", "en_US"))));
// Create the layout.
final JsonTemplateLayout layout = JsonTemplateLayout
.newBuilder()
.setConfiguration(CONFIGURATION)
.setEventTemplate(eventTemplate)
.build();
// Create the log event #1.
final MutableInstant instant1 = new MutableInstant();
instant1.initFromEpochSecond(1_634_943_424L, 218_000_000);
final LogEvent logEvent1 = Log4jLogEvent
.newBuilder()
.setInstant(instant1)
.build();
// Check the serialized event #1.
usingSerializedLogEventAccessor(layout, logEvent1, accessor -> {
assertThat(accessor.getObject("timestamp.epoch",
Long.class)).isEqualTo(1_634_943_424_218_000_000L);
assertThat(accessor.getString("timestamp.iso8601")).isEqualTo("2021-10-22T22:57:04.218Z");
});
// Create the log event #2.
final MutableInstant instant2 = new MutableInstant();
instant2.initFromEpochSecond(1_634_943_425L, 622_000_000);
final LogEvent logEvent2 = Log4jLogEvent
.newBuilder()
.setInstant(instant2)
.build();
// Check the serialized event #2.
usingSerializedLogEventAccessor(layout, logEvent2, accessor -> {
assertThat(accessor.getObject("timestamp.epoch",
Long.class)).isEqualTo(1_634_943_425_622_000_000L);
assertThat(accessor.getString("timestamp.iso8601")).isEqualTo("2021-10-22T22:57:05.622Z");
});
}
This was a snippet I chucked into `JsonTemplateLayoutTest`. Note that above
timestamp values are copied from the last two examples you shared.
Your examples indicate that epoch nanos resolutions occasionally contain
drifts, whereas formatted timestamps look okay. Both resolvers cache the
last resolution output and either use it (cache hit) or replace it (cache
miss). (See `TimestampResolver` for details.) Epoch resolvers use
`Instant#equals()` to raise a cache hit, formatting resolvers use
`calendar.getTimeInMillis() == logEvent.getTimeMillis()` instead – since
`FastDateFormat` works against `Calendar`s. Both interact with the shared
cache object (referenced by a `private final` member) in a `synchronized
resolve()` method body.
Maybe it is the late hour or the flu I have, I am not able to find a
smoking gun. How occasionally do you encounter these epoch drifts? At least
once a day? Is this a heavily threaded application where contention might
happen relatively a lot at the timestamp resolver's synchronized block? I
have checked 2.15.0-SNAPSHOT sources, they don't contain any changes to the
epoch nanos resolution, hence I don't expect any changes there.
How/Where did you spot these drifts? Do you read the JTL output from the
console? (I am trying to make sure it is not a number rounding problem –
yes Javascript, I am looking at you – while transmitting logs from the
application to your log sink.)
What I will really appreciate is a JUnit test reproducing the issue. Maybe
modifying the snippet I have shared above and shooting at it with some
threads?
Kind regards.
On Mon, Oct 25, 2021 at 8:20 PM Andrew Harris (andharr2) <
andrew.har...@appdynamics.com> wrote:
> 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: log4j-user-unsubscr...@logging.apache.org
> For additional commands, e-mail: log4j-user-h...@logging.apache.org
>
>
