Unexpected logs after lambda invocation

[miguelaferreira]

Issue description

We are getting unexpected log messages after each lambda invocation. I'm not sure of there's something wrong with our containers, or lambda configuration. I'm not even sure if it is expected and I should just find a way to exclude them. See bellow for the actual log messages

Versions:

• Micronaut 4.1.3
• Java 17
• Build as native binary on ghcr.io/graalvm/native-image-community:17

Micronaut dependencies

    annotationProcessor("io.micronaut:micronaut-graal")
    annotationProcessor("io.micronaut:micronaut-http-validation")
    annotationProcessor("io.micronaut.serde:micronaut-serde-processor")
    annotationProcessor("io.micronaut.serde:micronaut-serde-processor")
    annotationProcessor("io.micronaut.validation:micronaut-validation-processor")

    implementation("io.micronaut:micronaut-http-client")
    implementation("io.micronaut:micronaut-retry")
    implementation("io.micronaut.aws:micronaut-function-aws")
    implementation("io.micronaut.aws:micronaut-function-aws-custom-runtime")
    implementation("io.micronaut.aws:micronaut-aws-lambda-events-serde")
    implementation("io.micronaut.aws:micronaut-aws-sdk-v2")
    implementation("io.micronaut.aws:micronaut-aws-parameter-store")
    implementation("io.micronaut.validation:micronaut-validation")
    implementation("io.micronaut.crac:micronaut-crac")
    implementation("io.micronaut.email:micronaut-email-amazon-ses")
    implementation("io.micronaut.serde:micronaut-serde-jackson")
    implementation("io.micronaut:micronaut-jackson-databind")
    implementation("io.micronaut.reactor:micronaut-reactor")
    implementation("io.micronaut.discovery:micronaut-discovery-client")

While we have configured logs as JSON in logback, the unexpected log messages are not being printed as JSON objects.

Logback config:

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <withJansi>false</withJansi>
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <throwableConverter class="net.logstash.logback.stacktrace.ShortenedThrowableConverter">
                <maxDepthPerThrowable>30</maxDepthPerThrowable>
                <maxLength>4096</maxLength>
                <shortenedClassNameLength>20</shortenedClassNameLength>
                <exclude>io\.netty\.channel.*</exclude>
                <exclude>io\.netty\.util\.concurrent.*</exclude>
                <exclude>io\.netty\.handler\.codec.*</exclude>
                <exclude>io\.netty\.handler\.ssl.*</exclude>
                <exclude>io\.micronaut\.http\.netty\.stream.*</exclude>
                <exclude>reactor\.core\.publisher.*</exclude>
                <rootCauseFirst>true</rootCauseFirst>
                <inlineHash>true</inlineHash>
                <omitCommonFrames>true</omitCommonFrames>
            </throwableConverter>
        </encoder>
    </appender>

The logs

Unexpected message on HTTP2 connection channel: DefaultHttp2GoAwayFrame(errorCode=0, content=UnpooledSlicedByteBuf(ridx: 0, widx: 0, cap: 0/0, unwrapped: PooledUnsafeDirectByteBuf(ridx: 17, widx: 17, cap: 46)), extraStreamIds=0, lastStreamId=9)
Unexpected message on HTTP2 connection channel: DefaultHttp2GoAwayFrame(errorCode=0, content=UnpooledSlicedByteBuf(ridx: 0, widx: 0, cap: 0/0, unwrapped: PooledUnsafeDirectByteBuf(ridx: 17, widx: 17, cap: 46)), extraStreamIds=0, lastStreamId=9)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
at io.netty.handler.codec.http.HttpContentDecoder.channelInactive(HttpContentDecoder.java:235)
at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
at io.netty.handler.codec.MessageAggregator.channelInactive(MessageAggregator.java:441)
at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
at io.micronaut.http.client.netty.DefaultHttpClient$BaseHttpResponseHandler.channelInactive(DefaultHttpClient.java:2006)
Caused by: java.nio.channels.ClosedChannelException
... 7 more
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:102)
Suppressed: java.lang.Exception: #block terminated with an error
at com.gresb.notifications.FunctionLambdaRuntime.main(FunctionLambdaRuntime.java:21)
at com.gresb.notifications.FunctionLambdaRuntime.run(FunctionLambdaRuntime.java:36)
at io.micronaut.function.aws.runtime.AbstractMicronautLambdaRuntime.run(AbstractMicronautLambdaRuntime.java:156)
at io.micronaut.function.aws.runtime.AbstractMicronautLambdaRuntime.startRuntimeApiEventLoop(AbstractMicronautLambdaRuntime.java:381)
at io.micronaut.http.client.BlockingHttpClient.exchange(BlockingHttpClient.java:77)
at io.micronaut.http.client.netty.DefaultHttpClient$1.exchange(DefaultHttpClient.java:547)
at reactor.core.publisher.Flux.blockFirst(Flux.java:2704)
at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:100)
at reactor.core.Exceptions.propagate(Exceptions.java:408)
reactor.core.Exceptions$ReactiveException: java.nio.channels.ClosedChannelException
at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:813)
at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:301)
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:305)
at io.micronaut.http.client.netty.ConnectionManager$Pool$ConnectionHolder$3.channelInactive(ConnectionManager.java:1110)
at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:274)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:281)
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:303)
at io.netty.channel.CombinedChannelDuplexHandler.channelInactive(CombinedChannelDuplexHandler.java:221)
at io.netty.handler.codec.http.HttpClientCodec$Decoder.channelInactive(HttpClientCodec.java:329)
at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:376)
at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:411)
at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelInactive(CombinedChannelDuplexHandler.java:418)
Request loop failed with: java.nio.channels.ClosedChannelException
at org.graalvm.nativeimage.builder/com.oracle.svm.core.posix.thread.PosixPlatformThreads.pthreadStartRoutine(PosixPlatformThreads.java:210)
at org.graalvm.nativeimage.builder/com.oracle.svm.core.thread.PlatformThreads.threadStartRoutine(PlatformThreads.java:807)
at java.base@17.0.9/java.lang.Thread.run(Thread.java:840)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:596)
at io.netty.util.concurrent.SingleThreadEventExecutor.confirmShutdown(SingleThreadEventExecutor.java:763)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:375)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasksFrom(SingleThreadEventExecutor.java:426)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:167)
at io.netty.util.concurrent.AbstractEventExecutor.runTask(AbstractEventExecutor.java:174)
at io.netty.util.concurrent.PromiseTask.run(PromiseTask.java:106)
at io.netty.util.concurrent.PromiseTask.runTask(PromiseTask.java:98)
Sending HTTP POST to http://127.0.0.1:9001/2018-06-01/runtime/init/error

[miguelaferreira]

One other thing that we see sometimes happening in this function (and we can open a separate issue if that's better), is that we get read timeouts on the http client, while the requests still go through.

What we see in our telemetry is that the Micronaut http client throws a io.micronaut.http.client.exceptions.ReadTimeoutException in no more than a few milliseconds. However, the request is logged by the ALB that routes it to another system, that system processes the request and responds correctly (as logged by the system itself and the ALB). However, meanwhile the micronaut http client already produced a read timeout, so it does not get the response, and the monitoring picks this up as an issue to alert us on.

Flame graph for execution trace

ALB log for request

From the telemetry everything seems to be happening really fast and there would be no need to trigger a timeout. We are also no calling .block() at any moment, we are returning the http client response from our handler method (as seen in the class definition of the handler bellow), and letting Netty execute that.

public class FunctionRequestHandler extends MicronautRequestHandler<S3EventNotification, Mono<HttpResponse<String>>> {}