CODEWITHSUNDEEP
javanettynio
Rafał Wrzeszcz
Rafał Wrzeszcz

Reputation: 2067

Netty server doesn't accept connections after first connect

I have a problem running service that uses Netty. It starts and works properly, but only once. After that no connections are accepted (they are immediately dropped).

I have multiple listeners and each of them accepts only ony connection, after that it's impossible to connect to the same listener.

Code

Here is my Listener.java:

public class Listener
{
    /* ... */

    public void run()
    {
        // check if there is any sense in running this listener
        if (this.address == null) {
            this.logger.info("\"{}\" was not enabled for connection, no point to start it.", this.getName());
            return;
        }

        final int maxPacketSize = this.getMaxPacketSize();
        final ChannelHandler handler = new DispatcherHandler<ContextType>(this.context, this.dispatcher);
        EventLoopGroup acceptors = new NioEventLoopGroup();
        EventLoopGroup workers = new NioEventLoopGroup();

        try {
            // network service configuration
            ServerBootstrap bootstrap = new ServerBootstrap();
            bootstrap
                .group(acceptors, workers)
                .channel(NioServerSocketChannel.class)
                .option(ChannelOption.SO_REUSEADDR, true)
                .handler(new LoggingHandler(Listener.class))
                .childHandler(new ChannelInitializer<Channel> () {
                    @Override
                    public void initChannel(Channel channel)
                    {
                        // network service configuration
                        channel.pipeline().addLast(
                            new LoggingHandler(handler.getClass()),
                            new LineBasedFrameDecoder(maxPacketSize),
                            new StringDecoder(StandardCharsets.UTF_8),
                            new StringEncoder(StandardCharsets.UTF_8),
                            handler
                        );
                    }
                });

            // start the server
            this.channel = bootstrap.bind(this.address).sync().channel();

            this.logger.info("Started."); // (1)

            // wait until channel is closed
            this.channel.closeFuture().sync();

            this.logger.info("Stopped."); // (2)
        } catch (InterruptedException error) {
            // don't worry - it's what we want in fact
            this.logger.error("Interrupted."); // (3)
            //CHECKSTYLE:OFF: IllegalCatchCheck
        } catch (Throwable error) {
            //CHECKSTYLE:ON: IllegalCatchCheck
            // this is not expected
            this.logger.error("IO connection error: {}.", error.getMessage()); // (4)
        } finally {
            this.logger.info("Finalizing."); // (5)
            this.channel = null;

            // close connections
            acceptors.shutdownGracefully();
            workers.shutdownGracefully();
            this.logger.info("Done."); // (6)
        }
    }
}

DispatcherHandler.java:

public class DispatcherHandler<ContextType extends ContextInterface> extends ChannelInboundHandlerAdapter
{
    /* ... */

    @Override
    public void exceptionCaught(ChannelHandlerContext session, Throwable error)
    {
        this.logger.error(
            "Session ID {}: connection exteption.",
            session.name(),
            error
        );
        session.writeAndFlush(new JSONRPC2Response(JSONRPC2Error.INTERNAL_ERROR, null));
        session.close();
    }

    @Override
    public void channelRead(ChannelHandlerContext session, Object message)
    {
        JSONRPC2Response response = null;

        try {
            // parse the request
            JSONRPC2Request request = JSONRPC2Request.parse(message.toString());

            // dispatch it
            try {
                response = this.dispatcher.dispatch(request, this.context);
                //CHECKSTYLE:OFF: IllegalCatchCheck
            } catch (Throwable error) {
                //CHECKSTYLE:ON: IllegalCatchCheck
                // we DO WANT to catch all exceptions to avoid listener thread to die
                this.logger.error("Internal error.", error);
                response = new JSONRPC2Response(
                    JSONRPC2Error.INTERNAL_ERROR.appendMessage(": " + error.getMessage() + "."),
                    request.getID()
                );
            }
        } catch (JSONRPC2ParseException error) {
            response = new JSONRPC2Response(JSONRPC2Error.PARSE_ERROR, null);
            this.logger.error("Could not parse JSON-RPC request.");
        }

        // send response to client
        session.writeAndFlush(response.toJSONString());
    }
}

