Need to understand - com.hierynomus.smbj.session.Session.logoff:Line 193 - Caught exception while closing TreeConnect with id: 1 com.hierynomus.protocol.transport.TransportException: java.net.SocketException: Connection reset

[niravravalhighq]

Hi @hierynomus & @pepijnve ,
We have use SMBJ 0.5.0 library in UAT environment and we found below error on some frequent basis. The same we were not encounter in LOCAL environment. Can you please help me to understand this error?
Also is this critical error or this is generated due to I missed something in my code.
I have used below Code for closing resources of SMBJ

private void closeSMBJConnection(Connection connection, Session session) {
		try {
			if(session !=null){
				session.close();
			}
		} catch (Exception e) {
			// TODO Auto-generated catch block
			ExceptionUtilityHelper.accessExceptionStackTrace(e);
		}
		try {
			if(connection !=null){
				connection.close();
			}
		} catch (Exception e) {
			// TODO Auto-generated catch block
			ExceptionUtilityHelper.accessExceptionStackTrace(e);
		}
	}

Thanks.
Exception:
4/23/1810:49:30.328 AM | ERROR [uathqasg1] [2018-04-23T10:49:30,328] - com.hierynomus.smbj.session.Session.logoff:Line 193 - Caught exception while closing TreeConnect with id: 1 com.hierynomus.protocol.transport.TransportException: java.net.SocketException: Connection reset by peer: socket write error at com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport.write(DirectTcpTransport.java:77) ~[smbj-0.5.0.jar:?] at com.hierynomus.smbj.connection.Connection.send(Connection.java:252) ~[smbj-0.5.0.jar:?] at com.hierynomus.smbj.session.Session.send(Session.java:242) ~[smbj-0.5.0.jar:?] at com.hierynomus.smbj.share.TreeConnect.close(TreeConnect.java:61) ~[smbj-0.5.0.jar:?] at com.hierynomus.smbj.share.Share.close(Share.java:92) ~[smbj-0.5.0.jar:?] at com.hierynomus.smbj.session.Session.logoff(Session.java:191) [smbj-0.5.0.jar:?] at com.hierynomus.smbj.session.Session.close(Session.java:224) [smbj-0.5.0.jar:?] at com.hierynomus.smbj.connection.Connection.close(Connection.java:135) [smbj-0.5.0.jar:?] at com.hierynomus.smbj.connection.Connection.close(Connection.java:120) [smbj-0.5.0.jar:?] at com.hierynomus.smbj.connection.Connection.handleError(Connection.java:415) [smbj-0.5.0.jar:?] at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:53) [smbj-0.5.0.jar:?] at java.lang.Thread.run(Thread.java:748) [?:1.8.0_152] Caused by: java.net.SocketException: Connection reset by peer: socket write error at java.net.SocketOutputStream.socketWrite0(Native Method) ~[?:1.8.0_152] at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111) ~[?:1.8.0_152] at java.net.SocketOutputStream.write(SocketOutputStream.java:155) ~[?:1.8.0_152] at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) ~[?:1.8.0_152] at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) ~[?:1.8.0_152] at com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport.write(DirectTcpTransport.java:74) ~[smbj-0.5.0.jar:?] ... 11 moreCollapse

[hierynomus]

What is the server OS and version?

[harisingh-highq]

Hi @hierynomus
SMBJ library 0.5.0 throws error from below lines of code. So is it critical error because we found millions of error on daily basis in our UAT environment?

at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:53) [smbj-0.5.0.jar:?]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_152]

If it is not critical then please suggest us how to disable those error logs from SMBJ 0.5.0 library?

As per our understanding, SMBJ creates Packet Reader for xxx server thread for each connection
and above code will be called in every thread of Packet Reader for xxx server.

[pepijnve]

Could you test with a more recent version of the library and see if you still get the same problem?

[harisingh-highq]

Okay..We will try to check same with latest library 0.7.0 and will let you know

[niravravalhighq]

Hi. @pepijnve / @hierynomus ,
We have test file upload/download with SMBJ with new 0.7.0 Jar. And still same exception we found. Check below screen shot of log file.

Below two types of file server on which we do this testing and same exception we faced.

1. Windows File Server 2012
2. Windows File Server 2016

[harisingh-highq]

Hi @hierynomus / @pepijnve
We have replicated this issue in our local dev environment with simultaneous calls to SMBJ connection to one repository and we found stack trace same as above in log file.

