hierynomus / smbj

Server Message Block (SMB2, SMB3) implementation in Java
Other
707 stars 180 forks source link

SocketTimeoutException: Read timed out #682

Open abhisheksardana opened 2 years ago

abhisheksardana commented 2 years ago

Hello,

We are dealing with around 164 GB of data and performing multiple operations. While doing so we are encountering below exception.

INFO: 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) at com.hierynomus.smbj.transport.PacketReader.readPacket(PacketReader.java:70) at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:48) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readFully(DirectTcpPacketReader.java:70) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readTcpHeader(DirectTcpPacketReader.java:59) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.doRead(DirectTcpPacketReader.java:48) ... 3 more Dec 9, 2021 7:00:19 AM com.hierynomus.smbj.session.Session logoff INFO: Logging off session 211113010530433 from host 10.31.73.208 Dec 9, 2021 7:00:19 AM com.hierynomus.protocol.commons.concurrent.Promise tryRetrieve SEVERE: << 116194 >> woke to: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out Dec 9, 2021 7:00:19 AM com.hierynomus.protocol.commons.concurrent.Promise tryRetrieve SEVERE: << 116193 >> woke to: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out Dec 9, 2021 7:00:19 AM com.hierynomus.smbj.session.Session logoff SEVERE: 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:78) at com.hierynomus.smbj.connection.Connection.send(Connection.java:297) at com.hierynomus.smbj.session.Session.send(Session.java:292) at com.hierynomus.smbj.share.TreeConnect.close(TreeConnect.java:66) at com.hierynomus.smbj.share.Share.close(Share.java:115) at com.hierynomus.smbj.session.Session.logoff(Session.java:233) at com.hierynomus.smbj.session.Session.close(Session.java:274) at com.hierynomus.smbj.connection.Connection.close(Connection.java:153) at com.hierynomus.smbj.connection.Connection.close(Connection.java:128) at com.hierynomus.smbj.connection.Connection.handleError(Connection.java:467) at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:54) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.SocketException: Connection reset by peer: socket write error at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111) at java.net.SocketOutputStream.write(SocketOutputStream.java:155) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport.write(DirectTcpTransport.java:75) ... 11 more

Socket timeout was set to default 0, so ideally it should wait indefinitely. Nothing much is there in server/client windows event logs.

This is how we created the client:

SmbConfig config = SmbConfig.builder() .withTimeout(300, TimeUnit.SECONDS) .build();

Do let me know in case you need more details around it.

hierynomus commented 2 years ago

Your problem is not the SocketTimeout, that is a consequence of the connection being closed already earlier. The lowest exception visible is:

Caused by: java.net.SocketException: Connection reset by peer: socket write error
at java.net.SocketOutputStream.socketWrite0(Native Method)
at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)
at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140)
at com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport.write(DirectTcpTransport.java:75)

There could be something else earlier which I cannot tell without additional logging. I would suggest you first correctly analyze your logging

abhisheksardana commented 2 years ago

Hi @hierynomus,

Thanks for your reply.

In the above error there are two different stack traces. As per my understanding, first the packetReader thread got timeout exception and after that it try to handle the error and close the session as part of it. To close the session a new request has been sent to server there SocketException(Connection reset by peer) has been received but the cause seems to be the SocketTimeoutException.

Here is the complete stack trace:

