New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

libcurl doesn't detect an FTP 426 response #405

Closed
booboo0706 opened this Issue Sep 2, 2015 · 11 comments

Comments

Projects
None yet
2 participants
@booboo0706

booboo0706 commented Sep 2, 2015

I'm encountering this problem while uploading files to a Filezilla FTP server.
The server responds with 150 to the STOR command, however the data connection is not available immediately and the server aborts connection by sending a 426 response back. This response is not caught by libcurl.
This problem is similar to the one already reported here:
http://sourceforge.net/p/curl/bugs/1436/

libcurl log:

Debug output from the previous transfer (upload test1.jpg):

incoming header: 226 Successfully transferred "/test1.jpg"
Connection #0 to host 192.168.0.100 left intact
transfer done ftp://192.168.0.100:21/test1.jpg (No error-0)
Expire cleared

Upload test2.jpg

STATE: INIT => CONNECT handle 0x7195e508; line 1090 (connection #-5000)
Found bundle for host 192.168.0.100: 0x7191ffc8
Re-using existing connection! (#0) with host 192.168.0.100
Connected to 192.168.0.100 (192.168.0.100) port 21 (#0)
STATE: CONNECT => DO handle 0x7195e508; line 1136 (connection #0)
Request has same path as previous transfer
DO phase starts
Hostname 192.168.0.90 was found in DNS cache
outgoing header: EPRT |1|192.168.0.90|41546|
FTP 0x7196fec0 (line 1342) state change from STOP to PORT
ftp_perform ends with SECONDARY: 1
STATE: DO => DOING handle 0x7195e508; line 1324 (connection #0)
incoming header: 200 Port command successful
Connect data stream actively
FTP 0x7196fec0 (line 2132) state change from PORT to STOP
DO phase is complete2
STATE: DOING => DO_MORE handle 0x7195e508; line 1413 (connection #0)
FTP 0x7196fec0 (line 3533) state change from STOP to STOR_TYPE
outgoing header: STOR test2.jpg
FTP 0x7196fec0 (line 1711) state change from STOR_TYPE to STOR
incoming header: 150 Opening data channel for file upload to server of "/test2.jpg"
FTP 0x7196fec0 (line 2447) state change from STOR to STOP
Preparing for accepting server on data port
Checking for server connect
Data conn was not available immediately
STATE: DO_MORE => DO_DONE handle 0x7195e508; line 1439 (connection #0)
STATE: DO_DONE => WAITPERFORM handle 0x7195e508; line 1464 (connection #0)
STATE: WAITPERFORM => PERFORM handle 0x7195e508; line 1474 (connection #0)
STATE: PERFORM => DONE handle 0x7195e508; line 1632 (connection #0)
Curl_done
Remembering we are in dir ""
Connection #0 to host 192.168.0.100 left intact
transfer done ftp://192.168.0.100:21/test2.jpg (No error-0)

Network trace:
220-FileZilla Server 0.9.53 beta
220-written by Tim Kosse (tim.kosse@filezilla-project.org)
220 Please visit https://filezilla-project.org/
USER test
331 Password required for test
PASS test
230 Logged on
PWD
257 "/" is current directory.
EPRT |1|192.168.0.90|41432|
200 Port command successful
TYPE I
200 Type set to I
STOR test1_00121.jpg
150 Opening data channel for file upload to server of "/test1_00121.jpg"
226 Successfully transferred "/test1_00121.jpg"
EPRT |1|192.168.0.90|55615|
200 Port command successful
STOR test1_00122.jpg
150 Opening data channel for file upload to server of "/test1_00122.jpg"
226 Successfully transferred "/test1_00122.jpg"
EPRT |1|192.168.0.90|39864|
200 Port command successful
STOR test1_00123.jpg
150 Opening data channel for file upload to server of "/test1_00123.jpg"
226 Successfully transferred "/test1_00123.jpg"
EPRT |1|192.168.0.90|44857|
200 Port command successful
STOR test1_00124.jpg
150 Opening data channel for file upload to server of "/test1_00124.jpg"
226 Successfully transferred "/test1_00124.jpg"
EPRT |1|192.168.0.90|34222|
200 Port command successful
STOR test1_00125.jpg
150 Opening data channel for file upload to server of "/test1_00125.jpg"
426 Connection closed; aborted transfer of "/test1_00125.jpg"
QUIT
221 Goodbye

@booboo0706

This comment has been minimized.

booboo0706 commented Sep 3, 2015

Probably, an additional check for the "wait_data_conn" flag should be done in the ftp_multi_statemach function:

diff --git a/lib/ftp.c b/lib/ftp.c
index 7b7e113..15da5dc 100644
--- a/lib/ftp.c
+++ b/lib/ftp.c
@@ -3148,7 +3148,8 @@ static CURLcode ftp_multi_statemach(struct connectdata conn,
/
Check for the state outside of the Curl_socket_ready() return code checks
since at times we are in fact already in this state when this function
gets called. */

  • *done = (ftpc->state == FTP_STOP) ? TRUE : FALSE;
  • *done = (ftpc->state == FTP_STOP && ftpc->wait_data_conn != TRUE) ?
  • TRUE : FALSE;

return result;
}

I'm not sure if this is the proper solution to this problem.

@bagder

This comment has been minimized.

Member

bagder commented Sep 3, 2015

It makes your test case work at least I presume?

@bagder bagder self-assigned this Sep 3, 2015

@bagder

This comment has been minimized.

Member

bagder commented Sep 3, 2015

Test 591 seems very similar to your case but works fine for me. I suspect due to timing or similar.

ftp_do_more() really makes an effort already to not "complete" if ftpc->wait_data_conn is set TRUE. Any chance you can either single-step through that with a debugger or add some printf()s or something to help us understand which code path it takes it it returns with complete set TRUE when ftpc->wait_data_conn is also true?

@bagder bagder added the FTP label Sep 3, 2015

@booboo0706

This comment has been minimized.

booboo0706 commented Sep 4, 2015

I guess it's a timing issue. It's not easy to reproduce the problem.

Here comes more debug output with some explanations:

Connect data stream actively
FTP 0x75792bc0 (line 2132) state change from PORT to STOP
DO phase is complete2
STATE: DOING => DO_MORE handle 0x7573a008; line 1416 (connection #0)
When we are connected, DO MORE and then go DO_DO (multi_runsingle(), multi.c, line 1427)
FTP-DO-MORE called (ftp_do_more() ftp.c, line 3646)
FTP-DO-MORE: a transfer is about to take place (ftp_do_more(), ftp.c, line 3699)
FTP-DO-MORE: set_upload (ftp_do_more(), ftp.c, line 3721)
FTP 0x75792bc0 (line 3533) state change from STOP to STOR_TYPE
FTP 0x75792bc0 (line 1711) state change from STOR_TYPE to STOR
FTP 0x75792bc0 (line 2447) state change from STOR to STOP
Preparing for accepting server on data port
Checking for server connect
Data conn was not available immediately <===== here wait_data_conn is set to TRUE for the first time, but ftp_multi_statematch() doesn't check the flag and initializes the done flag to TRUE
We have control (multi_runsingle (), multi.c, line 1436)
STATE: DO_MORE => DO_DONE handle 0x7573a008; line 1444 (connection #0)
STATE: DO_DONE => WAITPERFORM handle 0x7573a008; line 1469 (connection #0)

STATE: WAITPERFORM => PERFORM handle 0x7573a008; line 1479 (connection #0)
STATE: PERFORM => DONE handle 0x7573a008; line 1637 (connection #0)
Curl_done
Remembering we are in dir ""
Connection #0 to host 192.168.0.100 left intact
transfer done ftp://192.168.0.100:21/test1_03300.jpg (No error-0)

@booboo0706

This comment has been minimized.

booboo0706 commented Sep 4, 2015

Just summarizing:
"else if(data->set.upload)" block doesn't check for wait_data_conn and I think it's a problem, or maybe we shouldn't execute this part of code at all, in this case.

@bagder

This comment has been minimized.

Member

bagder commented Sep 6, 2015

"else if(data->set.upload)" block doesn't check for wait_data_conn and I think it's a problem

Really? Because the if() just before this else checks for wait_data_conn and I figure that should be enough. Isn't it?

Also, you mentioned "ftp_multi_statematch() doesn't check the flag and initializes the done flag to TRUE", but isn't that driven from within ftp_do_more() ? If so, it checks the wait_data_conn flag after the multi_statemach function returns. What am I missing?

@booboo0706

This comment has been minimized.

booboo0706 commented Sep 7, 2015

It's correct, that the if() just before the else checks for wait_data_conn, however at that moment this flag is not set to TRUE so the "else if" is executed and we enter ftp_multi_statemach() (line 3726). When the ftp_muliti_statemach returns, *completep is TRUE and wait_data_conn is TRUE.

@bagder

This comment has been minimized.

Member

bagder commented Sep 7, 2015

Ah, ok. So would something like this fix it?

diff --git a/lib/ftp.c b/lib/ftp.c
index 7b7e113..2351638 100644
--- a/lib/ftp.c
+++ b/lib/ftp.c
@@ -3721,11 +3721,17 @@ static CURLcode ftp_do_more(struct connectdata *conn, int *completep)
       result = ftp_nb_type(conn, data->set.prefer_ascii, FTP_STOR_TYPE);
       if(result)
         return result;

       result = ftp_multi_statemach(conn, &complete);
-      *completep = (int)complete;
+      if(ftpc->wait_data_conn)
+        /* if we reach the end of the FTP state machine here, *complete will be
+           TRUE but so is ftpc->wait_data_conn, which says we need to wait for
+           the data connection and therefore we're not actually complete */
+        *completep = 0;
+      else
+        *completep = (int)complete;
     }
     else {
       /* download */
       ftp->downloadsize = -1; /* unknown as of yet */

@booboo0706

This comment has been minimized.

booboo0706 commented Sep 7, 2015

Yes or the check of the wait_data_conn flag could be done in ftp_multi_statemach as suggested in my patch above.
Thanks!

@bagder

This comment has been minimized.

Member

bagder commented Sep 7, 2015

Right, I just think my version here was slightly more conservative as I don't feel fully confident that putting it in the ftp_multi_statemach function doesn't have any drawbacks or side-effects.

@booboo0706

This comment has been minimized.

booboo0706 commented Sep 8, 2015

Ok, I understand. Will you commit your fix? Thanks for your help.

@bagder bagder closed this in 2762017 Sep 8, 2015

jgsogo added a commit to jgsogo/curl that referenced this issue Oct 19, 2015

FTP: do_more: add check for wait_data_conn in upload case
In some timing-dependnt cases when a 4xx response immediately followed
after a 150 when a STOR was issued, this function would wrongly return
'complete == true' while 'wait_data_conn' was still set.

Closes curl#405

Reported-by: Patricia Muscalu

@lock lock bot locked as resolved and limited conversation to collaborators May 7, 2018

Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.