Hanging suspendResolver

[StefanLiebig]

Schema.execute( .. ) will not return from suspendResolver { .. } if the result size is big "enough". This behaviour starts with switching from 0.3.1 to 0.4.0. Kgraphql runs in Ktor 1.2.1. The suspendResolver { .. } is

fun SchemaBuilder<Unit>.timeEntry() {

    query("timeEntries") {
        suspendResolver { ctx: Context, year: Int?, month: Int?, userId: UserId?, topicFK: Int?, timeEntryTypeFK: Int? ->
            val range = dateRange(year, month)

            val result = transacted {
                selectTimeEntries(ctx.applicationContext(), ctx.applicationContext().userId(userId), range)
            }
                    .filterOn(topicFK != null) { it.topicFK == topicFK }
                    .filterOn(timeEntryTypeFK != null) { it.timeEntryTypeFK == timeEntryTypeFK }
            println(result)
            result
        }
    }
..

The result will be printed (for debugging) and but Schema.execute( .. ) will not return. When executing the test in debug mode and pausing execution the stacktrace looks like this:

park:-1, Unsafe (sun.misc)
parkNanos:215, LockSupport (java.util.concurrent.locks)
parkNanos:31, DefaultTimeSource (kotlinx.coroutines)
joinBlocking:83, BlockingCoroutine (kotlinx.coroutines)
runBlocking:54, BuildersKt__BuildersKt (kotlinx.coroutines)
runBlocking:1, BuildersKt (kotlinx.coroutines)
handleRequest:137, TestApplicationEngine (io.ktor.server.testing)
handleRequest:33, TestEngineKt (io.ktor.server.testing)
invoke:310, GraphQLTest$test get time entries$2 (timebox.graphql)
invoke:49, GraphQLTest$test get time entries$2 (timebox.graphql)
invoke:69, TestEngineKt$withTestApplication$1 (io.ktor.server.testing)
invoke:-1, TestEngineKt$withTestApplication$1 (io.ktor.server.testing)
withApplication:50, TestEngineKt (io.ktor.server.testing)
withApplication$default:44, TestEngineKt (io.ktor.server.testing)
withTestApplication:67, TestEngineKt (io.ktor.server.testing)
test get time entries:305, GraphQLTest (timebox.graphql)
invoke0:-1, NativeMethodAccessorImpl (sun.reflect)
invoke:62, NativeMethodAccessorImpl (sun.reflect)
invoke:43, DelegatingMethodAccessorImpl (sun.reflect)
invoke:498, Method (java.lang.reflect)
invokeMethod:628, ReflectionUtils (org.junit.platform.commons.util)
invoke:117, ExecutableInvoker (org.junit.jupiter.engine.execution)
lambda$invokeTestMethod$7:184, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
execute:-1, 165687172 (org.junit.jupiter.engine.descriptor.TestMethodTestDescriptor$$Lambda$287)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
invokeTestMethod:180, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
execute:127, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
execute:68, TestMethodTestDescriptor (org.junit.jupiter.engine.descriptor)
lambda$executeRecursively$5:135, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, 1278852808 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$176)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$7:125, NodeTestTask (org.junit.platform.engine.support.hierarchical)
invoke:-1, 9190301 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$175)
around:135, Node (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$8:123, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, 966544353 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$174)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
executeRecursively:122, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:80, NodeTestTask (org.junit.platform.engine.support.hierarchical)
accept:-1, 1444635922 (org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService$$Lambda$180)
forEach:1257, ArrayList (java.util)
invokeAll:38, SameThreadHierarchicalTestExecutorService (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$5:139, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, 1278852808 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$176)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$7:125, NodeTestTask (org.junit.platform.engine.support.hierarchical)
invoke:-1, 9190301 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$175)
around:135, Node (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$8:123, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, 966544353 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$174)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
executeRecursively:122, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:80, NodeTestTask (org.junit.platform.engine.support.hierarchical)
accept:-1, 1444635922 (org.junit.platform.engine.support.hierarchical.SameThreadHierarchicalTestExecutorService$$Lambda$180)
forEach:1257, ArrayList (java.util)
invokeAll:38, SameThreadHierarchicalTestExecutorService (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$5:139, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, 1278852808 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$176)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$7:125, NodeTestTask (org.junit.platform.engine.support.hierarchical)
invoke:-1, 9190301 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$175)
around:135, Node (org.junit.platform.engine.support.hierarchical)
lambda$executeRecursively$8:123, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:-1, 966544353 (org.junit.platform.engine.support.hierarchical.NodeTestTask$$Lambda$174)
execute:73, ThrowableCollector (org.junit.platform.engine.support.hierarchical)
executeRecursively:122, NodeTestTask (org.junit.platform.engine.support.hierarchical)
execute:80, NodeTestTask (org.junit.platform.engine.support.hierarchical)
submit:32, SameThreadHierarchicalTestExecutorService (org.junit.platform.engine.support.hierarchical)
execute:57, HierarchicalTestExecutor (org.junit.platform.engine.support.hierarchical)
execute:51, HierarchicalTestEngine (org.junit.platform.engine.support.hierarchical)
execute:229, DefaultLauncher (org.junit.platform.launcher.core)
lambda$execute$6:197, DefaultLauncher (org.junit.platform.launcher.core)
accept:-1, 319644606 (org.junit.platform.launcher.core.DefaultLauncher$$Lambda$135)
withInterceptedStreams:211, DefaultLauncher (org.junit.platform.launcher.core)
execute:191, DefaultLauncher (org.junit.platform.launcher.core)
execute:128, DefaultLauncher (org.junit.platform.launcher.core)
startRunnerWithArgs:69, JUnit5IdeaTestRunner (com.intellij.junit5)
startRunnerWithArgs:47, IdeaTestRunner$Repeater (com.intellij.rt.execution.junit)
prepareStreamsAndStart:242, JUnitStarter (com.intellij.rt.execution.junit)
main:70, JUnitStarter (com.intellij.rt.execution.junit)

