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. > > > > >
