search

AgNO3 / jcifs-ng

A cleaned-up and improved version of the jCIFS library
GNU Lesser General Public License v2.1
313 stars 104 forks source link

`Connection reset` when closing an output stream #151

Open boris-petrov opened 5 years ago

boris-petrov commented 5 years ago

This is the stacktrace:

19:28:06.828 [Transport0] WARN  jcifs.smb.SmbTransportImpl - Disconnecting transport while still in use Transport0[0.0.0.0<00>/192.168.88.182:445,state=5,signingEnforced=false,usage=3]: [SmbSession[credentials=guest,targetHost=192.168.88.182,targetDomain=null,uid=0,connectionState=2,usage=2]]

19:28:06.828 [Transport0] WARN  jcifs.smb.SmbSessionImpl - Logging off session while still in use SmbSession[credentials=guest,targetHost=192.168.88.182,targetDomain=null,uid=0,connectionState=3,usage=2]:[SmbTree[share=BORIS-TEST,service=null,tid=-500311919,inDfs=false,inDomainDfs=false,connectionState=2,usage=2]]

19:28:06.828 [Transport0] WARN  jcifs.smb.SmbTreeImpl - Disconnected tree while still in use SmbTree[share=BORIS-TEST,service=null,tid=-500311919,inDfs=false, inDomainDfs=false,connectionState=3,usage=2]

19:28:06.850 [Transport0] WARN  jcifs.smb.SmbSessionImpl - Failed to disconnect tree SmbTree[share=BORIS-TEST,service=null,tid=-500311919,inDfs=false,inDomainDfs=false,connectionState=3,usage=2]
jcifs.RuntimeCIFSException: Disconnected tree while still in use
    at jcifs.smb.SmbTreeImpl.treeDisconnect(SmbTreeImpl.java:826)
    at jcifs.smb.SmbSessionImpl.logoff(SmbSessionImpl.java:1129)
    at jcifs.smb.SmbTransportImpl.doDisconnect(SmbTransportImpl.java:760)
    at jcifs.util.transport.Transport.disconnect(Transport.java:693)
    at jcifs.util.transport.Transport.loop(Transport.java:478)
    at jcifs.util.transport.Transport.run(Transport.java:769)
    at java.base/java.lang.Thread.run(Thread.java:834)

19:28:06.851 [application-thread] WARN  jcifs.util.transport.Transport - sendrecv failed
jcifs.util.transport.TransportException: Transport0 error reading response to command=SMB2_WRITE,status=0,flags=0x0000,mid=1089,wordCount=0,byteCount=533
    at jcifs.util.transport.Transport.waitForResponses(Transport.java:351)
    at jcifs.util.transport.Transport.sendrecv(Transport.java:232)
    at jcifs.smb.SmbTransportImpl.sendrecv(SmbTransportImpl.java:1005)
    at jcifs.smb.SmbTransportImpl.send(SmbTransportImpl.java:1523)
    at jcifs.smb.SmbSessionImpl.send(SmbSessionImpl.java:409)
    at jcifs.smb.SmbTreeImpl.send(SmbTreeImpl.java:472)
    at jcifs.smb.SmbTreeConnection.send0(SmbTreeConnection.java:399)
    at jcifs.smb.SmbTreeConnection.send(SmbTreeConnection.java:314)
    at jcifs.smb.SmbTreeConnection.send(SmbTreeConnection.java:294)
    at jcifs.smb.SmbTreeHandleImpl.send(SmbTreeHandleImpl.java:130)
    at jcifs.smb.SmbTreeHandleImpl.send(SmbTreeHandleImpl.java:117)
    at jcifs.smb.SmbFileOutputStream.writeDirect(SmbFileOutputStream.java:322)
    at jcifs.smb.SmbFileOutputStream.write(SmbFileOutputStream.java:284)
    at java.base/java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:81)
    at java.base/java.io.BufferedOutputStream.flush(BufferedOutputStream.java:142)
    at org.apache.commons.vfs2.util.MonitorOutputStream.close(MonitorOutputStream.java:59)
    at org.apache.commons.vfs2.provider.DefaultFileContent$FileContentOutputStream.close(DefaultFileContent.java:642)
    ... application code
