You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-user@logging.apache.org by "Andrew Harris (andharr2)" <an...@appdynamics.com> on 2021/10/25 18:20:02 UTC
Question regarding JSON Template timestamp rendering
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-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-user-help@logging.apache.org
Re: Question regarding JSON Template timestamp rendering
Posted by "Andrew Harris (andharr2)" <an...@appdynamics.com>.
Volkan,
Happy to hear that you have recovered! Thank you also for the info on the 2.15.0 release, I'm looking forward to it for several reasons.
I'll try to answer your questions:
> How do you purpose JTL?
My organization is looking to standardize application logging across our platform. Our goal is to reduce the internal overhead of monitoring, searching, and sense-making with logs. As an early pass toward this, we have developed an application-based log config using Log4j JTL, that conforms to a standard model.
> What do you use for the log storage engine? ELK?
Splunk is the storage engine that I use most often.
> Which appender (pipeline?) do you use to make your way from the application to your log sink?
My main development work for logging right now is on containerized applications, so stdout and the ConsoleAppender are what I use. All stdout logs forward to our aggregators. This follows current Kubernetes guidance that containers should write logs to stdout, for instance.
> What is the scale?
I hope it's enough to say: we run applications of varying sizes and request volumes in a large-enterprise, service-oriented, cloud-based, containerized architecture. We plan to support thousands of containerized application instances using this standard log format, to include Java applications.
> Do you have any Log4j/JTL customizations?
Yes, a couple at the moment. To support a numeric field derived from an existing Resolver, we wrote a simple custom Lookup that roughly translates the Resolver's output. The Lookup isn't perfect, because it exclusively renders as a String and the desired value is numeric, and because the mapping between the existing Resolver and the desired value is not 1:1. I would like to rewrite this translation as a custom Resolver in Log4j 2.15.0, to render the value correctly as numeric, to avoid the garbage hit of the Lookup, and maybe to provide additional data.
I also would like to implement a custom Resolver to render several nested JSON fields. Right now, we render these nested fields from a combination of fixed environment variable Lookups and the MDC Resolver. We have a regular expression with a simple negative lookahead regex on the MDC Resolver to avoid duplicating MDC values that are rendered elsewhere. It would be nice to simplify these assumptions down to one or two custom Resolvers, which could be dropped in much like the current MDC resolver. I also might have a use-case for the Log4j Kubernetes Lookup in the near future.
I hope these responses help. Happy to talk in greater detail as well. Thank you!
Andrew
Re: Question regarding JSON Template timestamp rendering
Posted by Volkan Yazıcı <vo...@yazi.ci>.
Thanks so much for confirming the fix and more importantly, sparing time to
share the issue with us. 2.15.0 is supposed to be released soon. We are
waiting for some changes from another maintainer (I am looking at you
Ralph) and then we will be done.
What I would really appreciate is some details about your use case. How do
you purpose JTL? What do you use for the log storage engine? ELK? Which
appender (pipeline?) do you use to make your way from the application to
your long sink? What is the scale? Do you have any Log4j/JTL customizations?
And... Thanks for your kind words. Flu has shackled me to bed for a couple
of days, but I am feeling better now.
On Thu, Oct 28, 2021 at 8:28 PM Andrew Harris (andharr2) <
andrew.harris@appdynamics.com> wrote:
> Volkan,
>
> I am happy to report that the change in
> 2dd7063fb6c6fe73070aded6607a2e2d53613b46 appears to have resolved the
> issue! After building and installing a local snapshot of
> log4j-layout-template-json from release-2.x, I now see the following in my
> test application:
>
> ```
> {"timestamp.epoch":1635443515353213000,"timestamp.iso8601":"2021-10-28T17:51:55.353Z","severityText":"INFO","body":"Starting
> count"}
> {"timestamp.epoch":1635443515360647000,"timestamp.iso8601":"2021-10-28T17:51:55.360Z","severityText":"INFO","body":"Event
> 0"}
> {"timestamp.epoch":1635443516365136000,"timestamp.iso8601":"2021-10-28T17:51:56.365Z","severityText":"INFO","body":"Event
> 1"}
> {"timestamp.epoch":1635443517365604000,"timestamp.iso8601":"2021-10-28T17:51:57.365Z","severityText":"INFO","body":"Event
> 2"}
> ```
>
> After several more runs, including runs over SLF4J, the epoch timestamp
> resolver operates as expected. I am also happy to report that a pattern
> layout also continues to operate as expected.
>
> Speaking to the test added in 2dd7063f, I ran exactly that test against
> the previous head b6774209, and indeed the test fails. Also a good sign,
> the test seems to cover the logging behavior! Seen as follows:
>
> ```
> [ERROR] Failures:
> [ERROR]
> TimestampResolverTest.epoch_nanos_should_not_overlap:43->lambda$epoch_nanos_should_not_overlap$1:69
> Found duplicate(s):
> [1635444597296722000L]
> in:
> [1635444597296722000L,
> 1635444597296722000L,
> 1635444597296722000L,
> 1635444597296722000L,
> 1635444597296722000L]
> ```
>
> Meanwhile, of course, the test passes in 2dd7063f.
>
> Thank you for your help here. I am sorry that I wasn't able to isolate the
> issue more quickly, let alone provide a test case myself. Looking forward
> to this change arriving in a future release. Hope you are feeling better,
> too!
>
> Andrew
>
Re: Question regarding JSON Template timestamp rendering
Posted by "Andrew Harris (andharr2)" <an...@appdynamics.com>.
Volkan,
I am happy to report that the change in 2dd7063fb6c6fe73070aded6607a2e2d53613b46 appears to have resolved the issue! After building and installing a local snapshot of log4j-layout-template-json from release-2.x, I now see the following in my test application:
```
{"timestamp.epoch":1635443515353213000,"timestamp.iso8601":"2021-10-28T17:51:55.353Z","severityText":"INFO","body":"Starting count"}
{"timestamp.epoch":1635443515360647000,"timestamp.iso8601":"2021-10-28T17:51:55.360Z","severityText":"INFO","body":"Event 0"}
{"timestamp.epoch":1635443516365136000,"timestamp.iso8601":"2021-10-28T17:51:56.365Z","severityText":"INFO","body":"Event 1"}
{"timestamp.epoch":1635443517365604000,"timestamp.iso8601":"2021-10-28T17:51:57.365Z","severityText":"INFO","body":"Event 2"}
```
After several more runs, including runs over SLF4J, the epoch timestamp resolver operates as expected. I am also happy to report that a pattern layout also continues to operate as expected.
Speaking to the test added in 2dd7063f, I ran exactly that test against the previous head b6774209, and indeed the test fails. Also a good sign, the test seems to cover the logging behavior! Seen as follows:
```
[ERROR] Failures:
[ERROR] TimestampResolverTest.epoch_nanos_should_not_overlap:43->lambda$epoch_nanos_should_not_overlap$1:69
Found duplicate(s):
[1635444597296722000L]
in:
[1635444597296722000L,
1635444597296722000L,
1635444597296722000L,
1635444597296722000L,
1635444597296722000L]
```
Meanwhile, of course, the test passes in 2dd7063f.
Thank you for your help here. I am sorry that I wasn't able to isolate the issue more quickly, let alone provide a test case myself. Looking forward to this change arriving in a future release. Hope you are feeling better, too!
Andrew
Re: Question regarding JSON Template timestamp rendering
Posted by Volkan Yazıcı <vo...@yazi.ci>.
Andrew, I have pushed a fix to the `release-2.x` branch with commit
`2dd7063fb6c6fe73070aded6607a2e2d53613b46`.
Mind giving it a try, please?
For the records, created LOG4J2-3183
<https://issues.apache.org/jira/browse/LOG4J2-3183>.
On Thu, Oct 28, 2021 at 11:02 AM Volkan Yazıcı <vo...@yazi.ci> wrote:
> I sadly am able to reproduce the issue Andrew:
>
> public final class TimeDriftDemo {
>
> public static void main(String[] args) throws InterruptedException {
> initLog4j();
> Logger logger = LogManager.getLogger();
> for (int i = 0; i < 5; i++) {
> logger.info("{}", i);
> Thread.sleep(100);
> }
> }
>
> private static LoggerContext initLog4j() {
>
> // Create the configuration builder.
> ConfigurationBuilder<BuiltConfiguration> configBuilder = ConfigurationBuilderFactory
> .newConfigurationBuilder()
> .setStatusLevel(Level.ERROR)
> .setConfigurationName(TimeDriftDemo.class.getSimpleName());
>
> // Create the configuration.
> String appenderName = "Console";
> String eventTemplate = "" +
> "[{\"$resolver\":\"timestamp\",\"epoch\":{\"unit\":\"nanos\"}}" +
> ",{\"$resolver\":\"timestamp\",\"pattern\":{\"format\":\"ss.SSS'Z'\",\"timeZone\":\"UTC\",\"locale\":\"en_US\"}}" +
> "]";
> Configuration config = configBuilder
> .add(configBuilder
> .newAppender(appenderName, "Console")
> .add(configBuilder
> .newLayout("JsonTemplateLayout")
> .addAttribute(
> "eventTemplate",
> eventTemplate)))
> .add(configBuilder.newLogger("com.vlkan", Level.TRACE))
> .add(configBuilder
> .newRootLogger(Level.ERROR)
> .add(configBuilder.newAppenderRef(appenderName)))
> .build(false);
>
> // Initialize the configuration.
> return Configurator.initialize(config);
>
> }
>
> }
>
> I will create a ticket and act on it.
> Thanks so much for the report!
>
>
> On Thu, Oct 28, 2021 at 3:19 AM Andrew Harris (andharr2) <
> andrew.harris@appdynamics.com> wrote:
>
>> Volkan,
>>
>> I was able to get the test case you supplied running in
>> JsonTemplateLayoutTest. I confirm that it passes on my system as well. In
>> fact, all the tests in `log4j-layout-template-json` at `rel/2.14.1` pass
>> (except JsonTemplateLayoutGcFreeTest, which I'm willing to believe is a
>> quirk of that test vis-a-vis my setup). That tells me that log rendering in
>> unit-test isolation operates as expected.
>>
>> I extended the test case to use SystemClock to generate two Instants with
>> a short pause between generation, like:
>> ```
>> final Clock systemClock = new SystemClock();
>> final MutableInstant instant3 = new MutableInstant();
>> instant3.initFrom(systemClock);
>> try { Thread.sleep(100); } catch (InterruptedException e) {};
>> final MutableInstant instant4 = new MutableInstant();
>> instant4.initFrom(systemClock);
>>
>> final LogEvent logEvent3 =
>> Log4jLogEvent.newBuilder().setInstant(instant3).build();
>> final LogEvent logEvent4 =
>> Log4jLogEvent.newBuilder().setInstant(instant4).build();
>>
>> usingSerializedLogEventAccessor(layout, logEvent3, accessor3 -> {
>> usingSerializedLogEventAccessor(layout, logEvent4, accessor4
>> -> {
>> Long epoch3 = accessor3.getObject("timestamp.epoch",
>> Long.class);
>> String iso3 = accessor3.getString("timestamp.iso8601");
>>
>> Long epoch4 = accessor4.getObject("timestamp.epoch",
>> Long.class);
>> String iso4 = accessor4.getString("timestamp.iso8601");
>>
>> assertThat(epoch4 - epoch3).isGreaterThanOrEqualTo(100L);
>> assertThat(iso3).isNotEqualTo(iso4);
>> });
>> });
>> ```
>>
>> This test portion also passed. This tells me that the act of deriving the
>> time from a provided clock operates as expected.
>>
>> Back in my example application, I did some more experimentation and found
>> the following:
>>
>> - Removing the timestamp pattern resolver from the JSON template does not
>> change behavior. Epoch timestamps continue to be repeated.
>> - Changing the timestamp epoch resolver to use millis or seconds does not
>> change behavior. Epoch timestamps are correctly rounded and rendered, they
>> just don't appear to advance.
>>
>> Seeking to rule out whether this was due to behavior in the logger, I
>> switched to an async logger using Disruptor 3.4.4:
>> - Passing
>> '-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector'
>> does not appear to change behavior.
>> - Using an AsyncLogger does not appear to change behavior.
>> - Changing `log4j2.clock` to use CachedClock (vs SystemClock) does not
>> change behavior. Some precision in the nano timestamp is lost, as I believe
>> is expected.
>>
>> I sought to rule out JDK differences, so I ran my bench application
>> against Azul Zulu 8, 11, and 16, as well as AdoptOpenJDK 11 on J9. No
>> change in behavior between these, the epoch was still repeated between runs.
>>
>> Using a PatternLayout allows both Unix epoch and pattern-derived
>> timestamps to be rendered as expected:
>> ```
>> <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} - %logger{36} - %msg
>> timestamp=%d{UNIX_MILLIS} %n"/>
>> ```
>>
>> """
>> 2021-10-27 18:07:28.111 - example.Log4jApp - Starting count
>> timestamp=1635383248111
>> 2021-10-27 18:07:28.118 - example.Log4jApp - Event 0
>> timestamp=1635383248118
>> 2021-10-27 18:07:29.123 - example.Log4jApp - Event 1
>> timestamp=1635383249123
>> """
>>
>> I confirmed the behavior of the PatternLayout with an AsyncLogger as
>> well, and it too worked as expected.
>>
>> Please let me know what might be worth trying next here, and thank you
>> for your ideas up to now. I'm quite confused at this point. :)
>>
>> Andrew
>>
>
Re: Question regarding JSON Template timestamp rendering
Posted by Volkan Yazıcı <vo...@yazi.ci>.
I sadly am able to reproduce the issue Andrew:
public final class TimeDriftDemo {
public static void main(String[] args) throws InterruptedException {
initLog4j();
Logger logger = LogManager.getLogger();
for (int i = 0; i < 5; i++) {
logger.info("{}", i);
Thread.sleep(100);
}
}
private static LoggerContext initLog4j() {
// Create the configuration builder.
ConfigurationBuilder<BuiltConfiguration> configBuilder =
ConfigurationBuilderFactory
.newConfigurationBuilder()
.setStatusLevel(Level.ERROR)
.setConfigurationName(TimeDriftDemo.class.getSimpleName());
// Create the configuration.
String appenderName = "Console";
String eventTemplate = "" +
"[{\"$resolver\":\"timestamp\",\"epoch\":{\"unit\":\"nanos\"}}" +
",{\"$resolver\":\"timestamp\",\"pattern\":{\"format\":\"ss.SSS'Z'\",\"timeZone\":\"UTC\",\"locale\":\"en_US\"}}"
+
"]";
Configuration config = configBuilder
.add(configBuilder
.newAppender(appenderName, "Console")
.add(configBuilder
.newLayout("JsonTemplateLayout")
.addAttribute(
"eventTemplate",
eventTemplate)))
.add(configBuilder.newLogger("com.vlkan", Level.TRACE))
.add(configBuilder
.newRootLogger(Level.ERROR)
.add(configBuilder.newAppenderRef(appenderName)))
.build(false);
// Initialize the configuration.
return Configurator.initialize(config);
}
}
I will create a ticket and act on it.
Thanks so much for the report!
On Thu, Oct 28, 2021 at 3:19 AM Andrew Harris (andharr2) <
andrew.harris@appdynamics.com> wrote:
> Volkan,
>
> I was able to get the test case you supplied running in
> JsonTemplateLayoutTest. I confirm that it passes on my system as well. In
> fact, all the tests in `log4j-layout-template-json` at `rel/2.14.1` pass
> (except JsonTemplateLayoutGcFreeTest, which I'm willing to believe is a
> quirk of that test vis-a-vis my setup). That tells me that log rendering in
> unit-test isolation operates as expected.
>
> I extended the test case to use SystemClock to generate two Instants with
> a short pause between generation, like:
> ```
> final Clock systemClock = new SystemClock();
> final MutableInstant instant3 = new MutableInstant();
> instant3.initFrom(systemClock);
> try { Thread.sleep(100); } catch (InterruptedException e) {};
> final MutableInstant instant4 = new MutableInstant();
> instant4.initFrom(systemClock);
>
> final LogEvent logEvent3 =
> Log4jLogEvent.newBuilder().setInstant(instant3).build();
> final LogEvent logEvent4 =
> Log4jLogEvent.newBuilder().setInstant(instant4).build();
>
> usingSerializedLogEventAccessor(layout, logEvent3, accessor3 -> {
> usingSerializedLogEventAccessor(layout, logEvent4, accessor4
> -> {
> Long epoch3 = accessor3.getObject("timestamp.epoch",
> Long.class);
> String iso3 = accessor3.getString("timestamp.iso8601");
>
> Long epoch4 = accessor4.getObject("timestamp.epoch",
> Long.class);
> String iso4 = accessor4.getString("timestamp.iso8601");
>
> assertThat(epoch4 - epoch3).isGreaterThanOrEqualTo(100L);
> assertThat(iso3).isNotEqualTo(iso4);
> });
> });
> ```
>
> This test portion also passed. This tells me that the act of deriving the
> time from a provided clock operates as expected.
>
> Back in my example application, I did some more experimentation and found
> the following:
>
> - Removing the timestamp pattern resolver from the JSON template does not
> change behavior. Epoch timestamps continue to be repeated.
> - Changing the timestamp epoch resolver to use millis or seconds does not
> change behavior. Epoch timestamps are correctly rounded and rendered, they
> just don't appear to advance.
>
> Seeking to rule out whether this was due to behavior in the logger, I
> switched to an async logger using Disruptor 3.4.4:
> - Passing
> '-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector'
> does not appear to change behavior.
> - Using an AsyncLogger does not appear to change behavior.
> - Changing `log4j2.clock` to use CachedClock (vs SystemClock) does not
> change behavior. Some precision in the nano timestamp is lost, as I believe
> is expected.
>
> I sought to rule out JDK differences, so I ran my bench application
> against Azul Zulu 8, 11, and 16, as well as AdoptOpenJDK 11 on J9. No
> change in behavior between these, the epoch was still repeated between runs.
>
> Using a PatternLayout allows both Unix epoch and pattern-derived
> timestamps to be rendered as expected:
> ```
> <PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} - %logger{36} - %msg
> timestamp=%d{UNIX_MILLIS} %n"/>
> ```
>
> """
> 2021-10-27 18:07:28.111 - example.Log4jApp - Starting count
> timestamp=1635383248111
> 2021-10-27 18:07:28.118 - example.Log4jApp - Event 0
> timestamp=1635383248118
> 2021-10-27 18:07:29.123 - example.Log4jApp - Event 1
> timestamp=1635383249123
> """
>
> I confirmed the behavior of the PatternLayout with an AsyncLogger as well,
> and it too worked as expected.
>
> Please let me know what might be worth trying next here, and thank you for
> your ideas up to now. I'm quite confused at this point. :)
>
> Andrew
>
Re: Question regarding JSON Template timestamp rendering
Posted by "Andrew Harris (andharr2)" <an...@appdynamics.com>.
Volkan,
I was able to get the test case you supplied running in JsonTemplateLayoutTest. I confirm that it passes on my system as well. In fact, all the tests in `log4j-layout-template-json` at `rel/2.14.1` pass (except JsonTemplateLayoutGcFreeTest, which I'm willing to believe is a quirk of that test vis-a-vis my setup). That tells me that log rendering in unit-test isolation operates as expected.
I extended the test case to use SystemClock to generate two Instants with a short pause between generation, like:
```
final Clock systemClock = new SystemClock();
final MutableInstant instant3 = new MutableInstant();
instant3.initFrom(systemClock);
try { Thread.sleep(100); } catch (InterruptedException e) {};
final MutableInstant instant4 = new MutableInstant();
instant4.initFrom(systemClock);
final LogEvent logEvent3 = Log4jLogEvent.newBuilder().setInstant(instant3).build();
final LogEvent logEvent4 = Log4jLogEvent.newBuilder().setInstant(instant4).build();
usingSerializedLogEventAccessor(layout, logEvent3, accessor3 -> {
usingSerializedLogEventAccessor(layout, logEvent4, accessor4 -> {
Long epoch3 = accessor3.getObject("timestamp.epoch", Long.class);
String iso3 = accessor3.getString("timestamp.iso8601");
Long epoch4 = accessor4.getObject("timestamp.epoch", Long.class);
String iso4 = accessor4.getString("timestamp.iso8601");
assertThat(epoch4 - epoch3).isGreaterThanOrEqualTo(100L);
assertThat(iso3).isNotEqualTo(iso4);
});
});
```
This test portion also passed. This tells me that the act of deriving the time from a provided clock operates as expected.
Back in my example application, I did some more experimentation and found the following:
- Removing the timestamp pattern resolver from the JSON template does not change behavior. Epoch timestamps continue to be repeated.
- Changing the timestamp epoch resolver to use millis or seconds does not change behavior. Epoch timestamps are correctly rounded and rendered, they just don't appear to advance.
Seeking to rule out whether this was due to behavior in the logger, I switched to an async logger using Disruptor 3.4.4:
- Passing '-Dlog4j2.contextSelector=org.apache.logging.log4j.core.async.AsyncLoggerContextSelector' does not appear to change behavior.
- Using an AsyncLogger does not appear to change behavior.
- Changing `log4j2.clock` to use CachedClock (vs SystemClock) does not change behavior. Some precision in the nano timestamp is lost, as I believe is expected.
I sought to rule out JDK differences, so I ran my bench application against Azul Zulu 8, 11, and 16, as well as AdoptOpenJDK 11 on J9. No change in behavior between these, the epoch was still repeated between runs.
Using a PatternLayout allows both Unix epoch and pattern-derived timestamps to be rendered as expected:
```
<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} - %logger{36} - %msg timestamp=%d{UNIX_MILLIS} %n"/>
```
"""
2021-10-27 18:07:28.111 - example.Log4jApp - Starting count timestamp=1635383248111
2021-10-27 18:07:28.118 - example.Log4jApp - Event 0 timestamp=1635383248118
2021-10-27 18:07:29.123 - example.Log4jApp - Event 1 timestamp=1635383249123
"""
I confirmed the behavior of the PatternLayout with an AsyncLogger as well, and it too worked as expected.
Please let me know what might be worth trying next here, and thank you for your ideas up to now. I'm quite confused at this point. :)
Andrew
Re: Question regarding JSON Template timestamp rendering
Posted by "Andrew Harris (andharr2)" <an...@appdynamics.com>.
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
Re: Question regarding JSON Template timestamp rendering
Posted by "Andrew Harris (andharr2)" <an...@appdynamics.com>.
Volkan,
Thank you for the reply, and for the insight regarding the caching action of rendered timestamps. That would seem like a great place for me to try to investigate further.
You asked about the environment in which I spotted these drifts. The application in which I am using Log4J is a Micronaut-based API service (https://micronaut.io/). The log output I offered in my first message was, I believe, just vanilla console logging through Log4J while running the application in a Docker harness. Debug-level logging was enabled, however I wasn't deliberately introducing load on the application, just making some simple API calls.
I'll see what I can do about reproducing the behavior in a test case, or in some other generic format. Feel better soon!
Andrew
________________________________
From: Volkan Yazıcı <vo...@yazi.ci>
Sent: Monday, October 25, 2021 12:55 PM
To: Log4J Users List <lo...@logging.apache.org>
Subject: Re: Question regarding JSON Template timestamp rendering
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.harris@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-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>
Re: Question regarding JSON Template timestamp rendering
Posted by Volkan Yazıcı <vo...@yazi.ci>.
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.harris@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-unsubscribe@logging.apache.org
> For additional commands, e-mail: log4j-user-help@logging.apache.org
>
>