http://bugzilla.slf4j.org/show_bug.cgi?id=176 Ryan Cogswell <rcogswell@datasltn.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |rcogswell@datasltn.com -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #1 from Gili <cowwoc@bbs.darktech.org> 2011-06-19 05:34:01 CEST --- *** Bug 223 has been marked as a duplicate of this bug. *** -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 Ceki Gulcu <listid@qos.ch> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |listid@qos.ch --- Comment #3 from Ceki Gulcu <listid@qos.ch> 2011-06-21 22:11:12 CEST --- Hello Ryan, I will have a look at this in the next few days. If I somehow forget, please do not hesitate to remind me. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 Timofey Basanov <timofey.basanov@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |timofey.basanov@gmail.com --- Comment #4 from Timofey Basanov <timofey.basanov@gmail.com> 2011-06-24 08:58:31 CEST --- I would like to vote for this bug. I also get it during parallel unit-testing with TestNG. It took several hours of debugging before I understand the reason why it is happening. It made me really sad, because before of that slf4j was "just working" without the need to read through its internals. Thanks for such a good product BTW. I also would like to add that now slf4j code has data race due to incorrect access to shared variable. org.slf4j.LoggerFactory#INITIALIZATION_STATE could be easily accessed for read and write operations from multiple threads without synchronization primitives. According to JLS specification there are no guaranties from JVM on changes to state of such variable visible to other threads. Af far as I know the best way to fix this is to place synchronized(lock) guards around all places where you read or write to this variable. As far as I understand the code the simplest way to achieve this will be to place synchronized modifier onto org.slf4j.LoggerFactory#getILoggerFactory org.slf4j.LoggerFactory#reset and org.slf4j.LoggerFactory#failedBinding because they are the only public method. Cause creating fabric and not the logger should be pretty fast this will not impose any specific drawbacks for slf4j. This will also guarantee, that there will be no problems with order of synchronization for different threads which we are posing in this ticket. If this is not viable solution for some reason then I request to at least add volatile modificator for org.slf4j.LoggerFactory#INITIALIZATION_STATE to at least have a code that is written according to JLS requirements. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #6 from Timofey Basanov <timofey.basanov@gmail.com> 2011-07-06 15:46:13 CEST --- Yes, I'm using logback-classic. But, as far as I understand the bug is in slf4j-api module, not sure how could you workaround this through fixing logback-classic, as the problem arises when several threads call to LoggerFactory.getLogger with no dependence on actual StaticLoggerBinder implementation: Two thread simultaneously calls getLogger, and getILoggerFactory later. One of them sets INITIALIZATION_STATE = ONGOING_INITILIZATION and right after that another one gets TEMP factory. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #8 from Ceki Gulcu <listid@qos.ch> 2011-07-06 16:07:42 CEST --- Timofey, you are right to say that the problem arises when several threads call to LoggerFactory.getLogger. However, there is "some" dependence on actual StaticLoggerBinder implementation because initial configuration occurs within that first call. This is true for all backends performing auto-configuration on first use, e.g. log4j, logback and j.u.l. If auto-configuration were delegated to a different thread then SLF4J binding phase would take less time. This would in turn reduce the probability of creating tempLoggers. However, there is still no guarantee that no tempLoggers would be created. In fact delegating auto-configuration to a different thread might have little or no impact on the creating of tempLoggers, especially if the delegation process is itself comparatively long. At this time, I am just trying to understand the implications of different solutions. Addressing this problem in logback would help to keep SLF4J as dumb as possible but no dumber. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #9 from Gili <cowwoc@bbs.darktech.org> 2011-07-06 16:34:44 CEST --- Ceki, 1. Fixing this in slf4j is the only way to fix the problem for *all* implementations, not just logback. I understand that you want to keep slf4j as dumb as possible, but in this case I would argue that it's simply not possible. 2. Spawning separate threads for initialization is not guaranteed to fix the problem. It might work on one machine and fail on another due to race conditions. 3. According to JLS, variables accessed from different threads must be marked as volatile or accessed while holding a lock. This part of the fix must be in slf4j, not in logback. What do you think of Ryan's proposed fix? -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #11 from Ryan Cogswell <rcogswell@datasltn.com> 2011-07-06 21:18:09 CEST --- (In reply to comment #5)

I am considering to address this issue within logback-classic initialization. Ryan, Timofey, could you please confirm/infirm that you are both using logback-classic as the SLF4J back-end?

Yes, I am using logback-classic. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #19 from Jed Wesley-Smith <jed@atlassian.com> 2012-11-20 02:42:28 CET --- What is the status of this? If you want an alternative thread-safe initialisation that is not bespoke, we have a class that encapsulates lazy but thread-safe initialisation: https://bitbucket.org/atlassian/atlassian-util-concurrent/src/master/src/mai... Docs: https://bitbucket.org/atlassian/atlassian-util-concurrent/wiki/LazyReference... This class is Apache licensed. It has essentially no real dependencies and could easily be copied in to the slf4j source tree. -- Configure bugmail: http://bugzilla.slf4j.org/userprefs.cgi?tab=email ------- You are receiving this mail because: ------- You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 Simon Arlott <bugzilla.slf4j.simon@arlott.org> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |bugzilla.slf4j.simon@arlott | |.org --- Comment #20 from Simon Arlott <bugzilla.slf4j.simon@arlott.org> --- (In reply to comment #19)

What is the status of this? If you want an alternative thread-safe initialisation that is not bespoke, we have a class that encapsulates lazy but thread-safe initialisation:

