SpringBoot 2.5.0-RC1 NPE when activating netty access log and http2

I am on Spring Boot 2.5.0-RC1 with jdk 11 and hence the http2 support with netty is documented to be supported.

When activating the access log of netty while using http2 requests fail with a NPE.

application.yml

logging.level.reactor.netty.http.server.AccessLog: INFO
server.http2.enabled: true

build.gradle.kts

tasks.withType<BootRun> {
  jvmArgs = listOf("-Dreactor.netty.http.server.accessLogEnabled=true")
}

Problem

Running the application...

./gradlew bootRun

...starts up the application but on the first request:

2021-04-23 11:54:55.632 ERROR 24889 --- [or-http-epoll-3] o.s.w.s.adapter.HttpWebHandlerAdapter    : [cdc3650c-1] Error [java.lang.NullPointerException] for HTTP GET "/foo/bar?x=1", but ServerHttpResponse already committed (200 OK)
2021-04-23 11:54:55.638 ERROR 24889 --- [or-http-epoll-3] r.n.http.server.HttpServerOperations     : [id:cdc3650c-1, L:/127.0.0.1:8080 - R:/127.0.0.1:60818] Error finishing response. Closing connection

java.lang.NullPointerException: null
    at reactor.netty.http.server.logging.AccessLogHandlerH1.write(AccessLogHandlerH1.java:102) ~[reactor-netty-http-1.0.6.jar:1.0.6]
    Suppressed: reactor.core.publisher.FluxOnAssembly$OnAssemblyException: 
Error has been observed at the following site(s):
    |_ checkpoint ⇢ Handler com.example.FooController#bar(long, CurrentUser, Continuation) [DispatcherHandler]

So it seems that accessLogArgProvider in AccessLogHandlerH1 is null. In reactor.netty.http.server.logging there is a AccessLogHandlerH1 for http/1.1 and a AccessLogHandlerH2 for http2.

It seems like the H1 handler is used independently of activating http2 which might be the cause of the NPE and what I would consider a bug.

Notes

When removing either the jvmArgs or not enabling http2 the application works fine. The same problem occurs when using intellij run configurations.

Comment From: wilkinsona

Thanks for the report. This appears to be a bug in Reactor Netty. It can be reproduced with the following minimal application:

import reactor.core.publisher.Mono;
import reactor.netty.DisposableServer;
import reactor.netty.http.HttpProtocol;
import reactor.netty.http.server.HttpServer;

public class AccessLoggingApplication {

    public static void main(String[] args) {
        System.setProperty("reactor.netty.http.server.accessLogEnabled", "true");
        DisposableServer server = HttpServer.create().port(8080).protocol(HttpProtocol.HTTP11, HttpProtocol.H2C)
                .handle((request, response) -> response.sendString(Mono.just("hello"))).bindNow();
        server.onDispose().block();
    }

}

Making an HTTP/1.1 request to the server requests in a NullPointerException. An HTTP/2 request that assumes prior knowledge succeeds. Here's the failure:

java.lang.NullPointerException: null
    at reactor.netty.http.server.logging.AccessLogHandlerH1.write(AccessLogHandlerH1.java:102)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:709)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:792)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:702)
    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.write(CombinedChannelDuplexHandler.java:526)
    at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:110)
    at io.netty.channel.CombinedChannelDuplexHandler.write(CombinedChannelDuplexHandler.java:346)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:709)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:792)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:702)
    at reactor.netty.http.server.HttpTrafficHandler.write(HttpTrafficHandler.java:308)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:717)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWriteAndFlush(AbstractChannelHandlerContext.java:764)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:790)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:758)
    at io.netty.channel.AbstractChannelHandlerContext.writeAndFlush(AbstractChannelHandlerContext.java:808)
    at io.netty.channel.DefaultChannelPipeline.writeAndFlush(DefaultChannelPipeline.java:1025)
    at io.netty.channel.AbstractChannel.writeAndFlush(AbstractChannel.java:306)
    at reactor.netty.http.HttpOperations.lambda$send$0(HttpOperations.java:129)
    at reactor.core.publisher.FluxFlatMap.trySubscribeScalarMap(FluxFlatMap.java:152)
    at reactor.core.publisher.MonoFlatMap.subscribeOrReturn(MonoFlatMap.java:53)
    at reactor.core.publisher.Mono.subscribe(Mono.java:4135)
    at reactor.netty.NettyOutbound.subscribe(NettyOutbound.java:337)
    at reactor.core.publisher.MonoSource.subscribe(MonoSource.java:68)
    at reactor.netty.http.server.HttpServer$HttpServerHandle.onStateChange(HttpServer.java:915)
    at reactor.netty.transport.ServerTransport$ChildObserver.onStateChange(ServerTransport.java:478)
    at reactor.netty.http.server.HttpServerOperations.onInboundNext(HttpServerOperations.java:526)
    at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:94)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at reactor.netty.http.server.HttpTrafficHandler.channelRead(HttpTrafficHandler.java:209)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:103)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
    at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at reactor.netty.http.server.logging.AccessLogHandlerH1.channelRead(AccessLogHandlerH1.java:59)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.codec.ByteToMessageDecoder.handlerRemoved(ByteToMessageDecoder.java:253)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:515)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:447)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:276)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

I've opened https://github.com/reactor/reactor-netty/issues/1610.