search

FileSysOrg / fileServersNG-v5

Replacement Alfresco file servers subsystem using the JFileServer code
1 stars 2 forks source link

java.nio.channels.ClosedChannelException #2

Open hi-ko opened 4 years ago

hi-ko commented 4 years ago

In production we see all the time following error pattern. How could we track this down and how to fix this?

 2020-09-29 08:30:44,075  DEBUG [org.alfresco.fileServersNG] [SMBConnectionsHandler] [SMB] Created session T12214
 2020-09-29 08:30:44,075  DEBUG [org.alfresco.fileServersNG] [SMBConnectionsHandler] [SMB] Connection from /192.168.233.86:52268, handler=[SMB,TCP-SMB,ALL:1445], sess=T12214
 2020-09-29 08:30:44,075  DEBUG [org.alfresco.fileServersNG] [SMBConnectionsHandler] [SMB] Waiting for new connection ...
 2020-09-29 08:30:44,075  DEBUG [org.alfresco.fileServersNG] [SMBRequestHandler_2] [SMB] Register session with request handler, handler=SMBRequestHandler_2, sess=T12214
 2020-09-29 08:30:44,075  DEBUG [org.alfresco.fileServersNG] [FileSrvWorker16] [SMB] Closed session 12214, sessions=50
 2020-09-29 08:30:44,076  DEBUG [org.alfresco.fileServersNG] [FileSrvWorker16] Error during packet receive, closing session sess=T12214, addr=192.168.233.86 ex=null
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16] java.nio.channels.ClosedChannelException
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16]  at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:257)
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16]  at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:300)
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16]  at org.filesys.smb.server.nio.ChannelPacketHandler.readBytes(ChannelPacketHandler.java:109)
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16]  at org.filesys.smb.server.nio.TcpipSMBChannelHandler.readPacket(TcpipSMBChannelHandler.java:61)
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16]  at org.filesys.smb.server.nio.NIOSMBThreadRequest.runRequest(NIOSMBThreadRequest.java:82)
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16]  at org.filesys.server.thread.ThreadRequestPool$ThreadWorker.run(ThreadRequestPool.java:136)
 2020-09-29 08:30:44,076  ERROR [org.alfresco.fileServersNG] [FileSrvWorker16]  at java.lang.Thread.run(Thread.java:748)
 2020-09-29 08:30:44,076  DEBUG [org.alfresco.fileServersNG] [FileSrvWorker16] [SMB] Closed session 12214, sessions=50
 2020-09-29 08:30:44,079  DEBUG [org.alfresco.fileServersNG] [SMBConnectionsHandler] [SMB] Created session T12215
 2020-09-29 08:30:44,079  DEBUG [org.alfresco.fileServersNG] [SMBConnectionsHandler] [SMB] Connection from /192.168.233.86:52269, handler=[SMB,TCP-SMB,ALL:1445], sess=T12215
 2020-09-29 08:30:44,079  DEBUG [org.alfresco.fileServersNG] [SMBConnectionsHandler] [SMB] Waiting for new connection ...
 2020-09-29 08:30:44,079  DEBUG [org.alfresco.fileServersNG] [SMBRequestHandler_2] [SMB] Register session with request handler, handler=SMBRequestHandler_2, sess=T12215
 2020-09-29 08:30:44,079  DEBUG [org.alfresco.fileServersNG] [FileSrvWorker23] [SMB] Closed session 12215, sessions=50
 2020-09-29 08:30:44,079  DEBUG [org.alfresco.fileServersNG] [FileSrvWorker23] Error during packet receive, closing session sess=T12215, addr=192.168.233.86 ex=null
 2020-09-29 08:30:44,079  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23] java.nio.channels.ClosedChannelException
 2020-09-29 08:30:44,080  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23]  at sun.nio.ch.SocketChannelImpl.ensureReadOpen(SocketChannelImpl.java:257)
 2020-09-29 08:30:44,080  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23]  at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:300)
 2020-09-29 08:30:44,080  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23]  at org.filesys.smb.server.nio.ChannelPacketHandler.readBytes(ChannelPacketHandler.java:109)
 2020-09-29 08:30:44,080  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23]  at org.filesys.smb.server.nio.TcpipSMBChannelHandler.readPacket(TcpipSMBChannelHandler.java:61)
 2020-09-29 08:30:44,080  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23]  at org.filesys.smb.server.nio.NIOSMBThreadRequest.runRequest(NIOSMBThreadRequest.java:82)
 2020-09-29 08:30:44,080  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23]  at org.filesys.server.thread.ThreadRequestPool$ThreadWorker.run(ThreadRequestPool.java:136)
 2020-09-29 08:30:44,080  ERROR [org.alfresco.fileServersNG] [FileSrvWorker23]  at java.lang.Thread.run(Thread.java:748)
 2020-09-29 08:30:44,080  DEBUG [org.alfresco.fileServersNG] [FileSrvWorker23] [SMB] Closed session 12215, sessions=50
FileSysOrg commented 4 years ago

These errors are caused by the client closing the socket rather than shutting down the session cleanly, which seems to happen more often with newer clients.

You will see these messages if you have the 'Socket' sessionDebug flag set. The simplest option is to switch off that debug flag, via the smb.sessionDebug property in alfresco-global.properties.

I'll have a look into filtering out that exception. That code has been the same for a long time, it's in the original Alfresco-JLAN code, there is a catch all in the NIO based request handler, you just don't see it with Alfresco-JLAN because the debug flag is off by default.

hi-ko commented 4 years ago

The ERROR should be a warning then since it is not an ERROR. Checking client by client pointed out that these users didn't reboot since migration to fileServersNG. Windows seems not to support switching the smb version on reconnect. After rebooting all these clients reduced at least these ERRORS from thousands to some hundreds a day

FileSysOrg commented 4 years ago

I've put a filter into the code now so you should not see those errors again, it should be in the next fileServersNG release.