If my OpenFile returns error, second 'STOR' command in sequence fails #30

byrnedo · 2017-09-21T15:11:05Z

If I send multiple files, and the first returns an error I get
229 Entering Extended Passive Mode (|||41111|)
back as an error from my client. Is this an issue with the client or the server?
Is 229 Entering Extended Passive Mode (|||41111|) valid for a store response?
logs:

t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="220 Welcome, you're on dir /tmp/doc-service-ftp-test"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="FEAT\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="211- These are my features"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line=" UTF8"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line=" SIZE"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line=" MDTM"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line=" REST STREAM"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="211 end"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="USER foo\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="331 OK"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="PASS bar\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="230 Password ok, continue"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="TYPE I\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="200 Type set to binary"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="EPSV\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="229 Entering Extended Passive Mode (|||41077|)"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="STOR ../create1.txt\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="150 Using transfer connection"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP Transfer connection opened" action=ftp.transfer_open id=1 remoteAddr=127.0.0.1:47174 localAddr=127.0.0.1:41077
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="550 Requested path outside base directory"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="226 Closing transfer connection"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP Transfer connection closed" action=ftp.transfer_close id=1
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="EPSV\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="229 Entering Extended Passive Mode (|||41111|)"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=1 line="PASV\r\n"
t=2017-09-21T17:08:20+0200 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=1 line="227 Entering Passive Mode (127,0,1,1,180,93)"
	driver_test.go:93: Failed to save simple file: 229 Entering Extended Passive Mode (|||41111|)

The text was updated successfully, but these errors were encountered:

fclairamb · 2017-09-21T23:01:20Z

Thank you for submitting this.

The server is definitely not behaving correctly. It shouldn't start a data connection if it knows it's unable to write the file.

I will fix it

…ction. Fix for issue #30

fclairamb · 2017-09-21T23:22:03Z

This first fix seems to do the trick. I'll update it with some tests:

ftp> put ftpserver /tmp/test1.txt
local: ftpserver remote: /tmp/test1.txt
DBUG[09-22|01:16:41] FTP RECV                                 action=ftp.cmd_recv id=1 line="EPSV\r\n"
DBUG[09-22|01:16:41] FTP SEND                                 action=ftp.cmd_send id=1 line="229 Entering Extended Passive Mode (|||50348|)"
229 Entering Extended Passive Mode (|||50348|)
DBUG[09-22|01:16:41] FTP RECV                                 action=ftp.cmd_recv id=1 line="STOR /tmp/test1.txt\r\n"
DBUG[09-22|01:16:41] FTP SEND                                 action=ftp.cmd_send id=1 line="550 Could not open file: open /var/folders/vk/vgsfkf9975xfrc4_fk102g200000gn/T/ftpserver446543218/tmp/test1.txt: no such file or directory"
550 Could not open file: open /var/folders/vk/vgsfkf9975xfrc4_fk102g200000gn/T/ftpserver446543218/tmp/test1.txt: no such file or directory

byrnedo · 2017-09-22T06:37:24Z

Thanks for the super quick response!
Not sure I explained fully what was happening:

Referring to the test below:
In my OpenFile function I explicitly throw an error for the first case (relative root outside my base dir).

The second and third calls fail.
If I remove the first call, the second and third scenarios work..

Here's my test

func TestCreateFile(t *testing.T){

	srv := runServer(t)

	con := connect(t)

       // should and does throw an error
       if err := con.Stor("../create1.txt", strings.NewReader("test1")); err == nil {
		t.Fatal("Should not be able to make file outside of root")
	}

        // shouldn't throw but does
	if err := con.Stor("./create1.txt", strings.NewReader("test1")); err != nil {
		t.Fatal(errors.Wrap(err, "Failed to save simple file"))
	}

	if err := con.Stor("./create2.txt", strings.NewReader("test2")); err != nil {
		t.Fatal(errors.Wrap(err, "Failed to save simple file"))
	}

	srv.Stop()
}

My dirver OpenFile func:

// OpenFile opens a file in 3 possible modes: read, write, appending write (use appropriate flags)
func (driver *MainDriver) OpenFile(cc server.ClientContext, path string, flag int) (server.FileStream, error) {

	path = driver.baseDir + path
	if err := driver.validatePath(path); err != nil {
		return nil, err
	}

	// If we are writing and we are not in append mode, we should remove the file
	if (flag & os.O_WRONLY) != 0 {
		flag |= os.O_CREATE
		if (flag & os.O_APPEND) == 0 {
			os.Remove(path)
		}
	}

	return os.OpenFile(path, flag, 0666)
}

