A lot of log will be output and consumed a lot of CPU after network is disconnected on Android devices

[igiantpanda]

I have a trouble about netty when I use micronaut on Android. And I reported an issue to micronaut(micronaut-projects/micronaut-core#4129). But they tell me that I should report the issue to netty.

Expected behavior

Micronaut server stopped normally.

Actual behavior

Micronaut server will be stopped, but a lot of log will be output. And this will take up a lot of CPU resource.
Log:

 [nioEventLoopGroup-1-1] WARN io.netty.channel.nio.NioEventLoop - Selector.select() returned prematurely 512 times in a row; rebuilding Selector io.netty.channel.nio.SelectedSelectionKeySetSelector@70c8d50.
2020-09-18 14:58:18.405 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.405 [nioEventLoopGroup-1-1] INFO io.netty.channel.nio.NioEventLoop - Migrated 1 channel(s) to the new Selector.
2020-09-18 14:58:18.406 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.406 [nioEventLoopGroup-1-1] WARN io.netty.channel.nio.NioEventLoop - Selector.select() returned prematurely 512 times in a row; rebuilding Selector io.netty.channel.nio.SelectedSelectionKeySetSelector@1a42c4e.
2020-09-18 14:58:18.407 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.407 [nioEventLoopGroup-1-1] INFO io.netty.channel.nio.NioEventLoop - Migrated 1 channel(s) to the new Selector.
2020-09-18 14:58:18.409 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.408 [nioEventLoopGroup-1-1] WARN io.netty.channel.nio.NioEventLoop - Selector.select() returned prematurely 512 times in a row; rebuilding Selector io.netty.channel.nio.SelectedSelectionKeySetSelector@8352e7c.
2020-09-18 14:58:18.409 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.409 [nioEventLoopGroup-1-1] INFO io.netty.channel.nio.NioEventLoop - Migrated 1 channel(s) to the new Selector.
2020-09-18 14:58:18.411 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.410 [nioEventLoopGroup-1-1] WARN io.netty.channel.nio.NioEventLoop - Selector.select() returned prematurely 512 times in a row; rebuilding Selector io.netty.channel.nio.SelectedSelectionKeySetSelector@21abf5a.
2020-09-18 14:58:18.411 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.411 [nioEventLoopGroup-1-1] INFO io.netty.channel.nio.NioEventLoop - Migrated 1 channel(s) to the new Selector.
2020-09-18 14:58:18.413 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.413 [nioEventLoopGroup-1-1] WARN io.netty.channel.nio.NioEventLoop - Selector.select() returned prematurely 512 times in a row; rebuilding Selector io.netty.channel.nio.SelectedSelectionKeySetSelector@2e4b668.
2020-09-18 14:58:18.413 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.413 [nioEventLoopGroup-1-1] INFO io.netty.channel.nio.NioEventLoop - Migrated 1 channel(s) to the new Selector.
2020-09-18 14:58:18.415 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.414 [nioEventLoopGroup-1-1] WARN io.netty.channel.nio.NioEventLoop - Selector.select() returned prematurely 512 times in a row; rebuilding Selector io.netty.channel.nio.SelectedSelectionKeySetSelector@7357726.
2020-09-18 14:58:18.415 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.415 [nioEventLoopGroup-1-1] INFO io.netty.channel.nio.NioEventLoop - Migrated 1 channel(s) to the new Selector.
2020-09-18 14:58:18.417 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.417 [nioEventLoopGroup-1-1] WARN io.netty.channel.nio.NioEventLoop - Selector.select() returned prematurely 512 times in a row; rebuilding Selector io.netty.channel.nio.SelectedSelectionKeySetSelector@482d114.
2020-09-18 14:58:18.417 25846-25923/com.example.androidwebtest I/System.out: 14:58:18.417 [nioEventLoopGroup-1-1] INFO io.netty.channel.nio.NioEventLoop - Migrated 1 channel(s) to the new Selector.
......

CPU:

Tasks: 785 total,   4 running, 780 sleeping,   0 stopped,   1 zombie
  Mem:      5.4G total,      5.3G used,      116M free,      175M buffers
 Swap:      2.5G total,      498M used,      2.0G free,      3.0G cached
800%cpu  81%user  14%nice 196%sys 490%idle   0%iow  16%irq   3%sirq   0%host
  PID USER         PR  NI VIRT  RES  SHR S[%CPU] %MEM     TIME+ ARGS
25846 u0_a219      10 -10 5.3G 130M  79M S 99.3   2.3   0:15.86 com.example.androidwebtest

Steps to reproduce

1. Start micronaut and listen the IP of WiFi, but not listen "0.0.0.0".
2. Disconect WiFi.

Minimal yet complete reproducer code (or URL to code)

https://github.com/igiantpanda/AndroidWebTest/tree/disconnect-issue

Netty version

4.1.48.Final (The corresponding version of Micronaut is 2.0.0)

JVM version (e.g. java -version)

1.8

OS version (e.g. uname -a)

Android 10 (Tested on Android emulator and OPPO Reno)

[hyperxpro]

Turn off logging for io.netty.channel.nio.NioEventLoop

[InternalHigh]

Turn off logging for io.netty.channel.nio.NioEventLoop

I hope that this is a joke. There must be a bug in Netty that causes these messages in the first place.

[hyperxpro]

Turn off logging for io.netty.channel.nio.NioEventLoop

I hope that this is a joke. There must be a bug in Netty that causes these messages in the first place.

There is no bug in Netty but in Java NIO. So apart from turn off logging, you can switch to Epoll mechanism. Else, no other option. :)

