All geek questions in one place

Netty server does not accept connections after the first connection

I have a problem starting a service that uses Netty. It starts and works correctly, but only once. After this, connections are not accepted (they are immediately deleted).

I have several listeners, and each of them accepts only one connection, after which it is 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 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 that some things can be simplified, this is a short version that still reproduces the problem)

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

(do not worry about the JSON-RPC error, this is a logical error, with the right request and response it works the same way)

Second session

But after closing the client connection, it is impossible to reconnect.

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

- change -

Netty Version: 4.0.33.Final

- edit 2 -

While the connection is active, the server is working fine - I can exchange requests / answers until I close the connection.

Do not confuse IP addresses, this is a local port redirected to Docker where the application is running. This should not be a problem, I have an Apache MINA application that works the same and is trying to port it to Netty.

- edit 3 -

After making 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:

All the same, the parent channel does not close 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.
  • is registered and the server is working
  • not logged in until I destroy the server ( [CTRL] + [C] )
  • never registered
  • never registered
  • registered after disconnecting the socket
  • recorded subsequently

- change 4 -

Log Example with LoggingHandler is the 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 abcdef | +--------+-------------------------------------------------+----------------+ |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 abcdef | +--------+-------------------------------------------------+----------------+ |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 abcdef | +--------+-------------------------------------------------+----------------+ |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 abcdef | +--------+-------------------------------------------------+----------------+ |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
+5
source share
2 answers

Ok, figured it out. @zapl the idea of ​​adding additional logs led me to add a logger for io.netty . This is what happened after the following connection 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 this is clear enough;).

+2
source

Thanks to Rafał for your reply .

I would also like to share more information, in case you use a non Sharable handler, you will need to create a new instance 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 need to create a new handler each time you add it to the pipeline, because it is not separated by state, such as member variables.

0
source

Source: https://habr.com/ru/post/1239875/

More articles:


All Articles