Registered GrpcExceptionHandler is not triggered in Kotlin service execution

[mckernant1]

Hello,

I am registering this exception handler in a configuration class like so

Exception handler configuration

import com.mckernant1.commons.logging.Slf4j.logger
import io.grpc.Status
import org.springframework.context.annotation.Bean
import org.springframework.context.annotation.Configuration
import org.springframework.grpc.server.exception.GrpcExceptionHandler
import org.springframework.security.authentication.BadCredentialsException

@Configuration
class GrpcCustomExceptionHandler {

    companion object {
        private val logger = logger()
    }

    @Bean
    fun genericExceptionHandler(): GrpcExceptionHandler {
        logger.info("Hit Exception")
        return GrpcExceptionHandler { e ->
            when (e) {
                is BadCredentialsException ->
                    Status.UNAUTHENTICATED
                        .withDescription(e.message)
                        .asException()

                else -> {
                    logger.error("Internal Error: ", e)
                    Status.INTERNAL
                        .withDescription("An unexpected error occurred")
                        .asException()
                }
            }
        }
    }

}

Service Code

I have also tested getting ObjectProvider<GrpcExceptionHandler> and List<ServerInterceptor> from the context in a request and ensured that my genericExceptionHandler and globalExceptionHandlerInterceptor are listed as classes in these lists.

The CompositeGrpcExceptionHandler appears to work as expected and prints the exception correctly.

import com.cacophony.AuthServiceGrpcKt
import com.cacophony.CreateUserRequest
import com.cacophony.CreateUserResponse
import com.cacophony.VerifyLoggedInRequest
import com.cacophony.VerifyLoggedInResponse
import com.cacophony.api.auth.TokenService
import com.mckernant1.commons.logging.Slf4j.logger
import io.grpc.ServerInterceptor
import org.springframework.beans.factory.ObjectProvider
import org.springframework.grpc.server.exception.CompositeGrpcExceptionHandler
import org.springframework.grpc.server.exception.GrpcExceptionHandler
import org.springframework.stereotype.Service

@Service
class AuthService(
    private val tokenService: TokenService,
    private val exceptionHandler: ObjectProvider<GrpcExceptionHandler>,
    private val interceptors: List<ServerInterceptor>
) : AuthServiceGrpcKt.AuthServiceCoroutineImplBase() {

    companion object {
        private val logger = logger()
    }

    override suspend fun verifyLoggedIn(request: VerifyLoggedInRequest): VerifyLoggedInResponse {
        val a = exceptionHandler
            .orderedStream()
            .toList()
            .toTypedArray()
        val c = CompositeGrpcExceptionHandler(*a)
        c.handleException(RuntimeException("asdf"))

        val i = interceptors.toList()

        i.forEach {
            logger.info("interceptor: ${it::class.simpleName}")
        }
        throw BadCredentialsException("Auth is null in the current context")
        return VerifyLoggedInResponse.getDefaultInstance()
    }

}

Debug logs

debug logs show both my genericExceptionHandler handler and the globalExceptionHandlerInterceptor being registered

