Hey Stephan, I have already fixed the issue both in `2.x` and `main` branches – I've updated your ticket accordingly.
> 1. The first is similar to what you proposed, but the check `if > (currentTime > cachedTime)` would only be used to decide whether the cached > time should be updated or not That is exactly what I had in mind. > 2. ... the same cached formatted time > could be reused as long as `instant.getEpochSecond() == > cached.epochSecond` We discussed this privately with Piotr and he has already shared his approach in his email pointing to his PR. What I think ideally should be done is to derive a comparison function from the pattern. That is, if the pattern is `%y-%m-%d`, the cache is still usable if the time difference is less than 1 day. There is a limited number of date-time pattern directives, we just need a table that maps each pattern to a precision which eventually points to a comparison function. For the records, I still have the impression that our date-time formatting infrastructure is sort of over-engineered. We have 3 competing implementations in the code Log4j base. In a setup where the human-readable date-time formatting of your logger is the bottleneck, I wonder if it is the logger that should be improved. In short, I am hesitant to introduce more sophistication into date-time formatting. On Thu, May 25, 2023 at 9:35 PM Stephan Markwalder <step...@markwalder.net> wrote: > Hi Volkan, > > Thank you very much for your feedback. > > I have created a GitHub issue: > https://github.com/apache/logging-log4j2/issues/1490 > > I also have an almost-ready mini application to reproduce the problem which > I will link in the GitHub issue in the next days, probably on Sunday. > > You wrote: > > shouldn't those `if (currentTime != cachedTime)` checks around the > compare-and-swap be replaced with `if (currentTime > cachedTime)`. > > I think the current strict inequality test is correct. Since different > threads can reach this code "out of order" (compared to when the event time > has been recorded), we cannot make any assumptions about whether the > current time is greater, equal, or less than the cached time. All the code > can do is re-used the cached formatted timestamp if the current time is > equal to the cached time. > > But there are two other improvements which could be made: > > 1. The first is similar to what you proposed, but the check `if > (currentTime > cachedTime)` would only be used to decide whether the cached > time should be updated or not. The assumption is that events will usually > (in the absence of concurrent threads) be logged with increasing times. So > the next event that will be logged in the future will most likely have a > time which is greater than or equal to `max(currentTime, cachedTime)`. By > only updating the cached time when it is less than the current time, the > code would increase the likelihood of a cache hit on the next method > invocation. > > 2. As of today, the cached formatted time is only reused if an event is > logged with the exact same `epochSecond` and `nanoOfSeconds` as the cached > time. But if the DatePatternConverter is configured with a time pattern > like "HH:mm:ss" which ignores everything more accurate than seconds, then > the value of `nanoOfSeconds` is actually irrelevant. No matter what this > value is, the formatted time will only be different if the value of > `epochSecond` is different. In other words, the same cached formatted time > could be reused as long as `instant.getEpochSecond() == > cached.epochSecond`. All events logged within the same second could benefit > from the cached formatted time. With some more logic, a similar improvement > could be achieved when using the default time pattern "HH:mm:ss,SSS", only > that the code now would have to compare the values of `nanoOfSeconds / > 1000000`. > > Best, > Stephan > > > On Tue, May 23, 2023 at 11:41 AM Volkan Yazıcı <vol...@yazi.ci> wrote: > > > Thanks so much for the report and the diligent analysis, Stephan! > > Much appreciated! 🙏 > > > > I think your analysis is correct. > > Would you mind creating a GitHub Issue, please? > > I will push a fix some time tonight (CET). > > > > I skimmed through JSON Template Layout's `InstantFormatter`, and it is > > looking fine. > > I want to investigate further if there are other places/layouts where > > the issue manifests itself. > > I wish I would have time to strap some jcstress harness around certain > > parts of Log4j. > > > > For the records, it always makes me wonder shouldn't those `if > (currentTime > > != cachedTime)` checks around the compare-and-swap be replaced with `if > > (currentTime > cachedTime)`. 🤔 > > > > @Piotr, @Christian, yet another supporting case for my "Unified date-time > > formatting" venture. > > > > On Sun, May 21, 2023 at 4:22 PM Stephan Markwalder < > > stephan.markwal...@fnz.com> wrote: > > > > > Hi, > > > > > > I'm not 100% sure if my analysis is correct. I therefore write to you > > > before opening an issue on GitHub. > > > > > > If two threads are calling the method > > > DatePatternConverter.formatWithoutThreadLocals(Instant,StringBuilder) > at > > > the same time, one of the threads may incorrectly use the formatted > date > > of > > > the other thread in the output. In other words, the event of one thread > > > could be written to a log file with the date of the other thread's > event. > > > > > > The following sequence shows how this could happen. All line numbers > are > > > based on this source code: > > > > > > > > > https://github.com/apache/logging-log4j2/blob/98c3ceb655d485b0adb48e05d84c8269716f59e8/log4j-core/src/main/java/org/apache/logging/log4j/core/pattern/DatePatternConverter.java#L327-L338 > > > > > > 0. cachedTime contains time t0. > > > > > > Thread 1: > > > 1. Line 327: Calls the method formatWithoutThreadLocals(instant,output) > > > with instant = t1, where t1 > t0. > > > 2. Line 328: Reads t0 from cachedTime into local variable cached. > > > 3. Line 329: if condition evaluates to true (t1 != t0). > > > 4. Line 330: Creates a new CachedTime(t1) and stores it in local > variable > > > newTime. > > > > > > Thread 2: > > > 5. Line 327: Calls the method formatWithoutThreadLocals(instant,output) > > > with instant = t2, where t2 > t1. > > > 6. Line 328: Reads t0 from cachedTime into local variable cached. > > > 7. Line 329: if condition evaluates to true (t2 != t0). > > > 8. Line 330: Creates a new CachedTime(t2) and stores it in local > variable > > > newTime. > > > > > > Thread 1: > > > 9. Line 331: Calls cachedTime.compareAndSet(cached, newTime): This will > > > set the shared cachedTime to thread 1's newTime t1 and return true > > > (t0.compareAndSet(t0,t1) == true). > > > 10. Line 332: Sets local variable cached = newTime (t1). > > > 11. Line 337: Appends cached.formatted (t1) to output. > > > > > > Thread 2: > > > 12. Line 331: Calls cachedTime.compareAndSet(cached, newTime): This > will > > > NOT change the shared cachedTime and return false > > (t1.compareAndSet(t0,t2) > > > == false). > > > 13. Line 334: Sets local variable cached = cachedTime.get(). <-- This > > will > > > read t1 into local variable cached! > > > 14. Line 337: Appends cached.formatted (t1!) to output. > > > > > > Result: The event recorded by thread 2 at time t2 will be logged with a > > > formatted date based on t1, the time when thread 1 has recorded its own > > > event. In other words, both events would be written to the log file > with > > > the same date and time, and the time of event 2 is completely lost. > Also, > > > in the presence of multiple appenders, the same event can be written to > > > different log files with a different date and time. > > > > > > I think the problem is found at line 334 where thread 2 is reading the > > > time that was previously written to cachedTime by thread 1. In order to > > use > > > the correct time, thread 2 should instead set cached = newTime. This > > means > > > that the if block (line 330) and else block (line 332) would be > > identical. > > > So the return value of cachedTime.compareAndSet(cached, newTime) would > > not > > > be needed, and the code could be simplified a lot. > > > > > > Is my analysis correct, or am I missing something? > > > > > > Best regards, > > > Stephan > > > > > > PS 1: This issue has been found when using Log4j in a web application. > > > This means that the use of thread-locals for "gc-free logging" is > > disabled > > > by default. > > > PS 2: The web application currently uses only synchronous loggers and > > > appenders. > > > Email Disclaimer > > > FNZ (UK) Ltd registered in England and Wales (05435760) 10th Floor, 135 > > > Bishopsgate, London EC2M 3TP, FNZ (UK) Ltd is authorised and regulated > by > > > the Financial Conduct Authority (438687); FNZ TA Services Ltd > registered > > in > > > England and Wales (09571767) 10th Floor, 135 Bishopsgate, London EC2M > > 3TP, > > > FNZ TA Services Ltd is authorised and regulated by the Financial > Conduct > > > Authority (932253); FNZ Securities Ltd registered in England and Wales > > > (09486463) 10th Floor, 135 Bishopsgate, London EC2M 3TP, FNZ Securities > > > Ltd, is authorised and regulated by the Financial Conduct Authority > > > (733400); JHC Systems Limited registered in England and Wales > (08729370) > > > Temple Point 6th Floor, 1 Temple Row, Birmingham, West Midlands, B2 > 5LG; > > > FNZ (Europe) DAC registered in Ireland (657886) Block C, Irish Life > > > Centre, Lower Abbey Street, Dublin 1, D01V9F5, Ireland; FNZ SA (Pty) > Ltd > > > registered under the laws of South Africa (2018/547997/07), 1st floor, > > > Newport House, Prestwich Street, Greenpoint, western Cape, 8001; FNZ > > > Limited registered in New Zealand (1797706) FNZ House, Level 3, 29A > > Brandon > > > Street, Wellington, 6011 New Zealand; FNZ (Australia) Pty Ltd > registered > > in > > > Australia (138 819 119) Level 1, 99 Elizabeth St, Sydney 2000; FNZ > (Hong > > > Kong) Limited registered in Hong Kong (1305362) 6A-1, Koshun House, 331 > > > Nathan Road, Hong Kong; FNZ (Singapore) Services Pte. Ltd. registered > in > > > Singapore (201307199R) 61 Robinson Road, #13-03A, Robinson Centre, > > > Singapore (068893); and FNZ (China) Ltd registered in China > > > (91310115MA1K3G4K6T) [中国（上海）自由贸易试验区世纪大道1196 号二 座20 层. > > > This message is intended solely for the addressee and may contain > > > confidential information. If you have received this message in error, > > > please send it back to us, and immediately and permanently delete it. > Do > > > not use, copy or disclose the information contained in this message or > in > > > any attachment. > > > Emails sent to and from FNZ may be monitored and read for legitimate > > > business purposes. Emails cannot be guaranteed to be secure or > > error-free, > > > and you should protect your systems. FNZ does not accept any liability > > > arising from interception, corruption, loss or destruction of this > email, > > > or if it arrives late or incomplete or with errors or viruses. > > > For more information about the FNZ group please visit our website here > > > where you can also find links to our policies including our Privacy > > policy > > > which provides information about what we do with your personal data. > > > > > > > > >