The problem is that the logger initialisation process may try to log something via SLF4J. There are three scenarios for calling getILoggerFactory() during initialisation: 1. This is the thread that is doing the initialisation. 2. This is another thread that just wants to create a Logger. 3. This is another thread that the initialisation thread is blocked on (e.g. the logger factory initialises itself in another thread which then tries to log something). For scenario 1, we return a TEMP_FACTORY and everything is ok. For scenario 2, we should wait indefinitely for initialisation to complete or fail. For scenario 3, we need to return a TEMP_FACTORY or a deadlock will occur. One way to distinguish between 2 and 3 is to wait N seconds for initialisation to complete before giving up, but there is no good value for N (perhaps you're logging over NFS and the network is temporarily overloaded). Ideally all locking performed during logger factory initialisation would be performed with something like Guava's CycleDetectingLockFactory so that we could detect deadlocks, but that would impose a requirement on all of the logging frameworks (and not just the binding code). To resolve this bug, either: 1. Allow scenario 3 to cause a deadlock so that scenario 2 works. 2. Implement a long enough timeout before failing, to cover most environments. This could log warnings to System.err after a short period of time. 3. Return a proxy factory that uses a caching logger until initialisation is complete. All loggers obtained during concurrent initialisation will be less efficient. On servers with many CPUs this could potentially be a lot of static class loggers. 4. Find a VM independent mechanism for detecting a deadlock that doesn't require modifying code outside of the binding. Note that scenario 1 is unchanged. It must return a NOP factory (or the proxy factory if option 3 is used). MarkerFactory and MDC have a similar problem. MarkerFactory will throw a NullPointerException and MDC will throw an IllegalStateException. -- You are receiving this mail because: You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #22 from Simon Arlott <bugzilla.slf4j.simon@arlott.org> --- Created attachment 99 --> http://bugzilla.slf4j.org/attachment.cgi?id=99&action=edit Patch to fix the issue with a configurable 10 second timeout Detect deadlocks with a configurable timeout that defaults to 10 seconds. If the timeout occurs an exception will be thrown. -- You are receiving this mail because: You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #24 from James R. Perkins <jperkins@redhat.com> --- Created attachment 101 --> http://bugzilla.slf4j.org/attachment.cgi?id=101&action=edit Patch for thread-safety issues during binding The patch uses the same test previously attached. The implementation is slightly different than the other patch. I don't think the reentrancy checking should be necessary, but I don't know if other bindings actually invoke this method again. -- You are receiving this mail because: You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 James R. Perkins <jperkins@redhat.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |jperkins@redhat.com --- Comment #26 from James R. Perkins <jperkins@redhat.com> --- (In reply to comment #25)

(In reply to comment #24)

...

Created attachment 101 [details] Patch for thread-safety issues during binding

The patch uses the same test previously attached. The implementation is slightly different than the other patch. I don't think the reentrancy checking should be necessary, but I don't know if other bindings actually invoke this method again.

...

// If re-entrant, return the temp factory

You're making an assumption that it will be re-entrant using the same thread. There is no guarantee that this is the case. The binding may be calling arbitrary external code that blocks while it does some initialisation. This initialisation may be performed with multiple threads in parallel, and one of those threads may try to log something.

Sorry for the delayed comment, I just realized I wasn't added to the CC when adding a comment... ...anyway Yes, that is the assumption that's being made. If another thread is invoked from the initialization that attempts to run initialization again, then it will deadlock. That said, initialization probably shouldn't be doing that. If it just returned the TEMP_FACTORY we'd be back in a similar position. -- You are receiving this mail because: You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 Chetan Mehrotra <chetan.mehrotra@gmail.com> changed: What |Removed |Added ---------------------------------------------------------------------------- CC| |chetan.mehrotra@gmail.com --- Comment #27 from Chetan Mehrotra <chetan.mehrotra@gmail.com> --- With fix for issue 311 [1] the Loggers returned by SubstituteLoggerFactory would become functional again post initialization. Only the logger calls made during the initialization phase would be NOOP. So it might be simpler to just handle proper synchronization around the LoggerFactory INITIALIZATION_STATE management and continue with current approach of using the SubstituteLoggerFactory [1] http://bugzilla.slf4j.org/show_bug.cgi?id=311 -- You are receiving this mail because: You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #29 from Chetan Mehrotra <chetan.mehrotra@gmail.com> ---

FWIW the fix in fixSubstitutedLoggers() method isn't really thread-safe either.

As per current code flow it is thread safe. 'fixSubstitutedLoggers' is invoked *after* the INITIALIZATION_STATE is set to SUCCESSFUL_INITIALIZATION. So by the time it is invoked TEMP_FACTORY would not be in use and no further SubstituteLogegrs would be created. So the only downside is that only during the initialization phase some log calls would be NOOP and log output would be lost. Similar situtation occurs in Logback if the Logback config is reset and any log message arrives during that phase. If that also needs to be addressed then we can move just the SimpleLogger to slf4j-api module and use that in place of NOOP logger for the initial delegate in SubstituteLogger -- You are receiving this mail because: You are the assignee for the bug.

http://bugzilla.slf4j.org/show_bug.cgi?id=176 --- Comment #31 from Gili <cowwoc@bbs.darktech.org> --- 4 years later, I'd say: let's make it work first and optimize later. James is right: just make it thread-safe for now. -- You are receiving this mail because: You are the assignee for the bug.