Http2MultiplexCodec demo for cleartext HTTP/2 between a server and a client (Netty 4.1.22)

MultiplexCodecCleartextHttp2Test.java

package org.xbib.netty.http.server.test.simple;

import io.netty.bootstrap.Bootstrap;
import io.netty.bootstrap.ServerBootstrap;
import io.netty.buffer.ByteBuf;
import io.netty.channel.Channel;
import io.netty.channel.ChannelHandlerContext;
import io.netty.channel.ChannelInboundHandlerAdapter;
import io.netty.channel.ChannelInitializer;
import io.netty.channel.ChannelPipeline;
import io.netty.channel.ChannelPromise;
import io.netty.channel.EventLoopGroup;
import io.netty.channel.SimpleChannelInboundHandler;
import io.netty.channel.nio.NioEventLoopGroup;
import io.netty.channel.socket.nio.NioServerSocketChannel;
import io.netty.channel.socket.nio.NioSocketChannel;
import io.netty.handler.codec.http.DefaultFullHttpResponse;
import io.netty.handler.codec.http.FullHttpRequest;
import io.netty.handler.codec.http.FullHttpResponse;
import io.netty.handler.codec.http.HttpMethod;
import io.netty.handler.codec.http.HttpObjectAggregator;
import io.netty.handler.codec.http.HttpResponseStatus;
import io.netty.handler.codec.http.HttpServerCodec;
import io.netty.handler.codec.http.HttpServerUpgradeHandler;
import io.netty.handler.codec.http.HttpVersion;
import io.netty.handler.codec.http2.CleartextHttp2ServerUpgradeHandler;
import io.netty.handler.codec.http2.DefaultHttp2Headers;
import io.netty.handler.codec.http2.DefaultHttp2HeadersFrame;
import io.netty.handler.codec.http2.Http2CodecUtil;
import io.netty.handler.codec.http2.Http2ConnectionPrefaceAndSettingsFrameWrittenEvent;
import io.netty.handler.codec.http2.Http2FrameLogger;
import io.netty.handler.codec.http2.Http2Headers;
import io.netty.handler.codec.http2.Http2MultiplexCodec;
import io.netty.handler.codec.http2.Http2MultiplexCodecBuilder;
import io.netty.handler.codec.http2.Http2ServerUpgradeCodec;
import io.netty.handler.codec.http2.Http2Settings;
import io.netty.handler.codec.http2.Http2StreamChannel;
import io.netty.handler.codec.http2.Http2StreamChannelBootstrap;
import io.netty.handler.codec.http2.Http2StreamFrameToHttpObjectCodec;
import io.netty.handler.logging.LogLevel;
import io.netty.handler.logging.LoggingHandler;
import io.netty.util.AsciiString;
import org.junit.Test;

import java.net.InetSocketAddress;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.TimeUnit;
import java.util.logging.ConsoleHandler;
import java.util.logging.Handler;
import java.util.logging.Level;
import java.util.logging.LogManager;
import java.util.logging.Logger;
import java.util.logging.SimpleFormatter;

/**
 *
 * Http2MultiplexCodec demo for cleartext HTTP/2 between a server and a client.
 *
 * What is HTTP/2 multiplex codec?
 *
 * codec-http2 currently has two flavors of APIs:
 *
 * <ul>
 *     <li>Http2ConnectionHandler and FrameListener - the initial API, lots of hours/usage on this code,
 * low object allocation, not canonical Netty design (extensibility via the channel pipeline is challenging)</li>
 *     <li>Http2FrameCodec and Http2MultiplexCodec - new API design which is more canonical Netty,
 *     more object allocation, not as much hours/usage. The FrameListener API exposure is minimized
 *     from the Http2MultiplexCodec and ideally its usage of the FrameListener is an implementation detail.</li>
 * </ul>
 *
 *
 */
public class MultiplexCodecCleartextHttp2Test {

    private static final Logger clientLogger = Logger.getLogger("client");
    private static final Logger serverLogger = Logger.getLogger("server");

    static {
        System.setProperty("io.netty.noUnsafe", Boolean.toString(true));
        System.setProperty("io.netty.noKeySetOptimization", Boolean.toString(true));
        System.setProperty("io.netty.recycler.maxCapacity", Integer.toString(0));
        System.setProperty("io.netty.leakDetection.level", "paranoid");

        // expand Java logging to full level
        System.setProperty("java.util.logging.SimpleFormatter.format",
                "%1$tY-%1$tm-%1$td %1$tH:%1$tM:%1$tS.%1$tL %4$-7s [%3$s] %2$s %5$s %6$s%n");
        LogManager.getLogManager().reset();
        Logger rootLogger = LogManager.getLogManager().getLogger("");
        Handler handler = new ConsoleHandler();
        handler.setFormatter(new SimpleFormatter());
        rootLogger.addHandler(handler);
        rootLogger.setLevel(Level.ALL);
        for (Handler h : rootLogger.getHandlers()) {
            handler.setFormatter(new SimpleFormatter());
            h.setLevel(Level.ALL);
        }
    }