[13:15:41.728] [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'genericExceptionHandler'

[13:15:41.747] [main] DEBUG org.springframework.beans.factory.support.DefaultListableBeanFactory - Creating shared instance of singleton bean 'globalExceptionHandlerInterceptor'

[16:19:59.395] [grpc-default-executor-0] DEBUG org.springframework.security.oauth2.server.resource.authentication.JwtAuthenticationProvider - Authenticated token
[16:19:59.463] [grpc-default-executor-1] DEBUG org.springframework.security.oauth2.server.resource.authentication.JwtAuthenticationProvider - Authenticated token
[16:19:59.497] [DefaultDispatcher-worker-2] ERROR com.cacophony.api.config.GrpcCustomExceptionHandler$Companion - Internal Error:
java.lang.RuntimeException: asdf
        at com.cacophony.api.grpc.service.AuthService.verifyLoggedIn$suspendImpl(AuthService.kt:41) [main/:?]
        at com.cacophony.api.grpc.service.AuthService.verifyLoggedIn(AuthService.kt) [main/:?]
        at com.cacophony.AuthServiceGrpcKt$AuthServiceCoroutineImplBase$bindService$2.invoke(AuthServiceOuterClassGrpcKt.kt:143) [main/:?]
        at com.cacophony.AuthServiceGrpcKt$AuthServiceCoroutineImplBase$bindService$2.invoke(AuthServiceOuterClassGrpcKt.kt:143) [main/:?]
        at io.grpc.kotlin.ServerCalls$unaryServerMethodDefinition$2$invoke$$inlined$map$1$2.emit(Emitters.kt:220) [grpc-kotlin-stub-1.4.3.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollectorKt$emitFun$1.invoke(SafeCollector.kt:11) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollectorKt$emitFun$1.invoke(SafeCollector.kt:11) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollector.emit(SafeCollector.kt:113) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollector.emit(SafeCollector.kt:82) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at io.grpc.kotlin.HelpersKt$singleOrStatusFlow$1$1.emit(Helpers.kt:65) [grpc-kotlin-stub-1.4.3.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollectorKt$emitFun$1.invoke(SafeCollector.kt:11) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollectorKt$emitFun$1.invoke(SafeCollector.kt:11) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollector.emit(SafeCollector.kt:113) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.internal.SafeCollector.emit(SafeCollector.kt:82) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at io.grpc.kotlin.ServerCalls$serverCallListener$requests$1.invokeSuspend(ServerCalls.kt:225) [grpc-kotlin-stub-1.4.3.jar:?]
        at io.grpc.kotlin.ServerCalls$serverCallListener$requests$1.invoke(ServerCalls.kt) [grpc-kotlin-stub-1.4.3.jar:?]
        at io.grpc.kotlin.ServerCalls$serverCallListener$requests$1.invoke(ServerCalls.kt) [grpc-kotlin-stub-1.4.3.jar:?]
        at kotlinx.coroutines.flow.SafeFlow.collectSafely(Builders.kt:57) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.AbstractFlow.collect(Flow.kt:226) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at io.grpc.kotlin.HelpersKt$singleOrStatusFlow$1.invokeSuspend(Helpers.kt:62) [grpc-kotlin-stub-1.4.3.jar:?]
        at io.grpc.kotlin.HelpersKt$singleOrStatusFlow$1.invoke(Helpers.kt) [grpc-kotlin-stub-1.4.3.jar:?]
        at io.grpc.kotlin.HelpersKt$singleOrStatusFlow$1.invoke(Helpers.kt) [grpc-kotlin-stub-1.4.3.jar:?]
        at kotlinx.coroutines.flow.SafeFlow.collectSafely(Builders.kt:57) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.flow.AbstractFlow.collect(Flow.kt:226) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at io.grpc.kotlin.ServerCalls$unaryServerMethodDefinition$2$invoke$$inlined$map$1.collect(SafeCollector.common.kt:112) [grpc-kotlin-stub-1.4.3.jar:?]
        at io.grpc.kotlin.ServerCalls$serverCallListener$rpcJob$1.invokeSuspend(ServerCalls.kt:240) [grpc-kotlin-stub-1.4.3.jar:?]
        at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) [kotlin-stdlib-1.8.22.jar:1.8.22-release-407(1.8.22)]
        at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.scheduling.CoroutineScheduler.runSafely(CoroutineScheduler.kt:584) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.executeTask(CoroutineScheduler.kt:811) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.runWorker(CoroutineScheduler.kt:715) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
        at kotlinx.coroutines.scheduling.CoroutineScheduler$Worker.run(CoroutineScheduler.kt:702) [kotlinx-coroutines-core-jvm-1.8.1.jar:?]
[16:19:59.501] [DefaultDispatcher-worker-2] INFO  com.cacophony.api.grpc.service.AuthService$Companion - interceptor: GrpcExceptionHandlerInterceptor
[16:19:59.501] [DefaultDispatcher-worker-2] INFO  com.cacophony.api.grpc.service.AuthService$Companion - interceptor: AuthenticationProcessInterceptor
[16:19:59.501] [DefaultDispatcher-worker-2] INFO  com.cacophony.api.grpc.service.AuthService$Companion - interceptor: ObservationGrpcServerInterceptor

I am running grpcurl against the api and keep getting this Error code unknown back.

grpcurl --plaintext \
                -H 'Authorization: Bearer <Token>' \
        localhost:9090 \
        com.cacophony.AuthService/VerifyLoggedIn
ERROR:
  Code: Unknown
  Message:

Let me know any troubleshooting advise that you have. Some additional debug logging would also be helpful around these interceptors and when they are triggered per request.

[mckernant1]

I believe this may be an issue with the grpc kotlin stub? going through the debugging it looks like my request is not being processed through the interceptors and being converted into an unknown here: https://github.com/grpc/grpc-kotlin/blob/master/stub/src/main/java/io/grpc/kotlin/ServerCalls.kt#L259

[dsyer]

There were also issues with the stubs generated by the Salesforce reactive gRPC plugin (#143). You could look at those to see if it matches. There might be a similar solution, but I don't know enough about Kotlin to help I'm afraid.

[genuss]

This one is propably a spring-grpc issue. Coroutine based servers work indeed a bit differently, however it doesn't stop https://github.com/grpc-ecosystem/grpc-spring from supporting exception handlers in coroutine servers. I'm not sure, but it might be related to the order of interceptors