And same time, we monitored JVM threads and found multiple packet reader threads are in running state and not stopping/releasing the threads.
Can you please help us to sort out this issue?

You can see attached JVM monitor file here for more details.

You can see attached stack trace here.

[harisingh-highq]

Hi @hierynomus / @pepijnve
I am very glad to inform you that this issue is resolved now.

Cause:- Actually we have used SMBJ connection code for different file operations(e.g. file upload/download/delete/rename etc.) in our product.
But we have not used try-with-resources for create connection code whereas we have used finally block to close the connection & session object explicitly

Earlier code

finally{ try { if(session !=null){ session.close(); } } catch (Exception e) { // TODO Auto-generated catch block ExceptionUtilityHelper.accessExceptionStackTrace(e); } try { if(connection !=null){ connection.close(); } } catch (Exception e) { // TODO Auto-generated catch block ExceptionUtilityHelper.accessExceptionStackTrace(e); } }
Replacement with try-with-resource and removed finally block as like below code

try(Connection connection = client.connect("fileserver1ind1.hqdev.india"))

I don't know why it behaves like as above described. Because as far as i understand try-with-resources and finally block close should behave the same.

[harisingh-highq]

Hi @neoxpert
Is this issue related to #365?

[mettuudaykumar]

@hierynomus please help us know if the issue is fixed ?

[araneolus]

In my case, the reason was that I had opened several connections to a Windows server in different Tasks.
For each "connect", a PacketReader was opened in the "com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader com.hierynomus.smbj.transport.PacketReader" class.

Starting PacketReader on thread: Packet Reader for XXXX

I had also set the sotimeout of the SMBClient to 2 minutes. What I then noticed was that the response packets to various requests occasionally ran into a timeout.
After I had established only one "com.hierynomus.smbj.connection.Connection" to the server (I solved this with a static ConcurrentHashMap with server name and port as key and a synchronised connect, new session, disconnect), this error disappeared and I could open and close SMB sessions and shares in several threads without this error occurring again. Unfortunately, I cannot answer why this is the case. I have not delved enough into the depths of smbj.

[hierynomus]

Different connection do not share anything underneath... From what you're writing, this sounds like a server-side problem where it mixes up the clients, because they receive a timeout when waiting for the response.

[araneolus]

Yes, it sounds crazy, but the counterpart is a Windows 10 PC, so it is not exotic and I have run the java program under Linux and Windows.
I will reduce my programme to the essentials. If the error occurs again, I can post my tests here.

[araneolus]

I have dump a part of the logfile with the perhaps important information. Look to connectTree and disconnectTree. It is always a pair of connectTree and disconnectTree, but at 13:53:34.055 (bold lines) I have two connects but only one disconnect for it. At the bottom you can see the Error Message. The disconnect for the diskshare of session 312277005762565 hangs.
I have configured 5 seconds soTimeout for the client to produce the error after a short time. I can set it to 5 minutes, the error will than come after 5 minutes.
If I work only with one connection to the same host and share, it works fine.
I have configured four connections to the same host and share and authentication.

13:53:33.694 [main] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 120 connectTree - Connecting to \w10-naber.alfa.de\temp on session 312277005762581
13:53:33.732 [main] DEBUG com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 226 disconnectTree - Notified of TreeDisconnected <<1>>
13:53:33.764 [main] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 120 connectTree - Connecting to \w10-naber.alfa.de\temp on session 312276938653809
13:53:33.771 [main] DEBUG com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 226 disconnectTree - Notified of TreeDisconnected <<1>>
13:53:33.954 [test2] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 120 connectTree - Connecting to \w10-naber.alfa.de\temp on session 312277005762573
13:53:33.999 [test2] DEBUG com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 226 disconnectTree - Notified of TreeDisconnected <<1>>
13:53:34.055 [test] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 120 connectTree - Connecting to \w10-naber.alfa.de\temp on session 312277005762565
13:53:34.072 [test] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 120 connectTree - Connecting to \w10-naber.alfa.de\temp on session 312277005762585
13:53:34.211 [test] DEBUG com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 226 disconnectTree - Notified of TreeDisconnected <<1>>
13:53:38.836 [RouteMaintenanceThread Maintenance SMB2FS] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 120 connectTree - Connecting to \w10-naber.alfa.de\temp on session 312277005762569
13:53:38.839 [RouteMaintenanceThread Maintenance SMB2FS] DEBUG com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 226 disconnectTree - Notified of TreeDisconnected <<1>>
13:53:38.852 [RouteMaintenanceThread Maintenance SMB2FS] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 120 connectTree - Connecting to \w10-naber.alfa.de\temp on session 312277005762601
13:53:38.855 [RouteMaintenanceThread Maintenance SMB2FS] DEBUG com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 226 disconnectTree - Notified of TreeDisconnected <<1>>
...
13:53:39.063 [Packet Reader for w10-naber.alfa.de] INFO com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader com.hierynomus.smbj.transport.PacketReader 53 run - PacketReader error, got exception.
com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out
at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.doRead(DirectTcpPacketReader.java:53) ~[smbj-0.11.5.jar:?]
at com.hierynomus.smbj.transport.PacketReader.readPacket(PacketReader.java:70) ~[smbj-0.11.5.jar:?]
at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:48) ~[smbj-0.11.5.jar:?]
at java.lang.Thread.run(Thread.java:748) ~[?:1.8.0_144]
Caused by: java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method) ~[?:1.8.0_144]
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) ~[?:1.8.0_144]
at java.net.SocketInputStream.read(SocketInputStream.java:171) ~[?:1.8.0_144]
at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:1.8.0_144]
at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readFully(DirectTcpPacketReader.java:70) ~[smbj-0.11.5.jar:?]
at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readTcpHeader(DirectTcpPacketReader.java:59) ~[smbj-0.11.5.jar:?]
at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.doRead(DirectTcpPacketReader.java:48) ~[smbj-0.11.5.jar:?]
... 3 more
13:53:39.076 [Packet Reader for w10-naber.alfa.de] INFO com.hierynomus.smbj.session.Session com.hierynomus.smbj.session.Session 233 logoff - Logging off session 312277005762565 from host w10-naber.alfa.de
13:53:39.076 [Packet Reader for w10-naber.alfa.de] DEBUG com.hierynomus.smbj.connection.Connection com.hierynomus.smbj.connection.Connection 226 send - Granted 1 (out of 512) credits to Encrypted[SMB2_TREE_DISCONNECT with message id << 5 >>]
13:53:39.076 [Packet Reader for w10-naber.alfa.de] DEBUG com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport 71 write - Writing packet Encrypted[SMB2_TREE_DISCONNECT with message id << 5 >>]
13:53:39.077 [Packet Reader for w10-naber.alfa.de] DEBUG com.hierynomus.protocol.commons.concurrent.Promise com.hierynomus.protocol.commons.concurrent.Promise 163 tryRetrieve - Awaiting << 5 >>

