Ktor: Exception in Route.handle is handled silently

[spand]

Unhandled exceptions are usually printed (afaik) but the IllegalArgumentException here isnt. My guess would be it should always be printed.

class Blocking(environment: ApplicationEnvironment) : Application(environment) {
    init {
        routing {
            method(HttpMethod.Post){
                route("/exception") {
                    handle {
                        println("exception")
                        throw IllegalArgumentException()
                    }
                }
                route("/exception2") {
                    handle {
                        println("exception2")
                        subject.respondWrite {
                            throw IllegalArgumentException()
                        }
                    }
                }
            }
        }
    }
}

class ExceptionEater {

    @Test
    fun foo(){
        val port = 44003
        val appHostConfig = applicationHostConfig { connector { this.port = port } }
        val appEnv = BasicApplicationEnvironment(javaClass.classLoader, SLF4JApplicationLog("KTorTest"), MapApplicationConfig(
                "ktor.application.class" to Blocking::class.qualifiedName!!
        ))
        val jetty = JettyApplicationHost(appHostConfig, appEnv)
        jetty.start()
        val paths = listOf("exception", "exception2")
        val e = Executors.newCachedThreadPool()
        paths.map { path ->
            e.submit(Callable {
                val c = URL("http://localhost:$port/$path").openConnection() as HttpURLConnection
                c.doOutput = true
                c.outputStream.apply {
                    write("Foo".toByteArray(StandardCharsets.UTF_8))
                    flush()
                }
                c.inputStream.bufferedReader().readLine().apply {
                    println("Done")
                }
            })
        }

        TimeUnit.SECONDS.sleep(10)
    }
}

[cy6erGn0m]

You can install CallLogger feature to see exceptions

class Blocking(environment: ApplicationEnvironment) : Application(environment) {
    init {
        install(CallLogging)

        routing {

[kyegupov]

CallLogger currently does not work as it should: https://github.com/Kotlin/ktor/issues/50

On top of that, swallowing exceptions silently by default is a very bad practice, resulting in an incredibly hostile learning curve.

Perhaps tutorial-mode setups like embeddedJettyServer(routing = ...).start() should have it baked in by default, with logging to stdout/stderr preconfigured?

[orangy]

It's not that we swallow exceptions by default, as you picture it. Highly async code is hard to make bullet-proof, but we are moving there. Missing a catch-and-marshall in one place can easily look like swallowing, but it's actually may be accidentally ignored in CompletableFuture callback or something.

[spand]

I think my confusion about this is now a little bit clearer. I did not know we had calllogging in our setup so I thought it was the default behaviour. In any case exceptions are actually being swallowed here. If you add install(CallLogging) it will only print one stack trace to the console. The first in route /exception is not being reported.

[orangy]

@spand I've reproduced the issue, but I see it not reported for exception2. Exception for exception route is reported if CallLogging is installed.

[orangy]

So indeed, it's not a swallowed exception. It's a double-exception error. It hits CallLogging interceptor with correct exception on a failing path. But then CallLogging tries to get method from an HttpRequest to show which request failed, and fails to get it, because request is already closed.

Thanks for noticing, we will fix it.

[orangy]

Just a matter of notice, we have a test for this case (throwing inside respondWrite), but it didn't fail because in test environment it was not "asynchronous enough". Need proper integration test…

[spand]

Oh, my mistake again. Glad to be of service in any case ;-)

[kyegupov]

I have a feeling the async core of ktor is going to be a nightmare to maintain, so it's unlikely for ktor to be production-ready anytime soon :( shame, since Kara development appears to be mostly dormant and Wasabi is also quite unstable (Gradle builds, ugh).

[spand]

Any progress on this ?

[orangy]

Debug note:
This is caused by https://github.com/Kotlin/ktor/blob/7f72bd3fcf7d53d289a3252dcac39a5300db413a/ktor-hosts/ktor-hosts-common/src/org/jetbrains/ktor/host/BaseApplicationCall.kt#L115-L115

closeAtEnd in sendAsyncChannel installs failure handler to properly close a call in case of failure or success, and it executes before CallLogging have a chance to report an exception. Then call.request.logInfo() fails because underlying request was already cleaned up.

[orangy]

I verified this case in our new coroutine-based implementation and everything is good (given CallLogging is installed)