INFO: 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) at com.hierynomus.smbj.transport.PacketReader.readPacket(PacketReader.java:70) at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:48) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readFully(DirectTcpPacketReader.java:70) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readTcpHeader(DirectTcpPacketReader.java:59) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.doRead(DirectTcpPacketReader.java:48) ... 3 more Dec 9, 2021 7:00:19 AM com.hierynomus.smbj.session.Session logoff INFO: Logging off session 211113010530433 from host 10.31.73.208 Dec 9, 2021 7:00:19 AM com.hierynomus.protocol.commons.concurrent.Promise tryRetrieve SEVERE: << 116194 >> woke to: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out Dec 9, 2021 7:00:19 AM com.hierynomus.protocol.commons.concurrent.Promise tryRetrieve SEVERE: << 116193 >> woke to: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out Dec 9, 2021 7:00:19 AM com.hierynomus.smbj.session.Session logoff SEVERE: 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:78) at com.hierynomus.smbj.connection.Connection.send(Connection.java:297) at com.hierynomus.smbj.session.Session.send(Session.java:292) at com.hierynomus.smbj.share.TreeConnect.close(TreeConnect.java:66) at com.hierynomus.smbj.share.Share.close(Share.java:115) at com.hierynomus.smbj.session.Session.logoff(Session.java:233) at com.hierynomus.smbj.session.Session.close(Session.java:274) at com.hierynomus.smbj.connection.Connection.close(Connection.java:153) at com.hierynomus.smbj.connection.Connection.close(Connection.java:128) at com.hierynomus.smbj.connection.Connection.handleError(Connection.java:467) at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:54) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.SocketException: Connection reset by peer: socket write error at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111) at java.net.SocketOutputStream.write(SocketOutputStream.java:155) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport.write(DirectTcpTransport.java:75) ... 11 more Dec 9, 2021 7:00:19 AM com.hierynomus.protocol.commons.concurrent.Promise tryRetrieve SEVERE: << 116192 >> woke to: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out Dec 9, 2021 7:00:19 AM com.hierynomus.protocol.commons.concurrent.Promise tryRetrieve SEVERE: << 116191 >> woke to: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out Dec 9, 2021 7:00:19 AM com.symantec.dlp.util.cloud.MetricLogger logMetrics INFO: {DISCOVER.DOCUMENT_DOWNLOAD=18847, DISCOVER.globalSuccess=1, message=DOCUMENT_DOWNLOAD metric: } Dec 9, 2021 7:00:19 AM com.symantec.dlp.util.cloud.MetricLogger logMetrics INFO: {DISCOVER.DOCUMENT_DOWNLOAD=18806, DISCOVER.globalSuccess=1, message=DOCUMENT_DOWNLOAD metric: } Dec 9, 2021 7:00:19 AM com.hierynomus.smbj.session.Session logoff SEVERE: Caught exception while closing TreeConnect with id: 5 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:78) at com.hierynomus.smbj.connection.Connection.send(Connection.java:297) at com.hierynomus.smbj.session.Session.send(Session.java:292) at com.hierynomus.smbj.share.TreeConnect.close(TreeConnect.java:66) at com.hierynomus.smbj.share.Share.close(Share.java:115) at com.hierynomus.smbj.session.Session.logoff(Session.java:233) at com.hierynomus.smbj.session.Session.close(Session.java:274) at com.hierynomus.smbj.connection.Connection.close(Connection.java:153) at com.hierynomus.smbj.connection.Connection.close(Connection.java:128) at com.hierynomus.smbj.connection.Connection.handleError(Connection.java:467) at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:54) at java.lang.Thread.run(Thread.java:748) Caused by: java.net.SocketException: Connection reset by peer: socket write error at java.net.SocketOutputStream.socketWrite0(Native Method) at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111) at java.net.SocketOutputStream.write(SocketOutputStream.java:155) at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82) at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:140) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpTransport.write(DirectTcpTransport.java:75) ... 11 more Dec 9, 2021 7:00:19 AM com.symantec.dlp.util.cloud.MetricLogger logMetrics INFO: {DISCOVER.DOCUMENT_DOWNLOAD=19008, DISCOVER.globalSuccess=1, message=DOCUMENT_DOWNLOAD metric: } Dec 9, 2021 7:00:19 AM com.symantec.dlp.util.cloud.MetricLogger logMetrics INFO: {DISCOVER.DOCUMENT_DOWNLOAD=18898, DISCOVER.globalSuccess=1, message=DOCUMENT_DOWNLOAD metric: } Dec 9, 2021 7:00:19 AM com.symantec.dlp.util.retry.RetryHandler runWithRetry WARNING: Exception occurred during retry : com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.util.concurrent.ExecutionException: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out at com.hierynomus.smbj.share.Share.receive(Share.java:385) at com.hierynomus.smbj.share.Share.receive(Share.java:367) at com.hierynomus.smbj.share.Share.sendReceive(Share.java:351) at com.hierynomus.smbj.share.Share.createFile(Share.java:159) at com.hierynomus.smbj.share.DiskShare.createFileAndResolve(DiskShare.java:97) at com.hierynomus.smbj.share.DiskShare.resolveAndCreateFile(DiskShare.java:79) at com.hierynomus.smbj.share.DiskShare.open(DiskShare.java:66) at com.hierynomus.smbj.share.DiskShare.openFile(DiskShare.java:148) at com.symantec.dlp.discover2g.repositoryconnector.filesystem.smbj.SmbjContentReader.openFileWithReadAccess(SmbjContentReader.java:78) at com.symantec.dlp.discover2g.repositoryconnector.filesystem.smbj.SmbjContentReader.openFile(SmbjContentReader.java:71) at com.symantec.dlp.discover2g.repositoryconnector.filesystem.DocumentDownloader.downloadDocument(DocumentDownloader.java:99) at com.symantec.dlp.discover2g.repositoryconnector.filesystem.FileSystemContentFetcher$1.call(FileSystemContentFetcher.java:215) at com.symantec.dlp.discover2g.repositoryconnector.filesystem.FileSystemContentFetcher$1.call(FileSystemContentFetcher.java:203) at com.symantec.dlp.util.retry.RetryHandler.runWithRetry(RetryHandler.java:85) at com.symantec.dlp.discover2g.repositoryconnector.filesystem.FileSystemContentFetcher.initializeDocumentAttachments(FileSystemContentFetcher.java:135) at com.symantec.dlp.discover2g.repositoryconnector.filesystem.FileSystemContentFetcher.fetchContent(FileSystemContentFetcher.java:110) at com.symantec.dlp.discover2g.server.contentfetcher.tasks.ContentFetcherTaskHelper.fetchContentInternal(ContentFetcherTaskHelper.java:214) at com.symantec.dlp.discover2g.server.contentfetcher.tasks.ContentFetcherTaskHelper.fetchContentAndSubmitDetectionRequest(ContentFetcherTaskHelper.java:129) at com.symantec.dlp.discover2g.server.contentfetcher.tasks.FilesDownloaderAndDetectionSubmitterTask.run(FilesDownloaderAndDetectionSubmitterTask.java:80) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) Caused by: com.hierynomus.protocol.transport.TransportException: java.util.concurrent.ExecutionException: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out at com.hierynomus.protocol.transport.TransportException$1.wrap(TransportException.java:29) at com.hierynomus.protocol.transport.TransportException$1.wrap(TransportException.java:23) at com.hierynomus.protocol.commons.concurrent.Futures.get(Futures.java:43) at com.hierynomus.smbj.share.Share.receive(Share.java:380) ... 21 more Caused by: java.util.concurrent.ExecutionException: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out at com.hierynomus.protocol.commons.concurrent.PromiseBackedFuture.get(PromiseBackedFuture.java:60) at com.hierynomus.protocol.commons.concurrent.CancellableFuture.get(CancellableFuture.java:84) at com.hierynomus.protocol.commons.concurrent.Futures.get(Futures.java:38) ... 22 more Caused by: com.hierynomus.smbj.common.SMBRuntimeException: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out at com.hierynomus.smbj.common.SMBRuntimeException$1.wrap(SMBRuntimeException.java:27) at com.hierynomus.smbj.common.SMBRuntimeException$1.wrap(SMBRuntimeException.java:21) at com.hierynomus.protocol.commons.concurrent.Promise.deliverError(Promise.java:95) at com.hierynomus.smbj.connection.OutstandingRequests.handleError(OutstandingRequests.java:88) at com.hierynomus.smbj.connection.Connection.handleError(Connection.java:465) at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:54) ... 1 more Caused by: com.hierynomus.protocol.transport.TransportException: java.net.SocketTimeoutException: Read timed out at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.doRead(DirectTcpPacketReader.java:53) at com.hierynomus.smbj.transport.PacketReader.readPacket(PacketReader.java:70) at com.hierynomus.smbj.transport.PacketReader.run(PacketReader.java:48) ... 1 more Caused by: java.net.SocketTimeoutException: Read timed out at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:171) at java.net.SocketInputStream.read(SocketInputStream.java:141) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readFully(DirectTcpPacketReader.java:70) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.readTcpHeader(DirectTcpPacketReader.java:59) at com.hierynomus.smbj.transport.tcp.direct.DirectTcpPacketReader.doRead(DirectTcpPacketReader.java:48) ... 3 more

hierynomus commented 2 years ago

read timeouts mean that we expected a packet from the remote, but never got it. It could be that you're running into a race condition in SMBJ, or there is a problem with the server side of things. Hard to tell without any packet captures. Is it possible to get a pcap file?

abhisheksardana commented 2 years ago

Can you please elaborate this line more " It could be that you're running into a race condition in SMBJ" like why do you think so and what could be the possible cause of the race conditions. We will try to generate the pcap file and analyse them and will get back to you if required. Also, we have verified server logs but nothing seems to be there. There were 28 machines which were connected to the server and performing operations. This error has been seen only on one machine.

hierynomus commented 2 years ago

A pcap file would be the most surefire way of seeing what's happening and why there's a timeout...