[araneolus]

Sometimes it helps to capature the packets with wireshark :-)
I have solved the problem, that I have declare the whole connect process as synchronized. So connection, and disconnection to the client, session and diskshare is now synchronized and voilà there is no Exception anymore.
I got still the Exception

19 Sep 2022 09:28:51.017- Session [Packet Reader for intellitune.sdz-medien.alfa-cloud.net] ERROR com.hierynomus.smbj.session.Session 238 logoff - Caught exception while closing TreeConnect with id: 1
com.hierynomus.protocol.transport.TransportException: java.util.concurrent.ExecutionException: com.hierynomus.smbj.common.SMBRuntimeException: java.util.concurrent.TimeoutException: Timeout expired

Perhaps you have to move up the lock at logoff() Function in the Session Class

   public void logoff() throws TransportException {
        try {
            logger.info("Logging off session {} from host {}", sessionId, connection.getRemoteHostname());
            nestedSessionsRwLock.writeLock().lock();
            for (Share share : treeConnectTable.getOpenTreeConnects()) {
                try {
                    share.close();
                } catch (IOException e) {
                    logger.error("Caught exception while closing TreeConnect with id: {}", share.getTreeConnect().getTreeId(), e);
                }
            }

          //  nestedSessionsRwLock.writeLock().lock();
            try {
            ...

[araneolus]

Forget my last post. I checked out the current sources, inserted debug messages in various places and recorded the packets using Wireshark. Unfortunately, the packets in question are encrypted, so the only way to find out whether the error is in the programme or whether there really is no response from the Windows system is to look at the number of packets sent and answered. After many tests I had to find out that with a small sotimeout and transactiontimeout at the smbclient the answer from Windows does not arrive. Only when I set these values very high did the error messages disappear. So smbj is doing everything right. Slow and steady wins the race.

[hierynomus]

Closing this ticket, it seems to be resolved.