We encountered a bug in our app, and during processing of our protocol, one handler entered infinite loop and was stuck in the channelRead() method.
This however started to cause other (not all, but some) new connections to be stuck as well, somewhere upon connection. There is no thread visible showing that the connections are stuck. This gradually increases number of established connections and then eventually new connections have trouble to connect and start to time-out.
Why would 1 thread stuck in channelRead in infinite loop block any other connections (There were around 32 available threads for processing)? I confirmed that once the thread continues, all the stuck connections would resume.
I replicated the behavior with this simple example:
AppServer.java:
import io.netty.bootstrap.ServerBootstrap;
import io.netty.channel.ChannelFuture;
import io.netty.channel.ChannelOption;
import io.netty.channel.EventLoopGroup;
import io.netty.channel.epoll.EpollEventLoopGroup;
import io.netty.channel.epoll.EpollServerSocketChannel;
public class AppServer {
private static final int HTTP_PORT = 8080;
public void run() throws Exception {
EventLoopGroup bossGroup = new EpollEventLoopGroup();
EventLoopGroup workerGroup = new EpollEventLoopGroup();
try {
ServerBootstrap httpBootstrap = new ServerBootstrap();
httpBootstrap
.group(bossGroup, workerGroup)
.channel(EpollServerSocketChannel.class)
.childHandler(new ServerInitializer())
.option(ChannelOption.SO_BACKLOG, 512)
.childOption(ChannelOption.SO_KEEPALIVE, true);
// Bind and start to accept incoming connections.
ChannelFuture httpChannel = httpBootstrap.bind(HTTP_PORT).sync();
// Wait until the server socket is closed
httpChannel.channel().closeFuture().sync();
}
finally {
workerGroup.shutdownGracefully();
bossGroup.shutdownGracefully();
}
}
public static void main(String[] args) throws Exception {
new AppServer().run();
}
}
ServerHandler.java
import io.netty.buffer.ByteBuf;
import io.netty.buffer.Unpooled;
import io.netty.channel.ChannelHandlerContext;
import io.netty.channel.SimpleChannelInboundHandler;
import io.netty.handler.codec.http.*;
import io.netty.util.CharsetUtil;
public class ServerHandler extends SimpleChannelInboundHandler<FullHttpRequest> {
public static int count = 0;
@Override
protected void channelRead0(ChannelHandlerContext ctx, FullHttpRequest msg) {
if (count == 0) {
count++;
while (true) {}
}
ByteBuf content = Unpooled.copiedBuffer("Hello World!", CharsetUtil.UTF_8);
FullHttpResponse response = new DefaultFullHttpResponse(HttpVersion.HTTP_1_1, HttpResponseStatus.OK, content);
response.headers().set(HttpHeaderNames.CONTENT_TYPE, "text/html");
response.headers().set(HttpHeaderNames.CONTENT_LENGTH, content.readableBytes());
ctx.write(response);
ctx.flush();
count++;
}
}
ServerInitializer.java:
import io.netty.channel.Channel;
import io.netty.channel.ChannelInitializer;
import io.netty.channel.ChannelPipeline;
import io.netty.handler.codec.http.HttpObjectAggregator;
import io.netty.handler.codec.http.HttpServerCodec;
public class ServerInitializer extends ChannelInitializer<Channel> {
@Override
protected void initChannel(Channel ch) {
ChannelPipeline pipeline = ch.pipeline();
pipeline.addLast(new HttpServerCodec());
pipeline.addLast(new HttpObjectAggregator(Integer.MAX_VALUE));
pipeline.addLast(new ServerHandler());
}
}
I run many connections just using xargs and curl curl -v http://[ip]:8080.
After some time it gets to the state where this fails on timeout:
nc -vz [ip] 8080
Ncat: Version 7.50 ( https://nmap.org/ncat )
Ncat: Connection timed out.
This didn't show on loopback interface.
If no thread is stuck, netty does not get into this problem with same testing. It is processing all requests and no connections get stuck.
I tried using Nio as well. Same result.
Netty4.1
Stuck connections in established:
netstat -n | grep 8080 | sed -E 's/[[:space:]]+/ /g' | cut -d' ' -f 6 | sort | uniq -c
14551 ESTABLISHED
6839 TIME_WAIT
Stuck connection looks like this:
curl -v http://localhost:8080
* Rebuilt URL to: http://localhost:8080/
* Trying 127.0.0.1...
* TCP_NODELAY set
* Connected to localhost (127.0.0.1) port 8080 (#0)
> GET / HTTP/1.1
> Host: localhost:8080
> User-Agent: curl/7.61.1
> Accept: */*
>
tcp dump when the connection is ok:
00:25:35.135929 IP 10.94.158.96.50192 > 10.200.154.102.8080: Flags [S], seq 648221383, win 65340, options [mss 1210,nop,wscale 8,nop,nop,sackOK], length 0
00:25:35.135993 IP 10.200.154.102.8080 > 10.94.158.96.50192: Flags [S.], seq 167219764, ack 648221384, win 35844, options [mss 8961,nop,nop,sackOK,nop,wscale 8], length 0
00:25:35.174362 IP 10.94.158.96.50192 > 10.200.154.102.8080: Flags [.], ack 1, win 515, length 0
00:25:35.176419 IP 10.94.158.96.50192 > 10.200.154.102.8080: Flags [P.], seq 1:84, ack 1, win 515, length 83
00:25:35.176440 IP 10.200.154.102.8080 > 10.94.158.96.50192: Flags [.], ack 84, win 140, length 0
00:25:35.177307 IP 10.200.154.102.8080 > 10.94.158.96.50192: Flags [P.], seq 1:77, ack 84, win 140, length 76
00:25:35.216609 IP 10.94.158.96.50192 > 10.200.154.102.8080: Flags [F.], seq 84, ack 77, win 514, length 0
00:25:35.216856 IP 10.200.154.102.8080 > 10.94.158.96.50192: Flags [F.], seq 77, ack 85, win 140, length 0
00:25:35.254134 IP 10.94.158.96.50192 > 10.200.154.102.8080: Flags [.], ack 78, win 514, length 0
tcp dump when the connection is stuck:
00:25:38.409177 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [S], seq 8750522, win 65340, options [mss 1210,nop,wscale 8,nop,nop,sackOK], length 0
00:25:38.409254 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [S.], seq 1214051234, ack 8750523, win 35844, options [mss 8961,nop,nop,sackOK,nop,wscale 8], length 0
00:25:38.446641 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [.], ack 1, win 515, length 0
00:25:38.449108 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [P.], seq 1:84, ack 1, win 515, length 83
00:25:38.449141 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [.], ack 84, win 140, length 0
00:25:39.535154 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [.], seq 83:84, ack 1, win 515, length 1
00:25:39.535211 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [.], ack 84, win 140, options [nop,nop,sack 1 {83:84}], length 0
00:25:40.641378 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [.], seq 83:84, ack 1, win 515, length 1
00:25:40.641404 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [.], ack 84, win 140, options [nop,nop,sack 1 {83:84}], length 0
00:25:41.741142 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [.], seq 83:84, ack 1, win 515, length 1
00:25:41.741199 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [.], ack 84, win 140, options [nop,nop,sack 1 {83:84}], length 0
00:25:42.844891 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [.], seq 83:84, ack 1, win 515, length 1
00:25:42.844947 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [.], ack 84, win 140, options [nop,nop,sack 1 {83:84}], length 0
00:25:44.035849 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [.], seq 83:84, ack 1, win 515, length 1
00:25:44.035869 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [.], ack 84, win 140, options [nop,nop,sack 1 {83:84}], length 0
00:25:45.135646 IP 10.94.158.96.50193 > 10.200.154.102.8080: Flags [.], seq 83:84, ack 1, win 515, length 1
00:25:45.135702 IP 10.200.154.102.8080 > 10.94.158.96.50193: Flags [.], ack 84, win 140, options [nop,nop,sack 1 {83:84}], length 0
... repeats ...