fclairamb · 2017-09-22T08:17:35Z

Yes I think it was clear enough,

basically what happened is that for some crazy reason we were:

Accepting the STOR command with a transfer connection (150)
Failing to open the file
Replying with an error message (550) - This is a second reply, which should never happen. Your client has no way to deal with that.
Closing the transfer connection (226)

When what we should have done is:

Failing to open the file
Replying an error message (550)

In other words, the fix simply tries to open the file before we start the transfer connection:
https://github.com/fclairamb/ftpserver/pull/32/files#diff-0c77d2426ef48618dcfde3946f0cd69eR22

byrnedo · 2017-09-22T10:17:54Z

Ah, I get you!

…

On 22 September 2017 at 10:17, Florent Clairambault < ***@***.***> wrote: Yes I think it was clear enough, basically what happened is that for some crazy reason we were: - Accepting the STOR command with a transfer connection (150) - Failing to open the file - Replying with an error message (550) - This is a *second* reply, which should never happen. Your client has no way to deal with that. - Closing the transfer connection (226) When what we should have done is: - Failing to open the file - Replying an error message (550) In other words, the fix simply tries to open the file *before* we start the transfer connection: https://github.com/fclairamb/ftpserver/pull/32/files#diff- 0c77d2426ef48618dcfde3946f0cd69eR22 — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <fclairamb/ftpserver#30 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFRbq7XpwwBSMDjBj-5q-jH6T1ot7dIyks5sk20igaJpZM4PfeQ9> .

byrnedo · 2017-09-22T10:24:10Z

Thanks for the quick work!

byrnedo · 2017-09-22T14:39:07Z

@fclairamb Any idea when you will merge and tag this?

fclairamb · 2017-09-22T15:33:04Z

I think tonight, when I'm home.

byrnedo · 2017-09-22T15:39:45Z

Sweet, thank you!

…

On 22 Sep 2017 5:33 pm, "Florent Clairambault" ***@***.***> wrote: I think tonight, when I'm home. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <fclairamb/ftpserver#30 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AFRbq541i-3jAsUHZaMftzxnCOX7oWUGks5sk9MwgaJpZM4PfeQ9> .

fclairamb · 2017-09-23T00:14:06Z

Came home a bit later than expected. I added a unit test, @asv and @mgenov had already approved it so I merged it.

All good for you ? If so, I think I'll make a tag v0.3 as it's a freaking big issue.

byrnedo · 2017-09-23T13:49:14Z

Looks good! Thanks for the quick turn-around on this.

byrnedo · 2017-09-27T13:41:38Z

So I tried out the new fix but I notice that I still can't make subsequent store requests.

I still get 229 Entering Extended Passive Mode.

I have a flow as follows:
Connect (Passive)
Login
Retrieve one file - > this works
Do some work
Store several files -> get 229 back as error
Quit

I checked and I'm on master's latest commit.

The redacted logs:

document_1            | t=2017-09-27T13:31:27+0000 lvl=info msg="FTP Client connected" action=ftp.connected id=3 src=192.168.96.27:42072 total=1
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="220 Welcome, you're on dir /data/cdn"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="FEAT\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="211- These are my features"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line=" UTF8"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line=" SIZE"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line=" MDTM"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line=" REST STREAM"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line=" MLSD"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="211 end"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="USER foobar\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="331 OK"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="PASS xxxxx\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="230 Password ok, continue"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="TYPE I\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="200 Type set to binary"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="EPSV\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="229 Entering Extended Passive Mode (|||38357|)"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="RETR labels/2017-09-27_13:31:27_734921092_sheet.pdf\r\n"
pdf_1                 | INFO: 2017/09/27 13:31:27 cutter.go:164: getting contents from /tmp/2017-09-27_13:31:27_734921092_sheet.pdf
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="150 Using transfer connection"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP Transfer connection opened" action=ftp.transfer_open id=3 remoteAddr=192.168.96.27:51170 localAddr=192.168.96.26:38357
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="226 Closing transfer connection"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP Transfer connection closed" action=ftp.transfer_close id=3
pdf_1                 | ERROR: 2017/09/27 13:31:27 cropworker.go:202: failed to send file to cdn 229 Entering Extended Passive Mode (|||42857|)
pdf_1                 | ERROR: 2017/09/27 13:31:27 cropworker.go:202: failed to send file to cdn 229 Entering Extended Passive Mode (|||41977|)
pdf_1                 | INFO: 2017/09/27 13:31:27 cropworker.go:96: worker: successfully processed job
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="EPSV\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="229 Entering Extended Passive Mode (|||42857|)"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="PASV\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="227 Entering Passive Mode (192,168,96,26,141,209)"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="EPSV\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="229 Entering Extended Passive Mode (|||41977|)"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="PASV\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="227 Entering Passive Mode (192,168,96,26,168,249)"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP RECV" action=ftp.cmd_recv id=3 line="QUIT\r\n"
document_1            | t=2017-09-27T13:31:27+0000 lvl=dbug msg="FTP SEND" action=ftp.cmd_send id=3 line="221 Goodbye"

