Topic "scripting FTP put file is not successful on server side"

Author Message
dudekjar
[View user's profile]

Joined: 2014-04-03
Posts: 4
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 http://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
Advertisements
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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?
_________________
Martin Prikryl
dudekjar
[View user's profile]

Joined: 2014-04-03
Posts: 4
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
Code:

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
Code:

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
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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.
_________________
Martin Prikryl
dudekjar
[View user's profile]

Joined: 2014-04-03
Posts: 4
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.
Simon G.

Guest


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.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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.
martin
[View user's profile]
Site Admin
Joined: 2002-12-10
Posts: 24530
Location: Prague, Czechia
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).
_________________
Martin Prikryl
dudekjar
[View user's profile]

Joined: 2014-04-03
Posts: 4
prikryl wrote:
Possible workaround would be to issue some dummy command after the transfer (e.g. ls).


Verified Very Happy

When I add this command, all transfers are OK on server side. Many thank for useful hint.

$tmp = $session.ListDirectory("/")
Advertisements

You can post new topics in this forum






Search Site

What is WinSCP?

It is award-winning SFTP client, SCP client, FTPS client and FTP client integrated into one software program for file transfer to FTP server or secure SFTP server. [More]

And it's free!

Donate

About donations

$9   $19   $49   $99

About donations

Recommend

WinSCP Privacy Policy

WinSCP License