Caused by: java.net.SocketException: Connection reset
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:186)
    at java.base/java.net.SocketInputStream.read(SocketInputStream.java:140)
    at jcifs.util.transport.Transport.readn(Transport.java:70)
    at jcifs.smb.SmbTransportImpl.peekKey(SmbTransportImpl.java:808)
    at jcifs.util.transport.Transport.loop(Transport.java:420)
    at jcifs.util.transport.Transport.run(Transport.java:769)
    ... 1 common frames omitted

I think the stacktrace should be read from the bottom up - that is, the bottom error causes the warnings above it.

I'm using Apache Commons VFS (which shouldn't matter). As you see, I called close on it, it called flush on BufferedOutputStream which in turn called write on SmbFileOutputStream. And this blows up with java.net.SocketException: Connection reset for mysterious reasons to me. I've been debugging this for a while now, do you have any idea what I might be doing wrong? Is it possible that my application code somehow causes the socket to be closed before the write is complete? How is this possible?

mbechler commented 5 years ago

More likely the remote server is closing down the connection for some reason, possibly as a result of not liking something in the write request. A packet capture would be helpful to figure out what might go wrong there.

boris-petrov commented 5 years ago

Hi, thanks for the support! If by "packet capture" you mean something like a Wireshark dump, I think I have one. No idea if it is the right thing or if it contains the correct information but you can tell me if I did it wrong so I can try again.

samba-dump.zip

By the way, the Samba server I'm using is on a NAS - QNAP TS-453 Pro. Maybe they have a broken implementation or there is a bug in jcifs-ng?

mbechler commented 5 years ago

Thanks for the dump. The remote server is unexpectedly closing the connection after the last write request we send (packet 1437). I really don't see anything wrong with that request, so this really might be a (somewhat strange) server issue. Maybe the server logfiles do provider further information, or you could try upgrading the firmware.

boris-petrov commented 5 years ago

I've got another problem with the same NAS, not sure if it is related - when accessing a large file, it seems to take a very long time to download it. I can see in Wireshark a million requests like Read Request Len:8192 Off:88817664 - as far as I understand, jcifs-ng makes a bunch of requests for 8kb of data. Why is that? Why doesn't it request much more? This causes massive slowdowns.

mbechler commented 5 years ago

Most likely, the read size is limited by the buffer size you are giving it. Otherwise it may limited by the negotiated maximum size.

boris-petrov commented 5 years ago

I'm using jcifs-ng with Apache VFS, I don't think it does anything special for buffer sizes. What should I be looking for in Wireshark for the "negotiated maximum size"?

mbechler commented 5 years ago

The max read/write sizes can be found in the SMB2 Negotiate response received from the server in the beginning of a connection. But I would much rather assume that this is a buffer size issue somewhere. 8192 seems to be the default buffer size for the BufferedOutputStream, so likely something before that is doing IO with smaller sizes.

boris-petrov commented 5 years ago

OK, I was using Apache Tika to detect mime types and it actually copies an input stream locally by doing a Files.copy which internally does in.transferTo(out) which has a buffer of size 8192. So this is where this number came from... I'm not sure if this is a normal thing that the JDK does but if it is, doesn't that mean that jcifs-ng has to do some internal buffering? As right now if I have an SmbFileInputStream and do a transferTo to some output stream, the same performance problem will occur. Not sure how these things are supposed to work.

P.S. transferTo is a new method on InputStream from Java 9 if you're wondering.

mbechler commented 5 years ago

I'd really want to avoid adding buffering on the library side, this adds yet another memory copy and is totally unnecessary if used right. You could add a buffered stream wrapper around it.

This way around (SmbFileInputStream -> other OtherputStream) the behavior of the transferTo could be fixed by overriding the default implementation and using the correct buffersize I guess, but the other way around is out of our control.