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

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?

Solution

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.