[igiantpanda]

Turn off logging for io.netty.channel.nio.NioEventLoop

I'm a beginner, could you tell me how to turn off logging for io.netty.channel.nio.NioEventLoop?
Thanks.

[normanmaurer]

I will have a look but this seems to be caused by a bug in the nio implementation of android as this should really never happen

[hyperxpro]

Turn off logging for io.netty.channel.nio.NioEventLoop

I'm a beginner, could you tell me how to turn off logging for io.netty.channel.nio.NioEventLoop?
Thanks.

Depends on what logger you're using.

[igiantpanda]

Turn off logging for io.netty.channel.nio.NioEventLoop

I'm a beginner, could you tell me how to turn off logging for io.netty.channel.nio.NioEventLoop?
Thanks.

Depends on what logger you're using.

After I turn off logging for io.netty.channel.nio.NioEventLoop, I also found a lot of the follow exception. And the exception is existed before I turn off logging for io.netty.channel.nio.NioEventLoop.
And I tried to turn off logging for io.netty.channel.DefaultChannelPipeline, then the exception log will not output.
But the application still consumes a lot of CPU resource, even though I stopped or restarted the micronaut web server.

......
2020-09-21 11:18:21.494 10931-11005/com.example.androidwebtest I/System.out: 03:18:21.494 [nioEventLoopGroup-1-1] WARN io.netty.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
2020-09-21 11:18:21.494 10931-11005/com.example.androidwebtest I/System.out: java.io.IOException: Invalid argument
2020-09-21 11:18:21.494 10931-11005/com.example.androidwebtest I/System.out:     at sun.nio.ch.ServerSocketChannelImpl.accept0(Native Method)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:422)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at sun.nio.ch.ServerSocketChannelImpl.accept(ServerSocketChannelImpl.java:250)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.util.internal.SocketUtils$5.run(SocketUtils.java:119)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.util.internal.SocketUtils$5.run(SocketUtils.java:116)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at java.security.AccessController.doPrivileged(AccessController.java:69)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.util.internal.SocketUtils.accept(SocketUtils.java:116)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.channel.socket.nio.NioServerSocketChannel.doReadMessages(NioServerSocketChannel.java:147)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.channel.nio.AbstractNioMessageChannel$NioMessageUnsafe.read(AbstractNioMessageChannel.java:75)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
2020-09-21 11:18:21.495 10931-11005/com.example.androidwebtest I/System.out:     at java.lang.Thread.run(Thread.java:919)
......

CPU:

Tasks: 180 total,   1 running, 178 sleeping,   0 stopped,   1 zombie
  Mem:      1.9G total,      1.5G used,      368M free,       29M buffers
 Swap:      1.4G total,      9.0M used,      1.4G free,      762M cached
400%cpu  13%user   0%nice 188%sys 199%idle   0%iow   0%irq   0%sirq   0%host
  PID USER         PR  NI VIRT  RES  SHR S[%CPU] %MEM     TIME+ ARGS
10931 u0_a137      10 -10 1.8G 136M  81M S 99.6   6.8  10:49.49 com.example.androidwebtest

[normanmaurer]

This is definitely an android bug. There is not much we can do unfortunally :/