(I know some stuff can be simplified, it's a shortcut version that still reproduces the issue)

First session

When I first connect to the server using nc localhost 6000 (sample port, whatever) everything works fine:

client session:

rafal.wrzeszcz@devel0:~$ nc -vv localhost 6000
localhost [127.0.0.1] 6000 (?) open
test
{"id":null,"error":{"code":-32700,"message":"JSON parse error"},"jsonrpc":"2.0"}^C
rafal.wrzeszcz@devel0:~$

server logs:

10:45:37.036 [nioEventLoopGroup-3-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0xd8fbf0ce, /0:0:0:0:0:0:0:0:6000] RECEIVED: [id: 0xb89181bd, /172.17.0.1:56485 => /172.17.0.2:6000]
10:45:37.056 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb89181bd, /172.17.0.1:56485 => /172.17.0.2:6000] REGISTERED
10:45:37.056 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb89181bd, /172.17.0.1:56485 => /172.17.0.2:6000] ACTIVE
10:45:39.285 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb89181bd, /172.17.0.1:56485 => /172.17.0.2:6000] RECEIVED: test
10:45:39.293 [nioEventLoopGroup-11-1] ERROR pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - Could not parse JSON-RPC request.
10:45:39.294 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb89181bd, /172.17.0.1:56485 => /172.17.0.2:6000] WRITE: {"id":null,"error":{"code":-32700,"message":"JSON parse error"},"jsonrpc":"2.0"}
10:45:39.297 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb89181bd, /172.17.0.1:56485 => /172.17.0.2:6000] FLUSH
10:45:40.066 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb89181bd, /172.17.0.1:56485 :> /172.17.0.2:6000] INACTIVE
10:45:40.067 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb89181bd, /172.17.0.1:56485 :> /172.17.0.2:6000] UNREGISTERED

(don't worry about the JSON-RPC error, it's logic error, with the proper request and response it works exactly the same way)

Second session

But after I close the client connection it's impossible to connect again.

client session:

rafal.wrzeszcz@devel0:~$ nc -vv localhost 6000
localhost [127.0.0.1] 6000 (x11) open
 sent 0, rcvd 0
rafal.wrzeszcz@devel0:~$

server logs:

10:45:40.539 [nioEventLoopGroup-3-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0xd8fbf0ce, /0:0:0:0:0:0:0:0:6000] RECEIVED: [id: 0x9e3dc0b1, /172.17.0.1:56487 => /172.17.0.2:6000]
10:45:40.545 [nioEventLoopGroup-11-2] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x9e3dc0b1, /172.17.0.1:56487 :> /172.17.0.2:6000] INACTIVE
10:45:40.547 [nioEventLoopGroup-11-2] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x9e3dc0b1, /172.17.0.1:56487 :> /172.17.0.2:6000] UNREGISTERED

-- edit --

Netty version: 4.0.33.Final

-- edit 2 --

As long as a connection is active the server works fine - I'm able to exchange requests/responses contonously until I close the connection.

Don't be confused by IP addresses, it's a local port forwarded to Docker, where the app is launched. It shouldn't be a problem, I have Apache MINA application running same way, and trying to port it to Netty.

-- edit 3 --

After applying changes from comments

Client

rafal.wrzeszcz@devel0:~$ nc -vv localhost 6000
localhost [127.0.0.1] 6000 (x11) open
test
{"id":null,"error":{"code":-32700,"message":"JSON parse error"},"jsonrpc":"2.0"}test
{"id":null,"error":{"code":-32700,"message":"JSON parse error"},"jsonrpc":"2.0"}^C sent 10, rcvd 160
rafal.wrzeszcz@devel0:~$ nc -vv localhost 6000
localhost [127.0.0.1] 6000 (x11) open
sent 0, rcvd 0

Server logs after additional messages:

Everything is the same, parent channel is not closed until I press [CTRL] + [C]:

