Deadlock when withContext() is combined with logging in object initializer

Question

Consider the following Kotlin object:

package com.example

import org.slf4j.LoggerFactory
import java.lang.Thread.currentThread
import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.runBlocking
import kotlinx.coroutines.withContext

object Object {
    private val log = LoggerFactory.getLogger(Object::class.java)

    init {
        runBlocking {
            log.info("[${currentThread().name}] Object initializing")
            withContext(Dispatchers.IO) {
                log.info("[${currentThread().name}] Object initialized")
            }
        }
    }

    fun f() = Unit
}

As you can see, inside the initializer, there's a logging event happening inside the withContext() block (the actual dispatcher can be any, but let's use Dispatchers.IO backed by the fork-join pool).

Now, if I try to access the object (Object.f()) from an outside code (e.g.: my main()), the initializer block hangs at withContext(), logging only the 1st message out of the two:

11:54:21.401 [main] INFO com.example.Object -- [main] Object initializing

— and the stack trace of the thread that is currently running the coroutine is as follows:

"DefaultDispatcher-worker-1" #24 daemon prio=5 os_prio=0 cpu=0.00ms elapsed=423.27s tid=0x000002357a6980b0 nid=0x6c90 in Object.wait()  [0x000000d4cc1ff000]
   java.lang.Thread.State: RUNNABLE
    at com.example.Object$1$1.invokeSuspend(Object.kt:16)
    - waiting on the Class initialization monitor for com.example.Object
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:108)
    at kotlinx.coroutines.internal.LimitedDispatcher$Worker.run(LimitedDispatcher.kt:115)
    at kotlinx.coroutines.scheduling.TaskImpl.run(Tasks.kt:103)
    at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:793)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:697)
    at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:684)

Interestingly, if I replace inner logging with a plain println() call, the deadlock goes away, so it has something to do with LoggerFactory.getLogger() call while the object is only partially initialized.

If I choose to log a message at some point in the future, the deadlock goes away, too:

    init {
        GlobalScope.launch(Dispatchers.IO) {
            log.info("[${currentThread().name}] Object initialized")
        }
    }

But why is the deadlock happening in the 1st place?

Answer 1

This has nothing to do with the logging, for me println() exhibits the same behavior. Even an empty withContext(Dispatchers.IO) block triggers the problem. Instead, the problem is most likely due to the timing when you create the coroutine.

The initializer of Object is called when an instance is needed. Object is declared as an object (not a class), meaning it is statically instantiated when the runtime loads your code. The init block is therefore executed before your app code is fully set up and before the entry point of your app was even called. Depending on the circumstances it might even be executed before other static initializers. It is conceivable that not everything of the coroutine framework is already fully set up at this point, leading to an inconsistent state that may result in the deadlock you observe.

Long story short: An object initializer is the wrong place to execute a heavy load. This should be done after the entry point of your app was reached so you can rely on the environment to be in a consistent state.

You can use class instead of object or lazily initialize the object when it is first accessed. What fits best depends on how the object is used and what the initialization actually does.

Answer 2

Here's the full code I used to test your scenario:

import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.runBlocking
import kotlinx.coroutines.withContext
import org.slf4j.LoggerFactory
import java.lang.Thread.currentThread

fun main() {
    Object.f()
}

object Object {
    private val log = LoggerFactory.getLogger(Object::class.java)

    init {
        runBlocking {
            log.info("[${currentThread().name}] Object initializing")
            withContext(Dispatchers.IO) {
                log.info("[${currentThread().name}] Object initialized")
            }
        }
    }

    fun f() = Unit
}

It hangs. Now, we make this minimal change: move private val log one line up, outside object scope:

package org.mtopol

import kotlinx.coroutines.Dispatchers
import kotlinx.coroutines.runBlocking
import kotlinx.coroutines.withContext
import org.slf4j.LoggerFactory
import java.lang.Thread.currentThread

fun main() {
    Object.f()
}

private val log = LoggerFactory.getLogger(Object::class.java)

object Object {

    init {
        runBlocking {
            log.info("[${currentThread().name}] Object initializing")
            withContext(Dispatchers.IO) {
                log.info("[${currentThread().name}] Object initialized")
            }
        }
    }

    fun f() = Unit
}

Now it no longer hangs.

Explanation

Your code hanged because log is an instance field of the Object singleton. The way the code is written, a thread in the IO pool must access it (log.info() call). However, the main thread, currently initializing the backing Object class, is blocked waiting for the IO thread to complete. Class initialization cannot happen in parallel on multiple threads; this is ensured by guarding the class init code with a lock.

Therefore, the IO thread is trying to acquire the lock that the main thread is holding, while the main thread is waiting on the IO thread to complete the task. Deadlock.

After my change, private val log is no longer an instance field; it is now a class field in the class holding the top-level declarations, in my case the TestingKt class. Now the IO thread can access log without a deadlock.