    private final InetSocketAddress inetSocketAddress = new InetSocketAddress("localhost", 8443);

    private final CompletableFuture<Boolean> settingsPrefaceFuture = new CompletableFuture<>();

    private final CompletableFuture<Boolean> responseFuture = new CompletableFuture<>();

    @Test
    public void testMultiplexHttp2() throws Exception {

        Http2FrameLogger serverFrameLogger = new Http2FrameLogger(LogLevel.INFO, "server");
        Http2FrameLogger clientFrameLogger = new Http2FrameLogger(LogLevel.INFO, "client");

        EventLoopGroup serverEventLoopGroup = new NioEventLoopGroup();
        EventLoopGroup clientEventLoopGroup = new NioEventLoopGroup();

        try {
            ServerBootstrap serverBootstrap = new ServerBootstrap()
                .group(serverEventLoopGroup)
                .channel(NioServerSocketChannel.class)
                .handler(serverFrameLogger)
                .childHandler(new ChannelInitializer<Channel>() {
                    @Override
                    protected void initChannel(Channel ch) {
                        ChannelPipeline p = ch.pipeline();
                        Http2MultiplexCodec serverMultiplexCodec = Http2MultiplexCodecBuilder.forServer(new ChannelInitializer<Channel>() {
                                @Override
                                protected void initChannel(Channel channel) {
                                    ChannelPipeline p = channel.pipeline();
                                    p.addLast("multiplex-server-traffic", new TrafficLoggingHandler("multiplex-server-traffic", LogLevel.INFO));
                                    p.addLast("multiplex-server-frame-converter", new Http2StreamFrameToHttpObjectCodec(true));
                                    p.addLast("multiplex-server-chunk-aggregator", new HttpObjectAggregator(1048576));
                                    p.addLast("multiplex-server-request-handler", new ServerRequestHandler());
                                }
                            })
                            .initialSettings(Http2Settings.defaultSettings())
                            .frameLogger(serverFrameLogger)
                            .build();
                        HttpServerUpgradeHandler.UpgradeCodecFactory upgradeCodecFactory = protocol -> {
                            if (AsciiString.contentEquals(Http2CodecUtil.HTTP_UPGRADE_PROTOCOL_NAME, protocol)) {
                                return new Http2ServerUpgradeCodec("server-codec", serverMultiplexCodec);
                            } else {
                                return null;
                            }
                        };
                        HttpServerCodec sourceCodec = new HttpServerCodec();
                        HttpServerUpgradeHandler upgradeHandler = new HttpServerUpgradeHandler(sourceCodec, upgradeCodecFactory);
                        CleartextHttp2ServerUpgradeHandler cleartextHttp2ServerUpgradeHandler =
                                new CleartextHttp2ServerUpgradeHandler(sourceCodec, upgradeHandler, serverMultiplexCodec);
                        p.addLast("server-traffic", new TrafficLoggingHandler("server-traffic", LogLevel.INFO));
                        p.addLast("server-upgrade", cleartextHttp2ServerUpgradeHandler);
                        p.addLast("server-messages", new ServerMessages());
                    }
                });
            Channel serverChannel = serverBootstrap.bind(inetSocketAddress).sync().channel();
            serverLogger.log(Level.INFO, "server up, channel = " + serverChannel);

            Http2MultiplexCodec clientMultiplexCodec = Http2MultiplexCodecBuilder.forClient(new ChannelInitializer<Channel>() {
                    @Override
                    protected void initChannel(Channel ch) {
                        // unused
                        throw new IllegalStateException();
                    }
                })
                .initialSettings(Http2Settings.defaultSettings())
                .frameLogger(clientFrameLogger)
                .build();
            Bootstrap clientBootstrap = new Bootstrap()
                .group(clientEventLoopGroup)
                .channel(NioSocketChannel.class)
                .handler(new ChannelInitializer<Channel>() {
                    @Override
                    protected void initChannel(Channel ch) {
                        ChannelPipeline p = ch.pipeline();
                        p.addLast("client-traffic", new TrafficLoggingHandler("client-traffic", LogLevel.INFO));
                        p.addLast("client-codec", clientMultiplexCodec);
                        p.addLast("client-messages", new ClientMessages());
                    }
                });
            Channel clientChannel = clientBootstrap.connect(inetSocketAddress).sync().channel();
            clientLogger.log(Level.INFO, "client connected, channel = " + clientChannel);

            settingsPrefaceFuture.get(10L, TimeUnit.SECONDS);
            if (!settingsPrefaceFuture.isDone()) {
                throw new RuntimeException("no settings and preface written, unable to continue");
            } else {
                clientLogger.log(Level.INFO, "settings and preface written");
            }
            // after settings/preface event, start child channel write
            Http2StreamChannel childChannel = new Http2StreamChannelBootstrap(clientChannel)
                .handler(new ChannelInitializer<Channel>() {
                     @Override
                     protected void initChannel(Channel ch)  {
                         ChannelPipeline p = ch.pipeline();
                         p.addLast("child-client-traffic", new TrafficLoggingHandler("child-client-traffic", LogLevel.INFO));
                         p.addLast("child-client-frame-converter", new Http2StreamFrameToHttpObjectCodec(false));
                         p.addLast("child-client-chunk-aggregator", new HttpObjectAggregator(1048576));
                         p.addLast("child-client-response-handler", new ClientResponseHandler());
                     }
                 }).open().syncUninterruptibly().getNow();
            Http2Headers request = new DefaultHttp2Headers().method(HttpMethod.GET.asciiName())
                    .path("/foobar")
                    .scheme("http")
                    .authority(inetSocketAddress.getHostName());
            childChannel.writeAndFlush(new DefaultHttp2HeadersFrame(request, true));
            clientLogger.log(Level.INFO, "waiting max. 10 seconds");
            responseFuture.get(10, TimeUnit.SECONDS);
            if (responseFuture.isDone()) {
                clientLogger.log(Level.INFO, "done!");
            }
        } finally {
            clientEventLoopGroup.shutdownGracefully();
            serverEventLoopGroup.shutdownGracefully();
            clientEventLoopGroup.awaitTermination(5, TimeUnit.SECONDS);
            clientLogger.log(Level.INFO, "client shutdown");
            serverEventLoopGroup.awaitTermination(5, TimeUnit.SECONDS);
            serverLogger.log(Level.INFO, "server shutdown");
        }
    }