byrnedo · 2017-09-27T14:29:16Z

Might have jumped the gun. This could be due to not closing my ftp client's response Reader before doing the Stor commands.

byrnedo · 2017-09-27T14:58:49Z

I think it was that, false alarm.

fclairamb · 2017-09-27T22:08:13Z

Interesting logs :) What is your "cropworker" doing ?

I'm quite interested by how people use this library. For me it is to offer a FTP access to google drive, which I offer with https://zoro.io (but the work isn't really finished around that one).

byrnedo · 2017-09-28T06:45:14Z

I had an internal service for fronting a cdn "bucket" which was using nats (https://nats.io/) for sending files to it. I changed it to ftp since sending files on the queue was a bad pattern. Instead of throwing a fully baked ftp on top I thought something like ftpserver was a better way since I potentially want more dynamic features in the future that we can integrate with our auth.

Cropworker is just cropping sections out of pdfs :) The files I'm sending back are those cropped images.

Nice idea with Zoro!

fclairamb · 2017-10-09T21:02:03Z

I created release v0.3 which contains a fix for that

fclairamb added the Bug label Sep 21, 2017

fclairamb self-assigned this Sep 21, 2017

fclairamb added a commit that referenced this issue Sep 21, 2017

Checking if we can write the file *before* opening the transfer conne…

f235d62

…ction. Fix for issue #30

fclairamb mentioned this issue Sep 21, 2017

Checking if we can write the file *before* opening the transfer connection #32

Merged

fclairamb closed this as completed Oct 9, 2017

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

If my OpenFile returns error, second 'STOR' command in sequence fails #30

If my OpenFile returns error, second 'STOR' command in sequence fails #30

byrnedo commented Sep 21, 2017

fclairamb commented Sep 21, 2017

fclairamb commented Sep 21, 2017

byrnedo commented Sep 22, 2017

fclairamb commented Sep 22, 2017

byrnedo commented Sep 22, 2017 via email

byrnedo commented Sep 22, 2017

byrnedo commented Sep 22, 2017

fclairamb commented Sep 22, 2017

byrnedo commented Sep 22, 2017 via email

fclairamb commented Sep 23, 2017 •

edited

Loading

byrnedo commented Sep 23, 2017

byrnedo commented Sep 27, 2017 •

edited

Loading

byrnedo commented Sep 27, 2017 •

edited

Loading

byrnedo commented Sep 27, 2017

fclairamb commented Sep 27, 2017 •

edited

Loading

byrnedo commented Sep 28, 2017

fclairamb commented Oct 9, 2017

If my OpenFile returns error, second 'STOR' command in sequence fails #30

If my OpenFile returns error, second 'STOR' command in sequence fails #30

Comments

byrnedo commented Sep 21, 2017

fclairamb commented Sep 21, 2017

fclairamb commented Sep 21, 2017

byrnedo commented Sep 22, 2017

fclairamb commented Sep 22, 2017

byrnedo commented Sep 22, 2017 via email

byrnedo commented Sep 22, 2017

byrnedo commented Sep 22, 2017

fclairamb commented Sep 22, 2017

byrnedo commented Sep 22, 2017 via email

fclairamb commented Sep 23, 2017 • edited Loading

byrnedo commented Sep 23, 2017

byrnedo commented Sep 27, 2017 • edited Loading

byrnedo commented Sep 27, 2017 • edited Loading

byrnedo commented Sep 27, 2017

fclairamb commented Sep 27, 2017 • edited Loading

byrnedo commented Sep 28, 2017

fclairamb commented Oct 9, 2017

fclairamb commented Sep 23, 2017 •

edited

Loading

byrnedo commented Sep 27, 2017 •

edited

Loading

byrnedo commented Sep 27, 2017 •

edited

Loading

fclairamb commented Sep 27, 2017 •

edited

Loading