Race condition / Concurrency problem on Fileread?

[sandreas]

Hey,

i noticed a strange behavior of my sftp server when downloading files: At random intervals the Download gets "-stalled-" and the server blocks one download permanently. Most of the time this happens with bigger files (>1MB), but sometimes smaller files run into that error, too. It seems to be completely random...

It also happens on Windows and MacOS at random progress (5%, 90%, event 100%), so OS seems to be irrelevant, but just for the sake of completeness my system specs:

MacBook Pro Early 2015, MacOS Sierra 10.12.6

Can someone reproduce this?
What could be the problem?

Code Sample:
https://github.com/sandreas/sftp/tree/race-condition/examples/request-server-simple

To get the sample:

git clone https://github.com/sandreas/sftp
cd sftp/
git checkout race-condition

# run sftp server, provide the files in /path/with/files via sftp on port 2022
# use a directory with at least 5 files and a few subdirectories
go run examples/request-server-simple/main.go --base-path="/path/with/files"

Now sftp is used in another Terminal:

# user: test, password: test
sftp -P 2022 test@localhost # password: test

# get all contents of the sftp, first time often works as expected
get -r *
# again, may work
get -r *
# ... try again, till suddenly one of the file downloads gets stalled (see attached screenshot)
get -r *

[sandreas]

Update: It seems that in this piece of code
request.go, fileget :

	if err != nil && (err != io.EOF || n == 0) {
		return nil, err
	}

possibly returns an error. If an error is returned, the whole current connection is stalled. Something seems to be wrong with the error handling in
request-server.go, handle
which wraps a go error into an ssh response packet.

Seems that os.Open as ReaderAt blocks the server in some cases...

Help appreciated!

[eikenb]

Thanks for the bug report and the great sample code. I've been able to reproduce the issue and am looking into it.

[eikenb]

The packet manager code was meant to address this, along with the ordering problems some clients have, and it does but only for writes. Reads still have a race with those last couple packets. The error occurs when the last packet that returns the EOF gets completely processed before the 2nd to last packet even gets registered with the packet manager. There is an extra channel/select in there that could allow for the race.

I'm not 100% as I haven't fixed it yet, but this is my best diagnosis for now.

[sandreas]

Thank you, this is a good hint. In the next days i will experiment a bit with the channels, but my concurrency knowledge is not as good. If i find a solution i will let you know or make a pull request. Let me know, if i can help otherwise and feel free to use my example code for your examples. The pathMapper has a test in my repo: https://github.com/sandreas/graft/tree/master/sftpd

[eikenb]

https://github.com/pkg/sftp/blob/master/packet-manager.go#L102

The select statement over the 2 channels in that 'controller' method is the one that I think allows for the race. My first test will be to just put locks on the incoming/outgoing slices and move the logic from the select up into the incomingPacket() and readyPacket() further up in that same file.

At first blush it seems like it should work. But I need to run it though the tests and make sure it doesn't hurt performance. Trying to get to it today, but so far work has me busy on other tasks.

[eikenb]

I'm not sure if that is it now. The locks helped but didn't really seem to be the answer as it was hard to get everything locked so there were no data races without changing quite a bit and it seemed to only reduce the chances instead of eliminate them (ie. just made the race harder).

So back to the original code and reviewing debug output I found that in each case of the stall an outgoing packet is duplicated somehow. It looks like it re-sends the previous outgoing packet instead of the correct one. So this seems like a promising lead that I will be working to track down.

You can see this if you uncomment the 2 debug() lines in maybeSendPacket() and outfilter and run w/ the debug tag. It will look something like this...

Watch packet with id: 14

2017/08/19 12:24:49 incoming id: 14
2017/08/19 12:24:49 break! -- outgoing: 0; incoming: 1
2017/08/19 12:24:49 incoming id: 15
2017/08/19 12:24:49 break! -- outgoing: 0; incoming: 2
2017/08/19 12:24:49 Fileread:  Filepath:  /medici-money.jpg , Target:   , Method:  Get
2017/08/19 12:24:49 Fileread:  Filepath:  /medici-money.jpg , Target:   , Method:  Get
2017/08/19 12:24:49 outgoing pkt: 14
2017/08/19 12:24:49 incoming: [14 15]
2017/08/19 12:24:49 outgoing: [14]

So here 14 should be done. It's incoming packet was matched with an outgoing.

2017/08/19 12:24:49 statusFromError: error is *errors.errorString &errors.errorString{s:"EOF"}
2017/08/19 12:24:49 break! -- outgoing: 0; incoming: 1
2017/08/19 12:24:49 outgoing pkt: 14

But wait. Here is another outgoing 14 and looking below there is never an outgoing packet with id 15.

2017/08/19 12:24:49 incoming: [15]
2017/08/19 12:24:49 outgoing: [14]
2017/08/19 12:24:49 Fileread:  Filepath:  /medici-money.jpg , Target:   , Method:  Get
2017/08/19 12:24:49 statusFromError: error is *errors.errorString &errors.errorString{s:"EOF"}
2017/08/19 12:24:49 incoming id: 16
2017/08/19 12:24:49 incoming: [15 16]
2017/08/19 12:24:49 outgoing: [14]
2017/08/19 12:24:49 outgoing pkt: 16
2017/08/19 12:24:49 incoming: [15 16]
2017/08/19 12:24:49 outgoing: [14 16]

Here it is stuck. It never got a match for the packet w/ id 14 in the outgoing slice and it has stopped getting new packets. Stalled.

[eikenb]

99% sure I've found the problem and am working on the fix.

[sandreas]

Great. Nice to hear that you found it, I would have needed much longer. Phew, this one was hard :-)

[eikenb]

Fixed it. To late to explain or clean it up for commit tonight. Will try to get it done tomorrow.

[sandreas]

kudos

[eikenb]

About to push the fix. Here's the somewhat wordy commit message...

Fix #195 Handler wrappers deal with errors

TLDR; have the Handler wrappers generate the response packets for the
errors instead of returning the errors.

Errors from the handers was returned up the stack to the request-server
handler call. In cases of errors the packet for the error was then
generated using the passed in packet (the incoming packet).

For file read/write/list operations the incoming packet data (includeing
ID) is put in a queue/channel so that it can be handled by the same file
handling code returned by the handler.

Due to gorouting scheduling, in some cases the packets in the channel
won't line up with the incoming packets. That is the worker that took an
incoming packet with one ID might respond with a packet with a different
ID. This doesn't matter as the reply order of packets doesn't matter.

BUT when this response packet that doesn't match IDs with the incoming packet
system returns an error, it uses the incoming packets ID to generate the
error packet. So the error response would use that ID and the packet
from the queue, once processed, would also use that ID (because on
success  it uses the ID from the packet in the queue).

This patch fixes the issue by having the code that works with the
packets, either incoming or from the queue, generate the error packet.
So there is no chance of them getting out of sync.

[sandreas]

Thank you very much, John :-) Due to a server crash i can't test it atm, but next week i will...