    class ClientResponseHandler extends SimpleChannelInboundHandler<FullHttpResponse> {

        @Override
        protected void channelRead0(ChannelHandlerContext ctx, FullHttpResponse msg) {
            clientLogger.log(Level.INFO, "response received on client: " + msg);
            responseFuture.complete(true);
        }
    }

    class ClientMessages extends ChannelInboundHandlerAdapter {

        @Override
        public void channelRead(ChannelHandlerContext ctx, Object msg) {
            clientLogger.log(Level.FINE, "got client msg " + msg + " class = " + msg.getClass());
        }

        @Override
        public void userEventTriggered(ChannelHandlerContext ctx, Object evt) {
            clientLogger.log(Level.FINE, "got client user event " + evt);
            if (evt instanceof Http2ConnectionPrefaceAndSettingsFrameWrittenEvent) {
                settingsPrefaceFuture.complete(true);
            }
            ctx.fireUserEventTriggered(evt);
        }

        @Override
        public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) {
            clientLogger.log(Level.WARNING, cause.getMessage(), cause);
        }
    }

    class ServerRequestHandler extends SimpleChannelInboundHandler<FullHttpRequest> {

        @Override
        protected void channelRead0(ChannelHandlerContext ctx, FullHttpRequest msg) {
            serverLogger.log(Level.INFO, "request received on server: " + msg +
                    " path = " + msg);
            DefaultFullHttpResponse response = new DefaultFullHttpResponse(HttpVersion.HTTP_1_1,
                    HttpResponseStatus.OK);
            serverLogger.log(Level.INFO, "writing server response: " + response);
            ctx.writeAndFlush(response);
        }
    }

    class ServerMessages extends ChannelInboundHandlerAdapter {

        @Override
        public void channelRead(ChannelHandlerContext ctx, Object msg) {
            serverLogger.log(Level.FINE, "got server msg " + msg + " class = " + msg.getClass());
        }

        @Override
        public void userEventTriggered(ChannelHandlerContext ctx, Object evt) {
            serverLogger.log(Level.FINE, "got server user event " + evt);
            ctx.fireUserEventTriggered(evt);
        }

        @Override
        public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) {
            serverLogger.log(Level.WARNING, cause.getMessage(), cause);
        }
    }

    class TrafficLoggingHandler extends LoggingHandler {

        TrafficLoggingHandler(String name, LogLevel level) {
            super(name, level);
        }

        @Override
        public void channelRegistered(ChannelHandlerContext ctx) {
            ctx.fireChannelRegistered();
        }

        @Override
        public void channelUnregistered(ChannelHandlerContext ctx) {
            ctx.fireChannelUnregistered();
        }

        @Override
        public void flush(ChannelHandlerContext ctx) {
            ctx.flush();
        }

        @Override
        public void write(ChannelHandlerContext ctx, Object msg, ChannelPromise promise) throws Exception {
            if (msg instanceof ByteBuf && !((ByteBuf) msg).isReadable()) {
                ctx.write(msg, promise);
            } else {
                super.write(ctx, msg, promise);
            }
        }
    }
}