12:05:53.720 [chilldev.pl-frontend] INFO  pl.chilldev.commons.jsonrpc.daemon.Listener - Started.
12:05:58.075 [nioEventLoopGroup-6-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0x7cbe3265, /0:0:0:0:0:0:0:0:6000] RECEIVED: [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000]
12:05:58.095 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] REGISTERED
12:05:58.096 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] ACTIVE
12:06:02.122 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] RECEIVED: test
12:06:02.129 [nioEventLoopGroup-11-1] ERROR pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - Could not parse JSON-RPC request.
12:06:02.129 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] WRITE: {"id":null,"error":{"code":-32700,"message":"JSON parse error"},"jsonrpc":"2.0"}
12:06:02.132 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] FLUSH
12:06:03.414 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] RECEIVED: test
12:06:03.415 [nioEventLoopGroup-11-1] ERROR pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - Could not parse JSON-RPC request.
12:06:03.416 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] WRITE: {"id":null,"error":{"code":-32700,"message":"JSON parse error"},"jsonrpc":"2.0"}
12:06:03.416 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 => /172.17.0.2:6000] FLUSH
12:06:04.091 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 :> /172.17.0.2:6000] INACTIVE
12:06:04.091 [nioEventLoopGroup-11-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0xb284a0b1, /172.17.0.1:57853 :> /172.17.0.2:6000] UNREGISTERED
12:06:07.923 [nioEventLoopGroup-6-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0x7cbe3265, /0:0:0:0:0:0:0:0:6000] RECEIVED: [id: 0x0def7d2a, /172.17.0.1:57856 => /172.17.0.2:6000]
12:06:07.932 [nioEventLoopGroup-11-2] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0def7d2a, /172.17.0.1:57856 :> /172.17.0.2:6000] INACTIVE
12:06:07.933 [nioEventLoopGroup-11-2] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0def7d2a, /172.17.0.1:57856 :> /172.17.0.2:6000] UNREGISTERED
^C12:08:25.329 [Thread-14] INFO  pl.chilldev.commons.jsonrpc.daemon.AbstractApplication - Stopping…
12:08:25.335 [nioEventLoopGroup-6-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0x7cbe3265, /0:0:0:0:0:0:0:0:6000] CLOSE()
12:08:25.337 [chilldev.pl-frontend] INFO  pl.chilldev.commons.jsonrpc.daemon.Listener - Stopped.
12:08:25.337 [nioEventLoopGroup-6-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0x7cbe3265, /0:0:0:0:0:0:0:0:6000] UNREGISTERED
12:08:25.337 [chilldev.pl-frontend] INFO  pl.chilldev.commons.jsonrpc.daemon.Listener - Finalizing.
12:08:25.345 [chilldev.pl-frontend] INFO  pl.chilldev.commons.jsonrpc.daemon.Listener - Done.
  1. is logged and server is running
  2. is not logged until I kill the server ([CTRL] + [C])
  3. is never logged
  4. is never logged
  5. is logged after the socket is unbound
  6. is logged afterwards

-- edit 4 --

Sample log with LoggingHandler being first handler

12:18:52.396 [nioEventLoopGroup-3-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0xbec73d3f, /0:0:0:0:0:0:0:0:6000] RECEIVED: [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000]
12:18:52.432 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] REGISTERED
12:18:52.435 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] ACTIVE
12:18:53.479 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] RECEIVED: 5B
        +-------------------------------------------------+
        |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 74 65 73 74 0a                                  |test.           |
