scripting FTP put file is not successful on server side :: Support Forum

dudekjar
Joined:: 2014-04-03
Posts:: 4

scripting FTP put file is not successful on server side

2014-04-03 12:59

Hi,

I found some strange behavior for some kind of FTP server. When I upload file via GUI everything is OK but via scripting it fail on server - Interupted and script itself return success.

Winscp version: 5.5.2(Build 4130)
WinSCPnet.dll version: 1.1.5.4130, product version 5.5.2.0

I'm using default example script https://winscp.net/eng/docs/library_powershell#example

If some other information is needed please let me know. I'll add as much as I can.

GUI log:
220 Welcome to Synchrony Gateway FTP server
USER ***
331 Send password please
PASS ***
230 User logged in, proceed
SYST
215 UNIX XFB/Gateway
FEAT
211-Extensions supported
211- SIZE
211- MDTM
211- AUTH TLS
211- PBSZ
211- PROT
211 End of feat command response
PWD
257 "/" is current directory.
CWD /test
250 Requested file action okay, completed
PWD
257 "/test" is current directory.
TYPE A
200 Command okay
PASV
227 Entering passive mode (*,*,*,*,*,*).
LIST -a
125 List started
226 List completed
TYPE A
200 Command okay
PASV
227 Entering passive mode (*,*,*,*,*,*).
LIST
125 List started
226 List completed
TYPE I
200 Command okay
PASV
227 Entering passive mode (*,*,*,*,*,*).
STOR test.txt
125 Start receiving 's691515.test.txt', remote file is: test.txt
226 Closing data connection (network bytes 34/file bytes 34)
TYPE A
200 Command okay
PASV
227 Entering passive mode (*,*,*,*,*,*).
LIST
125 List started
226 List completed

Script log:
220 Welcome to Synchrony Gateway FTP server
USER ***
331 Send password please
PASS ***
230 User logged in, proceed
SYST
215 UNIX XFB/Gateway
FEAT
211-Extensions supported
211- SIZE
211- MDTM
211- AUTH TLS
211- PBSZ
211- PROT
211 End of feat command response
PWD
257 "/" is current directory.
TYPE A
200 Command okay
PASV
227 Entering passive mode (*,*,*,*,*,*).
LIST
125 List started
226 List completed
TYPE I
200 Command okay
PASV
227 Entering passive mode (*,*,*,*,*,*).
STOR test
125 Start receiving 's691516.test', remote file is: test
226 Closing data connection (network bytes 34/file bytes 34)[url][/url]

running script + output:
powershell.exe -ExecutionPolicy Unrestricted -File upload.ps1
Upload of test.txt succeeded

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,442
Location:: Prague, Czechia

Re: scripting FTP put file is not successful on server side

2014-04-03

Sorry, I do not understand what fails. There's no error in the log. Do you mean the transfer finishes seemingly successfully, but the file is not complete?

Reply with quote

dudekjar
Joined:: 2014-04-03
Posts:: 4

Re: scripting FTP put file is not successful on server side

2014-04-03 23:29

Hi Martin,

FTP script client think that transfer is successful, but FTP server think, that transfer is not complete. This is most probably caused by script don't wait for 200 Command okay and end session immediately after server (or client) send 226 Closing data. Some incompatibility for that FTP server?

Here is server log example

Transfer interrupted - using scripting

23:43:09 230 FTP   I RECV_BEG  FTP_01(22061) [691980] Start receiving ftp file: test.txt
23:43:09 231 FTP   I RECV_BEG  FTP_01(22061) [691980] Start receiving file: /tmp/F0691980
23:43:09 103 NET   I CONN_RESP (159554:159558) incoming connection response     [resp_add="*.*.*.*/60435"]
23:43:09 101 FTP   I TRACE     Prot trace for: FTP_01 (22061 ) req:Read  len:34     Prot:FTP <- R FTP_01 22061:22061
23:43:09 101 FTP   I TRACE       0000  54657374 0d0a5465 73740d0a 54657374 [Test..Test..Test]
23:43:09 106 NET   I DISC_IND  (159554:159558) disconnection indication         [reason="Error 0 (0x0)"] [origin="0"]
23:43:09 101 FTP   I TRACE     Prot trace for: FTP_01 (22061 ) req:Write len:60     Prot:FTP <- S FTP_01 22061
23:43:09 101 FTP   I TRACE       0000  32323620 436c6f73 696e6720 64617461 [226 Closing data]
23:43:10 106 NET   I DISC_IND  (159554) disconnection indication         [reason="Error 0 (0x0)"] [origin="0"]
23:43:10 236 FTP   E RECV_ERR  FTP_01(22061) [691980] Error receiving (state I) ftp file: test.txt
23:43:10 237 FTP   E RECV_ERR  FTP_01(22061) [691980] Error receiving (state I) file: /tmp/F0691980
23:43:10 011 SUP   W ABORT_ID  FTP_01(46159405) connection abort indication: reason="0, No error" /prot.diag=226 / error=0

