LogcatAppender causes thread deadlock

[villel]

Following code causes deadlock when using the default LogcatAppender in logback-android. The root cause is in the AppenderBase parent class, where the doAppend() method is synchronized.

Simple fix is be to change the LogcatAppender base class from AppenderBase to UnsynchronizedAppenderBase which doesn't h block at doAppend() method. This should be safe, because android logcat doesn't need any external synchronization.

package example.logbackdeadlock;

import android.os.Handler;
import android.os.Message;
import android.support.v7.app.AppCompatActivity;
import android.os.Bundle;
import android.widget.TextView;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

import ch.qos.logback.classic.android.BasicLogcatConfigurator;

public class MainActivity extends AppCompatActivity {
    private static final Logger log = LoggerFactory.getLogger(MainActivity.class);

    static {
        BasicLogcatConfigurator.configureDefaultContext();
    }

    private TextView mT1Count;
    private TextView mT2Count;

    private final Handler mHandler = new Handler() {
        @Override
        public void handleMessage(Message msg) {
            switch (msg.what) {
            case 1:
                mT1Count.setText("T1: " + msg.arg1);
                break;
            case 2:
                mT2Count.setText("T2: " + msg.arg1);
                break;
            }
        }
    };

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        mT1Count = (TextView) findViewById(R.id.t1_count);
        mT2Count = (TextView) findViewById(R.id.t2_count);

        deadlock();
    }

    public static class A {
        private String mName;
        public synchronized String getName() {
            return mName;
        }
        public synchronized void setName(String name) {
            mName = name;
        }

        @Override
        public String toString() {
            return "My name is " + getName();
        }

        public synchronized void doStuff(int count) {
            log.debug("A is doing some synchronized stuff, count={}", count);
        }
    }

    void deadlock() {
        final A a = new A();
        a.setName("BAR");

        new Thread("T1") {
            @Override
            public void run() {
                log.info("Thread 1 start");
                int count = 0;
                while (true) {
                    mHandler.obtainMessage(1, count, 0).sendToTarget();
                    a.doStuff(++count);
                }
            }
        }.start();

        new Thread("T2") {
            @Override
            public void run() {
                log.info("Thread 2 start");
                int count = 0;
                while (true) {
                    mHandler.obtainMessage(2, count, 0).sendToTarget();
                    log.debug("T2 count={} a={}", ++count, a);
                }
            }
        }.start();
    }
}

Here are the relevant stack traces at deadlock:

"<11> T1" prio=5 waiting for monitor entry
java.lang.Thread.State: BLOCKED
at ch.qos.logback.core.AppenderBase.doAppend(Unknown Source:-1)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(Unknown Source:-1)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Unknown Source:-1)
at ch.qos.logback.classic.Logger.callAppenders(Unknown Source:-1)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Unknown Source:-1)
at ch.qos.logback.classic.Logger.filterAndLog_1(Unknown Source:-1)
at ch.qos.logback.classic.Logger.debug(Unknown Source:-1)
at example.logbackdeadlock.MainActivity$A.doStuff(MainActivity.java:63)
at example.logbackdeadlock.MainActivity$2.run(MainActivity.java:78)

"<12> T2" prio=5 waiting for monitor entry
java.lang.Thread.State: BLOCKED
at example.logbackdeadlock.MainActivity$A.getName(MainActivity.java:51)
at example.logbackdeadlock.MainActivity$A.toString(MainActivity.java:59)
at org.slf4j.helpers.MessageFormatter.safeObjectAppend(MessageFormatter.java:297)
at org.slf4j.helpers.MessageFormatter.deeplyAppendParameter(MessageFormatter.java:269)
at org.slf4j.helpers.MessageFormatter.arrayFormat(MessageFormatter.java:227)
at ch.qos.logback.classic.spi.LoggingEvent.getFormattedMessage(Unknown Source:-1)
at ch.qos.logback.classic.pattern.MessageConverter.convert(Unknown Source:-1)
at ch.qos.logback.classic.pattern.MessageConverter.convert(Unknown Source:-1)
at ch.qos.logback.core.pattern.FormattingConverter.write(Unknown Source:-1)
at ch.qos.logback.core.pattern.PatternLayoutBase.writeLoopOnConverters(Unknown Source:-1)
at ch.qos.logback.classic.PatternLayout.doLayout(Unknown Source:-1)
at ch.qos.logback.classic.PatternLayout.doLayout(Unknown Source:-1)
at ch.qos.logback.classic.android.LogcatAppender.append(Unknown Source:-1)
at ch.qos.logback.classic.android.LogcatAppender.append(Unknown Source:-1)
at ch.qos.logback.core.AppenderBase.doAppend(Unknown Source:-1)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(Unknown Source:-1)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Unknown Source:-1)
at ch.qos.logback.classic.Logger.callAppenders(Unknown Source:-1)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Unknown Source:-1)
at ch.qos.logback.classic.Logger.filterAndLog_2(Unknown Source:-1)
at ch.qos.logback.classic.Logger.debug(Unknown Source:-1)
at example.logbackdeadlock.MainActivity$3.run(MainActivity.java:90)

[tony19]

Great bug report 👍 I'll take a look

[villel]

Thank you for the quick fix. Any idea when it might be released?

[tony19]

Released in 1.1.1-5

[lock]

This thread has been automatically locked since there has not been any recent activity after it was closed. Please open a new issue for related bugs.