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