test.log

Testing started at 12:11 ...
12:11:54: Executing tasks ':netty-http-server:cleanTest :netty-http-server:test --tests org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test'...

Date: 2018-03-11T12:11:54.338191+01:00[Europe/Berlin]
Host: JorgPrantesMBP.fritz.box/192.168.178.23
OS: Mac OS X x86_64 10.12.6
JVM: 9.0.4.1 9.0.4.1+11 Azul Systems, Inc. OpenJDK 64-Bit Server VM
Gradle: 4.6 Groovy: 2.4.12 Java: 1.9
Build: group: org.xbib name: netty-http-client version: 4.1.22.2
:netty-http-server:cleanTest
:netty-http-common:compileJava UP-TO-DATE
:netty-http-common:processResources NO-SOURCE
:netty-http-common:classes UP-TO-DATE
:netty-http-common:jar UP-TO-DATE
:netty-http-client:compileJava UP-TO-DATE
:netty-http-client:processResources NO-SOURCE
:netty-http-client:classes UP-TO-DATE
:netty-http-client:jar UP-TO-DATE
:netty-http-server:compileJava UP-TO-DATE
:netty-http-server:processResources NO-SOURCE
:netty-http-server:classes UP-TO-DATE
:netty-http-server:compileTestJava
:netty-http-server:processTestResources NO-SOURCE
:netty-http-server:testClasses
:netty-http-server:test
2018-03-11 12:11:55.569 FEIN    [io.netty.util.internal.logging.InternalLoggerFactory] io.netty.util.internal.logging.InternalLoggerFactory newDefaultFactory Using java.util.logging as the default logging framework 
2018-03-11 12:11:55.599 FEIN    [io.netty.channel.MultithreadEventLoopGroup] io.netty.channel.MultithreadEventLoopGroup <clinit> -Dio.netty.eventLoopThreads: 16 
2018-03-11 12:11:55.627 FEIN    [io.netty.channel.nio.NioEventLoop] io.netty.channel.nio.NioEventLoop <clinit> -Dio.netty.noKeySetOptimization: true 
2018-03-11 12:11:55.627 FEIN    [io.netty.channel.nio.NioEventLoop] io.netty.channel.nio.NioEventLoop <clinit> -Dio.netty.selectorAutoRebuildThreshold: 512 
2018-03-11 12:11:55.641 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent isOsx0 Platform: MacOS 
2018-03-11 12:11:55.643 FEIN    [io.netty.util.internal.PlatformDependent0] io.netty.util.internal.PlatformDependent0 explicitNoUnsafeCause0 -Dio.netty.noUnsafe: true 
2018-03-11 12:11:55.643 FEIN    [io.netty.util.internal.PlatformDependent0] io.netty.util.internal.PlatformDependent0 explicitNoUnsafeCause0 sun.misc.Unsafe: unavailable (io.netty.noUnsafe) 
2018-03-11 12:11:55.644 FEIN    [io.netty.util.internal.PlatformDependent0] io.netty.util.internal.PlatformDependent0 javaVersion0 Java version: 9 
2018-03-11 12:11:55.644 FEIN    [io.netty.util.internal.PlatformDependent0] io.netty.util.internal.PlatformDependent0 <clinit> java.nio.DirectByteBuffer.<init>(long, int): unavailable 
2018-03-11 12:11:55.658 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent maxDirectMemory0 maxDirectMemory: 4294967296 bytes (maybe) 
2018-03-11 12:11:55.658 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent tmpdir0 -Dio.netty.tmpdir: /var/folders/v5/vvl6jhqs0cz_krl674_yb6980000gn/T (java.io.tmpdir) 
2018-03-11 12:11:55.659 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent bitMode0 -Dio.netty.bitMode: 64 (sun.arch.data.model) 
2018-03-11 12:11:55.660 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent <clinit> -Dio.netty.noPreferDirect: true 
2018-03-11 12:11:55.660 INFORMATION [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent <clinit> Your platform does not provide complete low-level API for accessing direct buffers reliably. Unless explicitly requested, heap buffer will always be preferred to avoid potential system instability. 
2018-03-11 12:11:55.661 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent <clinit> -Dio.netty.maxDirectMemory: -1 bytes 
2018-03-11 12:11:55.661 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent <clinit> -Dio.netty.uninitializedArrayAllocationThreshold: -1 
2018-03-11 12:11:55.666 FEIN    [io.netty.util.internal.PlatformDependent] io.netty.util.internal.PlatformDependent$Mpsc <clinit> org.jctools-core.MpscChunkedArrayQueue: unavailable 
2018-03-11 12:11:55.703 FEIN    [io.netty.channel.DefaultChannelId] io.netty.channel.DefaultChannelId <clinit> -Dio.netty.processId: 67927 (auto-detected) 
2018-03-11 12:11:55.705 FEIN    [io.netty.util.NetUtil] io.netty.util.NetUtil <clinit> -Djava.net.preferIPv4Stack: false 
2018-03-11 12:11:55.706 FEIN    [io.netty.util.NetUtil] io.netty.util.NetUtil <clinit> -Djava.net.preferIPv6Addresses: false 
2018-03-11 12:11:55.710 FEIN    [io.netty.util.NetUtil] io.netty.util.NetUtil <clinit> Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0) 
2018-03-11 12:11:55.710 FEIN    [io.netty.util.NetUtil] io.netty.util.NetUtil$1 run Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128 
2018-03-11 12:11:55.712 FEIN    [io.netty.channel.DefaultChannelId] io.netty.channel.DefaultChannelId <clinit> -Dio.netty.machineId: 78:31:c1:ff:fe:d6:f3:50 (auto-detected) 
2018-03-11 12:11:55.716 FEIN    [io.netty.util.internal.InternalThreadLocalMap] io.netty.util.internal.InternalThreadLocalMap <clinit> -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024 
2018-03-11 12:11:55.717 FEIN    [io.netty.util.internal.InternalThreadLocalMap] io.netty.util.internal.InternalThreadLocalMap <clinit> -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096 
2018-03-11 12:11:55.723 FEIN    [io.netty.util.ResourceLeakDetector] io.netty.util.ResourceLeakDetector <clinit> -Dio.netty.leakDetection.level: paranoid 
2018-03-11 12:11:55.724 FEIN    [io.netty.util.ResourceLeakDetector] io.netty.util.ResourceLeakDetector <clinit> -Dio.netty.leakDetection.targetRecords: 4 
2018-03-11 12:11:55.743 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.numHeapArenas: 16 
2018-03-11 12:11:55.744 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.numDirectArenas: 16 
2018-03-11 12:11:55.744 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.pageSize: 8192 
2018-03-11 12:11:55.745 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.maxOrder: 11 
2018-03-11 12:11:55.745 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.chunkSize: 16777216 
2018-03-11 12:11:55.745 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.tinyCacheSize: 512 
2018-03-11 12:11:55.746 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.smallCacheSize: 256 
2018-03-11 12:11:55.746 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.normalCacheSize: 64 
2018-03-11 12:11:55.747 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.maxCachedBufferCapacity: 32768 
2018-03-11 12:11:55.747 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.cacheTrimInterval: 8192 
2018-03-11 12:11:55.748 FEIN    [io.netty.buffer.PooledByteBufAllocator] io.netty.buffer.PooledByteBufAllocator <clinit> -Dio.netty.allocator.useCacheForAllThreads: true 
2018-03-11 12:11:55.754 FEIN    [io.netty.buffer.ByteBufUtil] io.netty.buffer.ByteBufUtil <clinit> -Dio.netty.allocator.type: pooled 
2018-03-11 12:11:55.754 FEIN    [io.netty.buffer.ByteBufUtil] io.netty.buffer.ByteBufUtil <clinit> -Dio.netty.threadLocalDirectBufferSize: 0 
2018-03-11 12:11:55.755 FEIN    [io.netty.buffer.ByteBufUtil] io.netty.buffer.ByteBufUtil <clinit> -Dio.netty.maxThreadLocalCharBufferSize: 16384 
2018-03-11 12:11:55.776 INFORMATION [server] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test testMultiplexHttp2 server up, channel = [id: 0xa66e5d09, L:/127.0.0.1:8443] 
2018-03-11 12:11:55.796 FEIN    [io.netty.buffer.AbstractByteBuf] io.netty.buffer.AbstractByteBuf <clinit> -Dio.netty.buffer.bytebuf.checkAccessible: true 
2018-03-11 12:11:55.799 FEIN    [io.netty.util.ResourceLeakDetectorFactory] io.netty.util.ResourceLeakDetectorFactory$DefaultResourceLeakDetectorFactory newResourceLeakDetector Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@674fe04e 
2018-03-11 12:11:55.803 FEIN    [io.netty.buffer.AdvancedLeakAwareByteBuf] io.netty.buffer.AdvancedLeakAwareByteBuf <clinit> -Dio.netty.leakDetection.acquireAndReleaseOnly: false 
2018-03-11 12:11:55.859 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler connect [id: 0x92bd40a5] CONNECT: localhost/127.0.0.1:8443 
2018-03-11 12:11:55.863 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler channelActive [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] ACTIVE 
2018-03-11 12:11:55.863 INFORMATION [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test testMultiplexHttp2 client connected, channel = [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] 
2018-03-11 12:11:55.865 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] WRITE: 24B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a |PRI * HTTP/2.0..|
|00000010| 0d 0a 53 4d 0d 0a 0d 0a                         |..SM....        |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.867 FEIN    [io.netty.util.Recycler] io.netty.util.Recycler <clinit> -Dio.netty.recycler.maxCapacityPerThread: disabled 
2018-03-11 12:11:55.868 FEIN    [io.netty.util.Recycler] io.netty.util.Recycler <clinit> -Dio.netty.recycler.maxSharedCapacityFactor: disabled 
2018-03-11 12:11:55.868 FEIN    [io.netty.util.Recycler] io.netty.util.Recycler <clinit> -Dio.netty.recycler.linkCapacity: disabled 
2018-03-11 12:11:55.868 FEIN    [io.netty.util.Recycler] io.netty.util.Recycler <clinit> -Dio.netty.recycler.ratio: disabled 
2018-03-11 12:11:55.871 INFORMATION [client] io.netty.handler.codec.http2.Http2FrameLogger logSettings [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} 
2018-03-11 12:11:55.891 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler channelActive [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] ACTIVE 
2018-03-11 12:11:55.894 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] WRITE: 15B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 06 04 00 00 00 00 00 00 06 00 00 20 00    |............. . |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.907 FEIN    [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test$ClientMessages userEventTriggered got client user event io.netty.handler.codec.http2.Http2ConnectionPrefaceAndSettingsFrameWrittenEvent@7da38301 
2018-03-11 12:11:55.908 INFORMATION [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test testMultiplexHttp2 settings and preface written 
2018-03-11 12:11:55.918 INFORMATION [child-client-traffic] io.netty.handler.logging.LoggingHandler channelActive [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443](H2 - -1) ACTIVE 
2018-03-11 12:11:55.923 INFORMATION [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test testMultiplexHttp2 waiting max. 10 seconds 
2018-03-11 12:11:55.923 INFORMATION [child-client-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443](H2 - -1) WRITE: DefaultHttp2HeadersFrame(stream=null, headers=DefaultHttp2Headers[:method: GET, :path: /foobar, :scheme: http, :authority: localhost], endStream=true, padding=0) 
2018-03-11 12:11:55.925 INFORMATION [client] io.netty.handler.codec.http2.Http2FrameLogger logHeaders [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] OUTBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:method: GET, :path: /foobar, :scheme: http, :authority: localhost] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true 
2018-03-11 12:11:55.931 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] WRITE: 14B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 16 01 25 00 00 00 03 00 00 00 00 0f       |....%.........  |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.932 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] WRITE: 17B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 82 44 85 62 53 9e 31 d9 86 41 86 a0 e4 1d 13 9d |.D.bS.1..A......|
|00000010| 09                                              |.               |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.948 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler channelRead [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] READ: 70B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 50 52 49 20 2a 20 48 54 54 50 2f 32 2e 30 0d 0a |PRI * HTTP/2.0..|
|00000010| 0d 0a 53 4d 0d 0a 0d 0a 00 00 06 04 00 00 00 00 |..SM............|
|00000020| 00 00 06 00 00 20 00 00 00 16 01 25 00 00 00 03 |..... .....%....|
|00000030| 00 00 00 00 0f 82 44 85 62 53 9e 31 d9 86 41 86 |......D.bS.1..A.|
|00000040| a0 e4 1d 13 9d 09                               |......          |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.952 INFORMATION [server] io.netty.handler.codec.http2.Http2FrameLogger logSettings [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] OUTBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} 
2018-03-11 12:11:55.953 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] WRITE: 15B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 06 04 00 00 00 00 00 00 06 00 00 20 00    |............. . |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.969 FEIN    [server] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test$ServerMessages userEventTriggered got server user event io.netty.handler.codec.http2.CleartextHttp2ServerUpgradeHandler$PriorKnowledgeUpgradeEvent@38faaa5d 
2018-03-11 12:11:55.971 INFORMATION [server] io.netty.handler.codec.http2.Http2FrameLogger logSettings [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] INBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} 
2018-03-11 12:11:55.972 INFORMATION [server] io.netty.handler.codec.http2.Http2FrameLogger logSettingsAck [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] OUTBOUND SETTINGS: ack=true 
2018-03-11 12:11:55.972 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] WRITE: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 04 01 00 00 00 00                      |.........       |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.974 FEIN    [server] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test$ServerMessages channelRead got server msg DefaultHttp2SettingsFrame(settings={MAX_HEADER_LIST_SIZE=8192}) class = class io.netty.handler.codec.http2.DefaultHttp2SettingsFrame 
2018-03-11 12:11:55.975 INFORMATION [server] io.netty.handler.codec.http2.Http2FrameLogger logHeaders [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] INBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:method: GET, :path: /foobar, :scheme: http, :authority: localhost] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true 
2018-03-11 12:11:55.977 INFORMATION [multiplex-server-traffic] io.netty.handler.logging.LoggingHandler channelActive [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683](H2 - 3) ACTIVE 
2018-03-11 12:11:55.978 INFORMATION [multiplex-server-traffic] io.netty.handler.logging.LoggingHandler channelRead [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683](H2 - 3) READ: DefaultHttp2HeadersFrame(stream=3, headers=DefaultHttp2Headers[:method: GET, :path: /foobar, :scheme: http, :authority: localhost], endStream=true, padding=0) 
2018-03-11 12:11:55.983 INFORMATION [server] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test$ServerRequestHandler channelRead0 request received on server: DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: AdvancedLeakAwareByteBuf(PooledHeapByteBuf(ridx: 0, widx: 0, cap: 256)))
GET /foobar HTTP/1.1
x-http2-scheme: http
host: localhost
x-http2-stream-id: 0 
2018-03-11 12:11:55.983 INFORMATION [server] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test$ServerRequestHandler channelRead0 writing server response: DefaultFullHttpResponse(decodeResult: success, version: HTTP/1.1, content: UnpooledByteBufAllocator$InstrumentedUnpooledHeapByteBuf(ridx: 0, widx: 0, cap: 0))
HTTP/1.1 200 OK 
2018-03-11 12:11:55.986 INFORMATION [multiplex-server-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683](H2 - 3) WRITE: DefaultHttp2HeadersFrame(stream=null, headers=DefaultHttp2Headers[:status: 200], endStream=true, padding=0) 
2018-03-11 12:11:55.989 INFORMATION [server] io.netty.handler.codec.http2.Http2FrameLogger logHeaders [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] OUTBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:status: 200] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true 
2018-03-11 12:11:55.992 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] WRITE: 14B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 06 01 25 00 00 00 03 00 00 00 00 0f       |....%.........  |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.993 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] WRITE: 1B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 88                                              |.               |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.997 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler channelRead [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] READ: 39B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 06 04 00 00 00 00 00 00 06 00 00 20 00 00 |............. ..|
|00000010| 00 00 04 01 00 00 00 00 00 00 06 01 25 00 00 00 |............%...|
|00000020| 03 00 00 00 00 0f 88                            |.......         |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.997 INFORMATION [multiplex-server-traffic] io.netty.handler.logging.LoggingHandler channelWritabilityChanged [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683](H2 - 3) WRITABILITY CHANGED 
2018-03-11 12:11:55.998 INFORMATION [client] io.netty.handler.codec.http2.Http2FrameLogger logSettings [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] INBOUND SETTINGS: ack=false settings={MAX_HEADER_LIST_SIZE=8192} 
2018-03-11 12:11:55.998 INFORMATION [client] io.netty.handler.codec.http2.Http2FrameLogger logSettingsAck [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] OUTBOUND SETTINGS: ack=true 
2018-03-11 12:11:55.998 INFORMATION [multiplex-server-traffic] io.netty.handler.logging.LoggingHandler channelInactive [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683](H2 - 3) INACTIVE 
2018-03-11 12:11:55.999 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler write [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] WRITE: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 04 01 00 00 00 00                      |.........       |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:55.999 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler channelReadComplete [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] READ COMPLETE 
2018-03-11 12:11:56.000 FEIN    [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test$ClientMessages channelRead got client msg DefaultHttp2SettingsFrame(settings={MAX_HEADER_LIST_SIZE=8192}) class = class io.netty.handler.codec.http2.DefaultHttp2SettingsFrame 
2018-03-11 12:11:56.000 INFORMATION [client] io.netty.handler.codec.http2.Http2FrameLogger logSettingsAck [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] INBOUND SETTINGS: ack=true 
2018-03-11 12:11:56.001 INFORMATION [client] io.netty.handler.codec.http2.Http2FrameLogger logHeaders [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] INBOUND HEADERS: streamId=3 headers=DefaultHttp2Headers[:status: 200] streamDependency=0 weight=16 exclusive=false padding=0 endStream=true 
2018-03-11 12:11:56.001 INFORMATION [child-client-traffic] io.netty.handler.logging.LoggingHandler channelRead [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443](H2 - 3) READ: DefaultHttp2HeadersFrame(stream=3, headers=DefaultHttp2Headers[:status: 200], endStream=true, padding=0) 
2018-03-11 12:11:56.004 INFORMATION [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test$ClientResponseHandler channelRead0 response received on client: DefaultFullHttpResponse(decodeResult: success, version: HTTP/1.1, content: AdvancedLeakAwareByteBuf(PooledHeapByteBuf(ridx: 0, widx: 0, cap: 256)))
HTTP/1.1 200 OK
x-http2-stream-id: 0 
2018-03-11 12:11:56.006 INFORMATION [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test testMultiplexHttp2 done! 
2018-03-11 12:11:56.006 INFORMATION [child-client-traffic] io.netty.handler.logging.LoggingHandler channelReadComplete [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443](H2 - 3) READ COMPLETE 
2018-03-11 12:11:56.008 INFORMATION [child-client-traffic] io.netty.handler.logging.LoggingHandler channelWritabilityChanged [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443](H2 - 3) WRITABILITY CHANGED 
2018-03-11 12:11:56.009 INFORMATION [child-client-traffic] io.netty.handler.logging.LoggingHandler channelInactive [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443](H2 - 3) INACTIVE 
2018-03-11 12:11:56.010 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler channelReadComplete [id: 0x92bd40a5, L:/127.0.0.1:60683 - R:localhost/127.0.0.1:8443] READ COMPLETE 
2018-03-11 12:11:56.012 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler channelRead [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] READ: 9B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 00 00 00 04 01 00 00 00 00                      |.........       |
+--------+-------------------------------------------------+----------------+ 
2018-03-11 12:11:56.013 INFORMATION [server] io.netty.handler.codec.http2.Http2FrameLogger logSettingsAck [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] INBOUND SETTINGS: ack=true 
2018-03-11 12:11:56.014 INFORMATION [client-traffic] io.netty.handler.logging.LoggingHandler channelInactive [id: 0x92bd40a5, L:/127.0.0.1:60683 ! R:localhost/127.0.0.1:8443] INACTIVE 
2018-03-11 12:11:56.014 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler channelReadComplete [id: 0x6496d73d, L:/127.0.0.1:8443 - R:/127.0.0.1:60683] READ COMPLETE 
2018-03-11 12:11:56.015 INFORMATION [server-traffic] io.netty.handler.logging.LoggingHandler channelInactive [id: 0x6496d73d, L:/127.0.0.1:8443 ! R:/127.0.0.1:60683] INACTIVE 
2018-03-11 12:11:58.130 FEIN    [io.netty.buffer.PoolThreadCache] io.netty.buffer.PoolThreadCache free Freed 6 thread-local buffer(s) from thread: nioEventLoopGroup-3-1 
2018-03-11 12:11:58.130 FEIN    [io.netty.buffer.PoolThreadCache] io.netty.buffer.PoolThreadCache free Freed 9 thread-local buffer(s) from thread: nioEventLoopGroup-2-2 
2018-03-11 12:11:58.228 INFORMATION [client] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test testMultiplexHttp2 client shutdown 
2018-03-11 12:11:58.229 INFORMATION [server] org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test testMultiplexHttp2 server shutdown 
BUILD SUCCESSFUL in 4s
8 actionable tasks: 3 executed, 5 up-to-date
12:11:58: Tasks execution finished ':netty-http-server:cleanTest :netty-http-server:test --tests org.xbib.netty.http.server.test.simple.MultiplexCodecCleartextHttp2Test'.