+--------+-------------------------------------------------+----------------+
12:18:53.495 [nioEventLoopGroup-9-1] ERROR pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - Could not parse JSON-RPC request.
12:18:53.497 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] WRITE: 80B
        +-------------------------------------------------+
        |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 7b 22 69 64 22 3a 6e 75 6c 6c 2c 22 65 72 72 6f |{"id":null,"erro|
|00000010| 72 22 3a 7b 22 63 6f 64 65 22 3a 2d 33 32 37 30 |r":{"code":-3270|
|00000020| 30 2c 22 6d 65 73 73 61 67 65 22 3a 22 4a 53 4f |0,"message":"JSO|
|00000030| 4e 20 70 61 72 73 65 20 65 72 72 6f 72 22 7d 2c |N parse error"},|
|00000040| 22 6a 73 6f 6e 72 70 63 22 3a 22 32 2e 30 22 7d |"jsonrpc":"2.0"}|
+--------+-------------------------------------------------+----------------+
12:18:53.499 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] FLUSH
12:18:54.369 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] RECEIVED: 5B
        +-------------------------------------------------+
        |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 74 65 73 74 0a                                  |test.           |
+--------+-------------------------------------------------+----------------+
12:18:54.370 [nioEventLoopGroup-9-1] ERROR pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - Could not parse JSON-RPC request.
12:18:54.372 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] WRITE: 80B
        +-------------------------------------------------+
        |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 7b 22 69 64 22 3a 6e 75 6c 6c 2c 22 65 72 72 6f |{"id":null,"erro|
|00000010| 72 22 3a 7b 22 63 6f 64 65 22 3a 2d 33 32 37 30 |r":{"code":-3270|
|00000020| 30 2c 22 6d 65 73 73 61 67 65 22 3a 22 4a 53 4f |0,"message":"JSO|
|00000030| 4e 20 70 61 72 73 65 20 65 72 72 6f 72 22 7d 2c |N parse error"},|
|00000040| 22 6a 73 6f 6e 72 70 63 22 3a 22 32 2e 30 22 7d |"jsonrpc":"2.0"}|
+--------+-------------------------------------------------+----------------+
12:18:54.372 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 => /172.17.0.2:6000] FLUSH
12:18:55.174 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 :> /172.17.0.2:6000] INACTIVE
12:18:55.181 [nioEventLoopGroup-9-1] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x0c8be37b, /172.17.0.1:58020 :> /172.17.0.2:6000] UNREGISTERED
12:19:01.203 [nioEventLoopGroup-3-1] DEBUG pl.chilldev.commons.jsonrpc.daemon.Listener - [id: 0xbec73d3f, /0:0:0:0:0:0:0:0:6000] RECEIVED: [id: 0x9fa99c9e, /172.17.0.1:58022 => /172.17.0.2:6000]
12:19:01.210 [nioEventLoopGroup-9-2] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x9fa99c9e, /172.17.0.1:58022 :> /172.17.0.2:6000] INACTIVE
12:19:01.210 [nioEventLoopGroup-9-2] DEBUG pl.chilldev.commons.jsonrpc.netty.DispatcherHandler - [id: 0x9fa99c9e, /172.17.0.1:58022 :> /172.17.0.2:6000] UNREGISTERED

Upvotes: 6

Views: 6103

Answers (2)

dorony
dorony

Reputation: 1072

Thanks Rafał for your answer.

I would also like to share additional info, in case you are using a non Sharable handler you will need to create a new instance of every time you add it to the pipeline.

From Netty 4.1 docs:

public static @interface ChannelHandler.Sharable

Indicates that the same instance of the annotated ChannelHandler can be added to one or more ChannelPipelines multiple times without a race condition.

If this annotation is not specified, you have to create a new handler instance every time you add it to a pipeline because it has unshared state such as member variables.

Upvotes: 0

Rafał Wrzeszcz
Rafał Wrzeszcz

Reputation: 2067

Ok, figured that out. @zapl idea of adding additional logs led me to adding logger for io.netty. This is what happend after next connect attempt:

12:25:53.007 [nioEventLoopGroup-8-2] WARN  io.netty.channel.ChannelInitializer - Failed to initialize a channel. Closing: [id: 0xed038b64, /172.17.0.1:58276 => /172.17.0.2:6000]
io.netty.channel.ChannelPipelineException: pl.chilldev.commons.jsonrpc.netty.DispatcherHandler is not a @Sharable handler, so can't be added or removed multiple times.

I think it's clear enough ;).

Upvotes: 3

Related Questions