[HDDS-9814] NettyClientStreamRpc trying to establish connection during shutdown

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Later
• Assignee: Unassigned
• Reporter: Attila Doroszlai
• Created: 30/Nov/23 18:01
• Updated: 07/Dec/23 18:41
• Resolved: 07/Dec/23 18:41

Description

TestOzoneFileSystemWithStreaming logs lots of "connection refused" and "schedule reconnecting" messages during shutdown.

sample

2023-11-30 18:39:00,039 [main] INFO  ozone.MiniOzoneClusterImpl (MiniOzoneClusterImpl.java:shutdown(449)) - Shutting down the Mini Ozone Cluster

...

2023-11-30 18:39:01,126 [Thread-1140] DEBUG client.NettyClientStreamRpc (NettyClientStreamRpc.java:close(452)) - flush? true
2023-11-30 18:39:01,122 [Thread-1133] WARN  util.PeerProxyMap (PeerProxyMap.java:closeProxy(170)) - 2ad30381-d2ef-4801-b4d0-3965e2d4accc-NettyServerStreamRpc: Failed to close proxy for peer 3c309c61-fe70-460a-bb5b-539134755074|127.0.0.1:15014, proxy class: class org.apache.ratis.client.impl.DataStreamClientImpl
org.apache.ratis.thirdparty.io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Connection refused: /127.0.0.1:15015
Caused by: java.net.ConnectException: finishConnect(..) failed: Connection refused
	at org.apache.ratis.thirdparty.io.netty.channel.unix.Errors.newConnectException0(Errors.java:166)
	at org.apache.ratis.thirdparty.io.netty.channel.unix.Errors.handleConnectErrno(Errors.java:131)
	at org.apache.ratis.thirdparty.io.netty.channel.unix.Socket.finishConnect(Socket.java:359)
	at org.apache.ratis.thirdparty.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.doFinishConnect(AbstractEpollChannel.java:710)
	at org.apache.ratis.thirdparty.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.finishConnect(AbstractEpollChannel.java:687)
	at org.apache.ratis.thirdparty.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe.epollOutReady(AbstractEpollChannel.java:567)
	at org.apache.ratis.thirdparty.io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:499)
	at org.apache.ratis.thirdparty.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:407)
	at org.apache.ratis.thirdparty.io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:997)
	at org.apache.ratis.thirdparty.io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at java.lang.Thread.run(Thread.java:750)

This is during a normal, successful test run (logs: TestOzoneFileSystemWithStreaming-output-pass.txt).

On a related note, test run occasionally times out during shutdown:

[INFO] Running org.apache.hadoop.fs.ozone.TestOzoneFileSystemWithStreaming
...
[WARNING] Tests run: 1030, Failures: 0, Errors: 0, Skipped: 24
...
[ERROR] Failed to execute goal org.apache.maven.plugins:maven-surefire-plugin:3.0.0-M5:test (default-test) on project ozone-integration-test: There was a timeout in the fork -> [Help 1]

(logs: org.apache.hadoop.fs.ozone.TestOzoneFileSystemWithStreaming-output.txt, 2023-05-05T05-46-34_028-jvmRun1.dump)

More recently I noticed job runner timeout. Unfortunately we don't have logs for that:

Thu, 30 Nov 2023 13:38:47 GMT
[INFO] Running org.apache.hadoop.fs.ozone.TestOzoneFileSystemWithStreaming
Thu, 30 Nov 2023 15:58:17 GMT
Error: The operation was canceled.

CC szetszwo

Issue Links

• relates to: RATIS-1948 NettyClientStreamRpc.Connection.scheduleReconnect should check isClosed.
• relates to: RATIS-1946 PeerProxyMap: Stack trace may not be printed.