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
package deadlock_test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Accessor {
private static Logger s_logger = LoggerFactory.getLogger(Accessor.class);
public void access(Worker worker) {
/** at some point, for any reason, this method decides to log the status of the worker object. */
s_logger.debug("Current worker status is: {}.", worker);
/**
* the following line would not cause the deadlock, because the thread never tries to acquire a lock on worker
* while already having a lock on the logger.
*/
s_logger.debug("Current worker status (not deadlocking) is: {}.", worker.toString());
}
}
package deadlock_test;
import static org.junit.Assert.assertFalse;
import org.junit.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class DeadlockTest {
private static Logger s_logger = LoggerFactory.getLogger(DeadlockTest.class);
@Test
public void deadlockTest() throws Exception {
s_logger.debug("Starting test.");
final Worker worker = new Worker();
final Thread workerThread = new Thread(new Runnable() {
public void run() {
worker.work();
}
});
workerThread.setName("WorkerThread");
final Thread accessorThread = new Thread(new Runnable() {
public void run() {
new Accessor().access(worker);
}
});
accessorThread.setName("AccessorThread");
workerThread.start();
accessorThread.start();
workerThread.join(5 * 1000);
assertFalse("Worker thread seems locked.", workerThread.isAlive());
}
}
package deadlock_test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
public class Worker {
private static Logger s_logger = LoggerFactory.getLogger(Worker.class);
private final Object m_lock = new Object();
public void work() {
// Locks the object to do some work changing internal status.
synchronized (m_lock) {
// Does some work...
try {
Thread.sleep(1 * 1000);
} catch (InterruptedException exc) {
//
}
// Then calls logger, while still holding the lock.
s_logger.debug("Did some work, result is: {}."/* ,... */);
}
}
public String getStatus() {
// Locks the object to make sure the status snapshot is coherent. (Will deadlock.)
synchronized (m_lock) {
// Packs some status information, e.g. in a StringBuffer.
final StringBuffer buf = new StringBuffer("STATUS");
// Returns the string.
return buf.toString();
}
}
@Override
public String toString() {
return getStatus();
}
}<?xml version="1.0" encoding="UTF-8"?>
<configuration>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<layout class="ch.qos.logback.classic.PatternLayout">
<param name="Pattern"
value="%relative %level [%thread] %logger{25} %message %nopex\n" />
</layout>
</appender>
<root>
<level value="DEBUG" />
<appender-ref ref="STDOUT" />
</root>
</configuration>_______________________________________________
Logback-user mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-user
