Ah I see, I hadn't looked at your code closely enough so failed to realise
it was your toString() implementation that was grabbing the lock, rather
than Logback itself. That makes a lot more sense of course!
I don't think there's any solution from your side other than to rework the
locking or call worker.toString() yourself, as you have indicated.
So yes I agree with your conclusion, Logback should be evaluating the toString()
call before it grabs any internal locks. This should solve the problem plus
potentially improve performance of Logback when multiple threads are writing,
without any obvious downside. After a quick glance at the Logback code though
this may not be a straightforward change, since the worker object gets treated
as an Object/Object[] until right at the last minute.
Hi,
Thank you for your reply.
I agree with your comments on synchronization best practices. I simply
produced a toy example to illustrate the problem I am encountering in
my application, but the code is not the one I use in my application. I
now changed the example to lock on a private lock object (hereby
attached). I also added a logback-test.xml file because the problem
only happen if logback indeed logs debug statements, so the
configuration file is needed to reproduce the problem. Also the
"final" on StringBuilder has indeed nothing to do with
synchronization, it is simply my habit of always declaring my
variables final when I don't need to change them after creation, for
code self-documentation and auto-verification purposes.
I also agree on the fact that the deadlock happens because of two
different orders in locking. One thread ("WorkerThread") locks the
worker, then wants to acquire a lock on the logger, while the other
one ("AccessorThread") first locks the logger, and while holding the
lock, tries to acquire a lock on the worker object.
But the problem is not solved by replacing the lock on the worker
object itself by a lock on an internal lock: the same mechanisms still
take place. The logger calls, in its internal routine,
worker.getStatus(), which tries to lock the worker internal lock.
Impossible as an other thread already holds the lock on the worker
internal lock (because it is being executing the very same method!).
Please also note that logback does not really decide to lock the
worker object. It just calls worker.toString(), as is expected from
the logging statement ("s_logger.debug("Current worker status is:
{}.", worker);"). And this method transparently locks the worker lock.
The more I think about it, the more I feel that the problem comes from
the fact that, AFAIU, logback does not release the lock on its
internal (shared) logger before calling a method on a not controlled,
externally-provided, potentially shared, object (i.e., worker). Would
logback 1) call worker.toString(), producing a String, and 2) acquire
the lock and print the string, then the deadlock would not happen. As
is illustrated by the fact that replacing the above logging statement
by the apparently very similar "s_logger.debug("Current worker status
(not deadlocking) is: {}.", worker.toString());" does not trigger the
deadlock any more.
I would still be very interested by any proposal to change the
attached demonstration code to avoid triggering the deadlock (other
than systematically releasing any internal lock before issuing any
logging statement, which I hope is not the only solution because not
very convenient).
Once again thank you for your comments.
Olivier
Chris Miller a écrit :
What's happening here, as I guess you're aware, is that multiple
locks are not being aquired in the same fixed order globally - a
situation prone to deadlocking. But on top of that, Logback is
unintentially executing a denial-of-service attack on your app by
locking the Worker instance. The reason this can happen is because
your Worker code is synchronizing on the Worker object itself. That
object is exposed to the outside world and therefore you have no
control over who else can lock on it and therefore no way to prevent
possible deadlocks or a plain denial-of-service.
Best practices is to never use "synchronized(this) { ... }" or
synchronize entire methods (which amounts to the same thing) in your
code. Instead your Worker class should have a private lock object of
its own that you synchronize on. This makes the lock object
inaccessible to the outside world and therefore impossible (without
malicious reflection at least!) to cause a denial-of-service
situation like you are experiencing.
eg:
public class Worker {
private static final Logger logger =
LoggerFactory.getLogger(Worker.class);
private final Object LOCK = new Object();
public void work() {
synchronized(LOCK) {
...
logger.info("Did some work...");
}
...
}
Note that the 'final' is essential for the LOCK object declaration
(and really for the logger variable too). Without final, you risk
different threads locking on different objects and visibility issues
between threads. In your implementation of getStatus() { ... } you
declare a final StringBuffer though - I guess you're aware that
doesn't have any impact on the threadsafety of your code?
Dear list,
I recently had a deadlock problem related to logging and I am
wondering if it comes from a problem in the logging framework (I
must say I doubt it) or from the way I use logging, in which case
I'd like to hear advices about how others avoid this kind of
problems.
The pattern is the following. (Please see hereby the java classes
which
might be clearer.)
- In a class "Worker", a method "work()" locks the object instance
of
the class Worker to do some work and calls the logging framework to
print the result (while still holding the lock).
- In the same class "Worker", an other method "getStatus()" obtains
the
current status of the object instance of the class Worker and
returns
it
as a String (method used for logging). That method locks the object
at
some point to make sure it reads consistent internal status
information.
- In an other class "Accessor", a method "access()" performs some
work
(not locking anything), then logs the status of an object of the
class
Worker by using its getStatus() method.
Now the deadlock scenario is the following.
- A thread "WorkerThread" is executing the method "work()". It has
acquired the lock for the Worker object and has not reached the
logging
statement yet.
- An other thread "AccessorThread" is executing the method
"access()",
and is executing the logging statement.
AFAIU, logback console logger has some sort of "central" locking
point:
when a thread is logging, an other thread may not log in parallel
(that
seems good as the user does not want his different logging
statements
to
be mixed together)... Thus, the following happens.
- AccessorThread has a lock to the Logger, and waits to acquire the
Worker lock to execute the synchronized block in getStatus().
- WorkerThread is holding that precise lock, and will never release
it,
because arriving at the logging statement in "work()", it starts
waiting
for the Logger lock acquired by AccessorThread. These two threads
are
caught in a deadlock.
I feel the problem comes from not respecting the general rule that a
block of code holding a lock should not call a method on an
externally
controlled object (possibly shared with other threads) whose locking
behavior is unknown. (Note that both my code and the logging
framework
do not respect this rule, AFAIK.) So I should not have issued the
log
statement in my synchronized block in "work()". In my case, I can
remove this logging statement from the synchronized block, but it is
not clear to me whether it is always possible (or easy) to do so,
especially if the thing you want to log depends on an internal state
which might change as soon as you release the lock.
An other way to solve that problem is to not use the parametrized
message system in SLF4J. Indeed, it would disable the possibility of
the AccessorThread to try to acquire the lock on Worker while being
in the SLF4J method.
I am wondering however if there is not a way that slf4j
implementation (logback) release the lock on its logger, then gets
the Worker lock, then re-acquire the lock on its logger only after
having released the Worker lock, so that it has only one lock at a
time? I tend to think that it would enable a user of the logging
framework to pay no attention of the deadlock possibilities incurred
by the logging framework, and to avoid him introducing subtle bugs
with logging statements... But I may be wrong and I am not an expert
in multithread programming.
More generally speaking, what would be the advices from experienced
programmers to avoid this problem? How do you log in a
multithreading context?
Also I am wondering if that (anti-)pattern could be documented on
the logback page, to avoid others to do the same mistake as me? Or
even on the SLF4J page, if it is not logback-specific?
The attached classes provide a test case showing the deadlock
scenario. The test fails reliably on my box.
Thank you for any help.
Olivier
_______________________________________________
Logback-user mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-user
_______________________________________________
Logback-user mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-user
