You are viewing a plain text version of this content. The canonical link for it is here.
Posted to notifications@logging.apache.org by "fabian-braun (via GitHub)" <gi...@apache.org> on 2025/06/30 15:23:38 UTC
[I] Broken timestamp since Log4J 2.25 [logging-log4j2]
fabian-braun opened a new issue, #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792
## Description
We sometimes encounter broken timestamp fields in our logs since we upgraded to the latest Log4J version which has been released a few days ago.
The logged timestamp is cut off and cannot be parsed by our ElasticSearch backend. For example it looks like `2025-06-28T10:20:` (note how seconds, etc are missing)
## Configuration
**Version:** 2.25.0
**Operating system:** Linux, 6.8.0-1024-aws
**JDK:** amazoncorretto:21-al2023
## Logs
```
[Stacktraces, errors, etc. relevant applications logs.]
```
## Reproduction
[An isolated test reproducing the test.
JUnit tests similar to the ones in the code base are extremely appreciated.]
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "vy (via GitHub)" <gi...@apache.org>.
vy commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3031568375
@fabian-braun Thanks for the report, much appreciated! 🙇
Could you reproduce the problem after implementing following changes?
1. Remove the `LOG4J_INSTANT_FORMATTER=legacy` environment variable (switch to use the defaults)
2. Add `LOG4J_ENABLE_THREADLOCALS=false`<sup>1</sup> (disable `ThreadLocal`s)
<sup>1</sup> [`log4j2.enableThreadlocals`](https://logging.apache.org/log4j/2.x/manual/systemproperties.html#log4j2.enableThreadlocals)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3022819492
@fabian-braun,
Thank you for bringing this to our attention! We’ll investigate further. Please note that formatters are recalculated every minute and cached. Could you clarify whether all the log events at `2025-06-28T10:20` are missing the end, or is it just a subset of them?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3024702924
I now took a look at all the failed log attempts on that day. We have 14 broken log events.
5 out of 14 have the broken timestamp with missing seconds-part.
The other 9 **are missing the timestamp completely**
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3027296707
Before switching back to the legacy format, I also observed a case now, where the sub second part is missing:
`"@timestamp": "2025-07-01T04:24:02.",`
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3035038748
Hi @ppkarwasz , your explanation makes sense from my POV thanks for elaborating and the feedback! How does this continue now? Will you implement a fix? I was wondering how it could be fixed: Could `lastEpochInstantAndBuffer` also become a ThreadLocal? Or do you want to preserve caching across Threads?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3027276204
Since we re-deployed the app with `LOG4J_INSTANT_FORMATTER=legacy` the problem is gone. In the last 24 hours since the deployment all logs could be parsed. So, I'm quite convinced now that the problem is indeed related to the latest Log4J release
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "garydgregory (via GitHub)" <gi...@apache.org>.
garydgregory commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3035444858
> That way, we can review the three open PRs over the weekend and aim to stage 2.25.1 next week.
I like that plan! đź‘Ť
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3035412560
Hi @fabian-braun,
The core issue with `lastEpochInstantAndBuffer` is that it's **not immutable**, unlike the previous `CachedTime` implementation:
https://github.com/apache/logging-log4j2/blob/054a4f7084b8a03f932bc9dd40ebba55142a36be/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java#L161-L171
Using a `String` instead of a `StringBuilder` would break the GC-free behavior expected when `log4j2.enableThreadlocals == true`, so we need to proceed carefully.
Here’s what I propose:
1. **In version 2.25.1** (scheduled for release next week), we remove `lastEpochInstantAndBuffer` entirely and eliminate inter-thread sharing. We’ll rely exclusively on the thread locals.
2. **In version 2.26.0**, we could consider introducing a non-GC-free version of `InstantPatternThreadLocalCachedFormatter`. This variant would be used when `log4j2.enableThreadlocals = false`, and it would format timestamps to immutable `String` values.
@vy What do you think? Since this is the last urgent issue for `2.25.1`, I’ll go ahead and open a PR for the first point shortly to help speed up development. That way, we can review the three open PRs over the weekend and aim to stage `2.25.1` next week.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3034786748
@vy since my deployment yesterday **no** further broken logs appeared. So it seems your suspicion was **right** and switching ThreadLocals off also fixes the problem. I hope that helps you to identify the root cause?
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3034941944
Hi @fabian-braun,
Thank you very much for the detailed debugging—it's truly appreciated! Most users who report concurrency issues under heavy load expect us to either reproduce the problem in our own test environments or guess what might be going wrong. Your investigation helps a lot.
I believe your findings explain the issue quite well. A likely root cause lies in how `InstantPatternThreadLocalCachedFormatter` handles the reuse of `StringBuilder` instances across threads. Although each thread has **its own** `StringBuilder` via `ThreadLocal`, the formatter’s logic exposes these reusable builders in a read-only way to other threads.
Here’s a possible sequence of events that could trigger the bug:
1. **Thread A** formats a timestamp and, on line 113, caches the result—making it visible to other threads.
2. **Thread B** starts formatting the *same* timestamp and retrieves the cached value from Thread A.
3. Meanwhile, **Thread A** begins formatting the timestamp for the *next* millisecond, executing the logic at lines 109–110.
4. Since both threads are referencing the **same** `StringBuilder` (via a shared cache), Thread B may encounter inconsistent state, depending on exactly where Thread A is in the formatting process. This can result in:
- An empty string (if Thread A is still at line 109).
- A partially formatted timestamp (if Thread A is mid-way through line 110).
Our new formatter decomposes the pattern `yyyy-MM-dd'T'HH:mm:ss.SSS'Z'` into:
- `yyyy-MM-dd'T'HH:mm`, evaluated once per minute,
- `ss.SSS`, evaluated every time,
- `'Z'`, a constant string evaluated once.
So if Thread B picks up a `StringBuilder` while it's only partially updated, it might receive just one or two of these segments, leading to the incorrect or incomplete timestamps you're observing.
Here is the relevant code for reference:
https://github.com/apache/logging-log4j2/blob/3ba9da5eef7c3a65a95a7ca547bbe2852aecb0d3/log4j-core/src/main/java/org/apache/logging/log4j/core/util/internal/instant/InstantPatternThreadLocalCachedFormatter.java#L89-L118
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3024584127
> [@fabian-braun](https://github.com/fabian-braun),
>
> Thank you for bringing this to our attention! We’ll investigate further. Please note that formatters are recalculated every minute and cached. Could you clarify whether all the log events at `2025-06-28T10:20` are missing the end, or is it just a subset of them?
@ppkarwasz , it is only a subset. I see log events on the same pod, for example with a timestamp of `2025-06-28T10:20:49.554Z` and `2025-06-28T10:20:01.173Z`
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3024672734
These are all the times for which we did observe log events in that same minute on the same pod
[scratch_3.txt](https://github.com/user-attachments/files/21004141/scratch_3.txt)
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "ppkarwasz (via GitHub)" <gi...@apache.org>.
ppkarwasz closed issue #3792: Broken timestamp since Log4J 2.25
URL: https://github.com/apache/logging-log4j2/issues/3792
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Broken timestamp since Log4J 2.25 [logging-log4j2]
Posted by "fabian-braun (via GitHub)" <gi...@apache.org>.
fabian-braun commented on issue #3792:
URL: https://github.com/apache/logging-log4j2/issues/3792#issuecomment-3031592613
I will deploy it right away
<img width="506" alt="Image" src="https://github.com/user-attachments/assets/e7931d46-b51d-4460-98c7-76da65771306" />
We will have to wait 24 hours to be sure that this setting also fixes the problem. I let you know as soon as I see broken logs again
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: notifications-unsubscribe@logging.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org