If the data (result) returned from the selection is smaller the test passes. And it depends on the machine it is running on. And it also happens in production.

[jeggy]

I haven't been able to reproduce this error, it would be great to get to know more about your specific environment. What do transacted and selectTimeEntries do?

and how big is big enough?

[StefanLiebig]

Oh, this is really strange. In the meanwhile I have been updating exposed (org.jetbrains.exposed) to 0.15.1and the above transacted has become

suspend fun <T> transacted(statement: Transaction.() -> T): T =
        suspendedTransaction {  // org.jetbrains.exposed.sql.transactions.experimental.suspendedTransaction(..)
            statement()
        }

with this it does no longer fail! With the prior version of exposed which does not have the (experimental) suspendedTransaction the transactedwas

suspend fun <T> transacted(statement: Transaction.() -> T): T =
        withContext(Dispatchers.IO) {
            transaction {    // org.jetbrains.exposed.sql.transactions.transaction(..)
                statement()
            }
        }

selectTimeEntries just selected a bunch of time entries from the database (with exposed). A TimeEntry is a data class. What is big enough? If the result list from the select gets greater than 30-40 it fails (hangs).

This really puzzles me. I do not see where or why this can interfere. But it seems that it does.

Any idea?

(updated kraphql to 0.6.4 - looks good)

[AndreasVolkmann]

The issue is most likely due to ThreadLocal not working predictably in coroutines. Quote from their wiki:

Exposed store some values in thread-local variables while Coroutines could (and will) be executed in different threads.

In other words, Exposed did not yet support suspended transactions.

[StefanLiebig]

Yes, I know. This is the problem of exposed and JDBC which rely on ThreadLocals. And the stacktrace does not look like a problem with ThreadLocal.

However, the old version of the transacted function with the kgraphql (0.3.1) worked well. There must have been a change in kraphql that caused this effect. I do not say that this is an errror in kraphql.

Because the current versions of kotlin, ktor, exposed and kraphql work I propose to close the issue.

[jeggy]

I would love a failing unit test before closing this issue. I will try to replicate this while being on version 0.4.0 and create a unit test there.

[StefanLiebig]

Yes, understand that but keep in mind that our test was just technicaly a unit test. The test for that is an integration test which started MySQL and started a ktor server and than made a graphql request to it. So graphql sits "between" ktor and exposed which calls via JDBC MySQL.