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
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 internal worker object.
s_logger.info("Current worker status is: {}.", worker);
}
}
package deadlock_test;
import static org.junit.Assert.*;
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 testname() throws Exception {
s_logger.info("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(100*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);
public void work() {
// Locks the object to do some work changing internal status.
synchronized (this) {
// Does some work...
try {
Thread.sleep(1*1000);
} catch (InterruptedException exc) {
//
}
// Then calls logger, while still holding the lock.
s_logger.info("Did some work, result is: {}."/*,...*/);
}
}
public String getStatus() {
// Locks the object to make sure the status snapshot is coherent. (Will deadlock.)
synchronized (this) {
// 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();
}
}_______________________________________________
Logback-user mailing list
[email protected]
http://qos.ch/mailman/listinfo/logback-user