Transfer success - using WinSCP GUI

23:43:29 230 FTP   I RECV_BEG  FTP_01(22062) [691981] Start receiving ftp file: test.txt
23:43:29 231 FTP   I RECV_BEG  FTP_01(22062) [691981] Start receiving file: /tmp/F0691981
23:43:29 103 NET   I CONN_RESP (159561:159568) incoming connection response     [resp_add="*.*.*.*/60439"]
23:43:29 101 FTP   I TRACE     Prot trace for: FTP_01 (22062 ) req:Read  len:34     Prot:FTP <- R FTP_01 22062:22062
23:43:29 101 FTP   I TRACE       0000  54657374 0d0a5465 73740d0a 54657374 [Test..Test..Test]
23:43:29 106 NET   I DISC_IND  (159561:159568) disconnection indication         [reason="Error 0 (0x0)"] [origin="0"]
23:43:29 101 FTP   I TRACE     Prot trace for: FTP_01 (22062 ) req:Write len:60     Prot:FTP <- S FTP_01 22062
23:43:29 101 FTP   I TRACE       0000  32323620 436c6f73 696e6720 64617461 [226 Closing data]
23:43:29 101 FTP   I TRACE     Prot trace for: FTP_01 (22062 ) req:Read  len:6      Prot:FTP <- R FTP_01 22062
23:43:29 101 FTP   I TRACE       0000  54595045 2041                       [TYPE A]
23:43:29 234 FTP   I RECV_END  FTP_01(22062) [691981] End receiving ftp file: test.txt
23:43:29 235 FTP   I RECV_END  FTP_01(22062) [691981] End receiving file: /tmp/F0691981
23:43:29 101 FTP   I TRACE     Prot trace for: FTP_01 (22062 ) req:Write len:16     Prot:FTP <- S FTP_01 22062
23:43:29 101 FTP   I TRACE       0000  32303020 436f6d6d 616e6420 6f6b6179 [200 Command okay]

Last edited by dudekjar on 2014-04-09 12:09; edited 1 time in total

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,442
Location:: Prague, Czechia

Re: scripting FTP put file is not successful on server side

2014-04-07

dudekjar wrote:

This is most probably caused by script don't wait for 200 Command okay and end session immediately after server (or client) send 226 Closing data.

The "200 Command okay" is response to "TYPE A" command that WinSCP probably sent to keep connection alive. That must have happened long after the transfer finished. Unfortunately, there are no timestamps in the log.

Reply with quote

dudekjar

Re: scripting FTP put file is not successful on server side

2014-04-09 12:12

I have added log timinig into my previous post. As you can see timing is really in same second.

I can also prepare some TCP dump if it would be helpful for investigation.

Reply with quote

Simon G. Guest

Missing QUIT command ?

2014-04-09 17:54

Hello,

When the connections are brutally closed, the remote server has no way to distinguish a brutal disconnection from a normal transfer end.

A stated in FTP RFC 959:
An unexpected close on the control connection will cause the
server to take the effective action of an abort (ABOR) and a
logout (QUIT).

Issuing a QUIT command in reply to the "226 Closing data connection" message will help as an acknowledgment that the transfer ended correctly.

Best regards,
Simon.

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,442
Location:: Prague, Czechia

Re: scripting FTP put file is not successful on server side

2014-04-10

dudekjar wrote:

I have added log timinig into my previous post. As you can see timing is really in same second.

I can also prepare some TCP dump if it would be helpful for investigation.

Ok, but that does not change anything. The transfer is finished by the time TYPE A was sent as acknowledged by the server by 226 response. That exchange is irrelevant to the file transfer.

Last edited by martin on 2014-04-10; edited 1 time in total

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,442
Location:: Prague, Czechia

Re: Missing QUIT command ?

2014-04-10

Simon G. wrote:

When the connections are brutally closed, the remote server has no way to distinguish a brutal disconnection from a normal transfer end.

We are talking about upload here. While uploading, it's a client who terminates the transfer connection (as the server cannot know when transfer finished as it does not know file size). Once connection is terminated, the server acknowledges transfer end with 226 response. So after the response BOTH sides are aware that transfer was finished. So at that time control connection termination cannot have any impact on file transfer as there's none.

Reply with quote

martin◆ Site Admin

Re: scripting FTP put file is not successful on server side

2014-04-10

It's likely that this is some king of bug on the server side. It probably has not really finished file writing before acknowledging the transfer. Possible workaround would be to issue some dummy command after the transfer (e.g. ls).

Reply with quote