Successful download not successful from server perspective? :: Support Forum

Guest

Successful download not successful from server perspective?

2009-06-10 20:36

WinSCP 4.1.9 # 416 on Windows Server 2003R2 x32.

I am using the command-line scripting to download a file from a mainframe from some vendor out in the cloud (I don't know what it is -- maybe an AIX system?). The script is super-simple:

get AUXMXPET.TXT
exit

The server is set up (somehow) to recognize when the file is downloaded and it moves it out into another folder. IF I use my Mac's SFTP and issue get AUXMXPET.TXT it will download the file and trigger the thing that it was downloaded. However, my script via winSCP will download the file but NOT trigger the script, leading me to believe maybe there's something goofy in the settings or the like. Any ideas? Attached below is the log. Note that the server suffers from some sort of OpenSSH bug so I had to use blowfish instead of aes.

THANKS!!!!!!!!!!!!

My command line

D:\UTILS\sftp PROD_RECEIVE /log=AUXMXPET.log  /script=ftp.txt >>C:\tmp\auxmxpetftp.log

. 2009-06-10 15:16:10.469 --------------------------------------------------------------------------
. 2009-06-10 15:16:10.469 WinSCP Version 4.1.9 (Build 416) (OS 5.2.3790 Service Pack 2)
. 2009-06-10 15:16:10.469 Login time: Wednesday, June 10, 2009 3:16:10 PM
. 2009-06-10 15:16:10.469 --------------------------------------------------------------------------
. 2009-06-10 15:16:10.469 Session name: PROD_RECEIVE
. 2009-06-10 15:16:10.469 Host name: XXXXXXXXXXXXXX (Port: 22)
. 2009-06-10 15:16:10.469 User name: XXXXXXXXXX (Password: Yes, Key file: No)
. 2009-06-10 15:16:10.469 Tunnel: No
. 2009-06-10 15:16:10.469 Transfer Protocol: SFTP (SCP)
. 2009-06-10 15:16:10.469 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2009-06-10 15:16:10.469 Proxy: none
. 2009-06-10 15:16:10.469 SSH protocol version: 2; Compression: No
. 2009-06-10 15:16:10.469 Bypass authentication: No
. 2009-06-10 15:16:10.469 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2009-06-10 15:16:10.469 Ciphers: blowfish,aes,3des,WARN,arcfour,des; Ssh2DES: No
. 2009-06-10 15:16:10.469 SSH Bugs: -,-,-,-,-,-,-,-
. 2009-06-10 15:16:10.469 SFTP Bugs: -,-
. 2009-06-10 15:16:10.469 Return code variable: Autodetect; Lookup user groups: Yes
. 2009-06-10 15:16:10.469 Shell: default, EOL: 0
. 2009-06-10 15:16:10.469 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2009-06-10 15:16:10.469 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2009-06-10 15:16:10.469 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2009-06-10 15:16:10.469 Cache directory changes: Yes, Permanent: Yes
. 2009-06-10 15:16:10.469 DST mode: 2
. 2009-06-10 15:16:10.469 --------------------------------------------------------------------------
. 2009-06-10 15:16:10.469 Looking up host "xxxxxxxxxxx" (IPv4)
. 2009-06-10 15:16:10.469 Connecting to xxxxxxxxxxx port 22
. 2009-06-10 15:16:10.562 Selecting events 63 for socket 1524
. 2009-06-10 15:16:10.562 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:10.562 Looking for incoming data
. 2009-06-10 15:16:10.562 Looking for network events
. 2009-06-10 15:16:10.562 Detected network event
. 2009-06-10 15:16:10.562 Enumerating network events for socket 1524
. 2009-06-10 15:16:10.562 Enumerated 18 network events making 18 cumulative events for socket 1524
. 2009-06-10 15:16:10.562 Handling network write event on socket 1524 with error 0
. 2009-06-10 15:16:10.562 Handling network connect event on socket 1524 with error 0
. 2009-06-10 15:16:10.562 Looking for network events
. 2009-06-10 15:16:10.719 Detected network event
. 2009-06-10 15:16:10.719 Enumerating network events for socket 1524
. 2009-06-10 15:16:10.719 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:10.719 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:10.719 Server version: SSH-2.0-OpenSSH_4.3
. 2009-06-10 15:16:10.719 We claim version: SSH-2.0-WinSCP_release_4.1.9
. 2009-06-10 15:16:10.719 SSPI: acquired credentials for: xxxxxxxx@xxxxxxxxxx
. 2009-06-10 15:16:10.719 Cannot convert IP address to SPN: DNS is not trusted
. 2009-06-10 15:16:10.719 GSSKEX disabled: The operation completed successfully.
 
. 2009-06-10 15:16:10.719 Using SSH protocol version 2
. 2009-06-10 15:16:10.719 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:10.719 Looking for incoming data
. 2009-06-10 15:16:10.719 Looking for network events
. 2009-06-10 15:16:10.797 Detected network event
. 2009-06-10 15:16:10.797 Enumerating network events for socket 1524
. 2009-06-10 15:16:10.797 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:10.797 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:10.797 Doing Diffie-Hellman group exchange
. 2009-06-10 15:16:10.797 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:10.797 Looking for incoming data
. 2009-06-10 15:16:10.797 Looking for network events
. 2009-06-10 15:16:10.969 Detected network event
. 2009-06-10 15:16:10.969 Enumerating network events for socket 1524
. 2009-06-10 15:16:10.969 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:10.969 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:10.969 Doing Diffie-Hellman key exchange with hash SHA-1
. 2009-06-10 15:16:11.015 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:11.015 Looking for incoming data
. 2009-06-10 15:16:11.015 Looking for network events
. 2009-06-10 15:16:11.265 Detected network event
. 2009-06-10 15:16:11.265 Enumerating network events for socket 1524
. 2009-06-10 15:16:11.265 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:11.265 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:11.312 Selecting events 63 for socket 1524
. 2009-06-10 15:16:11.312 Host key fingerprint is:
. 2009-06-10 15:16:11.312 ssh-rsa 2048 xxxxxxxxxxxxxxxxxxxxxxxxxxx
. 2009-06-10 15:16:11.312 Initialised Blowfish-128 CBC client->server encryption
. 2009-06-10 15:16:11.312 Initialised HMAC-SHA1 client->server MAC algorithm
. 2009-06-10 15:16:11.312 Initialised Blowfish-128 CBC server->client encryption
. 2009-06-10 15:16:11.312 Initialised HMAC-SHA1 server->client MAC algorithm
. 2009-06-10 15:16:11.312 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:11.312 Looking for incoming data
. 2009-06-10 15:16:11.312 Looking for network events
. 2009-06-10 15:16:11.578 Detected network event
. 2009-06-10 15:16:11.578 Enumerating network events for socket 1524
. 2009-06-10 15:16:11.578 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:11.578 Handling network read event on socket 1524 with error 0
! 2009-06-10 15:16:11.578 Using username "xxxxxxxxxxx".
. 2009-06-10 15:16:11.578 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:11.578 Looking for incoming data
. 2009-06-10 15:16:11.578 Looking for network events
. 2009-06-10 15:16:11.672 Detected network event
. 2009-06-10 15:16:11.672 Enumerating network events for socket 1524
. 2009-06-10 15:16:11.672 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:11.672 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:11.672 Prompt (6, SSH password, , &Password: )
. 2009-06-10 15:16:11.672 Using stored password.
. 2009-06-10 15:16:11.672 Sent password
. 2009-06-10 15:16:11.672 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:11.672 Looking for incoming data
. 2009-06-10 15:16:11.672 Looking for network events
. 2009-06-10 15:16:12.000 Detected network event
. 2009-06-10 15:16:12.000 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.000 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.000 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.000 Access granted
. 2009-06-10 15:16:12.000 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:12.000 Looking for incoming data
. 2009-06-10 15:16:12.000 Looking for network events
. 2009-06-10 15:16:12.078 Detected network event
. 2009-06-10 15:16:12.078 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.078 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.078 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.078 Opened channel for session
. 2009-06-10 15:16:12.078 Waiting for the server to continue with the initialisation
. 2009-06-10 15:16:12.078 Looking for incoming data
. 2009-06-10 15:16:12.078 Looking for network events
. 2009-06-10 15:16:12.172 Detected network event
. 2009-06-10 15:16:12.172 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.172 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.172 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.172 Started a shell/command
. 2009-06-10 15:16:12.172 --------------------------------------------------------------------------
. 2009-06-10 15:16:12.172 Using SFTP protocol.
. 2009-06-10 15:16:12.172 Doing startup conversation with host.
> 2009-06-10 15:16:12.172 Type: SSH_FXP_INIT, Size: 5, Number: -1
> 2009-06-10 15:16:12.172 01,00,00,00,03,
. 2009-06-10 15:16:12.172 Sent 9 bytes
. 2009-06-10 15:16:12.172 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.172 Looking for network events
. 2009-06-10 15:16:12.172 Timeout waiting for network events
. 2009-06-10 15:16:12.172 Waiting for another 4 bytes
. 2009-06-10 15:16:12.172 Looking for incoming data
. 2009-06-10 15:16:12.172 Looking for network events
. 2009-06-10 15:16:12.422 Detected network event
. 2009-06-10 15:16:12.422 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.422 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.422 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.422 Received 9 bytes (0)
. 2009-06-10 15:16:12.422 Read 4 bytes (5 pending)
. 2009-06-10 15:16:12.422 Read 5 bytes (0 pending)
< 2009-06-10 15:16:12.422 Type: SSH_FXP_VERSION, Size: 5, Number: -1
< 2009-06-10 15:16:12.422 02,00,00,00,03,
. 2009-06-10 15:16:12.422 SFTP version 3 negotiated.
. 2009-06-10 15:16:12.422 We believe the server has signed timestamps bug
. 2009-06-10 15:16:12.422 We will use UTF-8 strings for status messages only
. 2009-06-10 15:16:12.422 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes
. 2009-06-10 15:16:12.422 Getting current directory name.
. 2009-06-10 15:16:12.422 Getting real path for '.'
> 2009-06-10 15:16:12.422 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
> 2009-06-10 15:16:12.422 10,00,00,00,10,00,00,00,01,2E,
. 2009-06-10 15:16:12.422 Sent 14 bytes
. 2009-06-10 15:16:12.422 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.422 Looking for network events
. 2009-06-10 15:16:12.422 Timeout waiting for network events
. 2009-06-10 15:16:12.422 Waiting for another 4 bytes
. 2009-06-10 15:16:12.422 Looking for incoming data
. 2009-06-10 15:16:12.422 Looking for network events
. 2009-06-10 15:16:12.515 Detected network event
. 2009-06-10 15:16:12.515 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.515 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.515 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.515 Received 49 bytes (0)
. 2009-06-10 15:16:12.515 Read 4 bytes (45 pending)
. 2009-06-10 15:16:12.515 Read 45 bytes (0 pending)
< 2009-06-10 15:16:12.515 Type: SSH_FXP_NAME, Size: 45, Number: 16
< 2009-06-10 15:16:12.515 xxxxxxxxxxxxxxxxxxxxxxxxxx,
. 2009-06-10 15:16:12.515 Real path is '/XXXXXXXXX'
. 2009-06-10 15:16:12.515 Startup conversation with host finished.
. 2009-06-10 15:16:12.515 Listing file "AUXMXPET.TXT".
> 2009-06-10 15:16:12.515 Type: SSH_FXP_LSTAT, Size: 34, Number: 263
> 2009-06-10 15:16:12.515 xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx,
. 2009-06-10 15:16:12.515 Sent 38 bytes
. 2009-06-10 15:16:12.515 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.515 Looking for network events
. 2009-06-10 15:16:12.515 Timeout waiting for network events
. 2009-06-10 15:16:12.515 Waiting for another 4 bytes
. 2009-06-10 15:16:12.515 Looking for incoming data
. 2009-06-10 15:16:12.515 Looking for network events
. 2009-06-10 15:16:12.625 Detected network event
. 2009-06-10 15:16:12.625 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.625 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.625 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.625 Received 41 bytes (0)
. 2009-06-10 15:16:12.625 Read 4 bytes (37 pending)
. 2009-06-10 15:16:12.625 Read 37 bytes (0 pending)
< 2009-06-10 15:16:12.625 Type: SSH_FXP_ATTRS, Size: 37, Number: 263
< 2009-06-10 15:16:12.625 69,00,00,01,07,00,00,00,0F,00,00,00,00,00,00,10,00,00,00,00,00,00,00,00,00,
< 2009-06-10 15:16:12.625 00,00,81,24,4A,30,06,7C,4A,30,06,7C,
. 2009-06-10 15:16:12.625 File: "/XXXXXXXXXX/AUXMXPET.TXT"
. 2009-06-10 15:16:12.625 Copying "/XXXXXXXXXX/AUXMXPET.TXT" to local directory started.
. 2009-06-10 15:16:12.625 Ascii transfer mode selected.
. 2009-06-10 15:16:12.625 Opening remote file.
> 2009-06-10 15:16:12.625 Type: SSH_FXP_OPEN, Size: 42, Number: 515
> 2009-06-10 15:16:12.625 03,00,00,02,03,00,00,00,19,2F,4D,53,4F,46,2D,30,30,30,30,38,33,2F,41,55,44,
> 2009-06-10 15:16:12.625 58,4D,50,45,54,2E,54,58,54,00,00,00,01,00,00,00,00,
. 2009-06-10 15:16:12.625 Sent 46 bytes
. 2009-06-10 15:16:12.625 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.625 Looking for network events
. 2009-06-10 15:16:12.625 Timeout waiting for network events
. 2009-06-10 15:16:12.625 Waiting for another 4 bytes
. 2009-06-10 15:16:12.625 Looking for incoming data
. 2009-06-10 15:16:12.625 Looking for network events
. 2009-06-10 15:16:12.750 Detected network event
. 2009-06-10 15:16:12.750 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.750 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.750 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.750 Received 17 bytes (0)
. 2009-06-10 15:16:12.750 Read 4 bytes (13 pending)
. 2009-06-10 15:16:12.750 Read 13 bytes (0 pending)
< 2009-06-10 15:16:12.750 Type: SSH_FXP_HANDLE, Size: 13, Number: 515
< 2009-06-10 15:16:12.750 66,00,00,02,03,00,00,00,04,00,00,00,00,
> 2009-06-10 15:16:12.750 Type: SSH_FXP_READ, Size: 25, Number: 1029
> 2009-06-10 15:16:12.750 xxxxxxxxxxxxxxxxxxx
. 2009-06-10 15:16:12.750 Sent 29 bytes
. 2009-06-10 15:16:12.750 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.750 Looking for network events
. 2009-06-10 15:16:12.750 Timeout waiting for network events
> 2009-06-10 15:16:12.750 Type: SSH_FXP_READ, Size: 25, Number: 1285
xxxxxxxxxxxxxxxxxxxxxxxxx
. 2009-06-10 15:16:12.750 Sent 29 bytes
. 2009-06-10 15:16:12.750 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.750 Looking for network events
. 2009-06-10 15:16:12.750 Timeout waiting for network events
. 2009-06-10 15:16:12.750 Waiting for another 4 bytes
. 2009-06-10 15:16:12.750 Looking for incoming data
. 2009-06-10 15:16:12.750 Looking for network events
. 2009-06-10 15:16:12.844 Detected network event
. 2009-06-10 15:16:12.844 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.844 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.844 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.844 Received 418 bytes (0)
. 2009-06-10 15:16:12.844 Read 4 bytes (414 pending)
. 2009-06-10 15:16:12.844 Read 414 bytes (0 pending)
< 2009-06-10 15:16:12.844 Type: SSH_FXP_DATA, Size: 414, Number: 1029
xxxxxxxxxxxxxxxxx
> 2009-06-10 15:16:12.859 Type: SSH_FXP_READ, Size: 25, Number: 1541
xxxxxxxxxxxxxxxx
. 2009-06-10 15:16:12.859 Sent 29 bytes
. 2009-06-10 15:16:12.859 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.859 Looking for network events
. 2009-06-10 15:16:12.859 Timeout waiting for network events
> 2009-06-10 15:16:12.859 Type: SSH_FXP_READ, Size: 25, Number: 1797
xxxxxxxxxxxxxxxxx
. 2009-06-10 15:16:12.859 Sent 29 bytes
. 2009-06-10 15:16:12.859 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:12.859 Looking for network events
. 2009-06-10 15:16:12.859 Timeout waiting for network events
. 2009-06-10 15:16:12.859 Waiting for another 4 bytes
. 2009-06-10 15:16:12.859 Looking for incoming data
. 2009-06-10 15:16:12.859 Looking for network events
. 2009-06-10 15:16:12.937 Detected network event
. 2009-06-10 15:16:12.937 Enumerating network events for socket 1524
. 2009-06-10 15:16:12.937 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:12.937 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:12.937 Received 32 bytes (0)
. 2009-06-10 15:16:12.937 Read 4 bytes (28 pending)
. 2009-06-10 15:16:12.937 Read 28 bytes (0 pending)
< 2009-06-10 15:16:12.937 Type: SSH_FXP_STATUS, Size: 28, Number: 1285
xxxxxxxxxxxxxxxxxxxxxxxxx
< 2009-06-10 15:16:12.937 00,00,00,
. 2009-06-10 15:16:12.937 Storing reserved response
. 2009-06-10 15:16:12.937 Waiting for another 4 bytes
. 2009-06-10 15:16:12.937 Looking for incoming data
. 2009-06-10 15:16:12.937 Looking for network events
. 2009-06-10 15:16:13.031 Detected network event
. 2009-06-10 15:16:13.031 Enumerating network events for socket 1524
. 2009-06-10 15:16:13.031 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:13.031 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:13.031 Received 32 bytes (0)
. 2009-06-10 15:16:13.031 Read 4 bytes (28 pending)
. 2009-06-10 15:16:13.031 Read 28 bytes (0 pending)
< 2009-06-10 15:16:13.031 Type: SSH_FXP_STATUS, Size: 28, Number: 1541
xxxxxxxxxxxxxxxxxx
< 2009-06-10 15:16:13.031 00,00,00,
. 2009-06-10 15:16:13.031 Storing reserved response
. 2009-06-10 15:16:13.031 Waiting for another 4 bytes
. 2009-06-10 15:16:13.031 Looking for incoming data
. 2009-06-10 15:16:13.031 Looking for network events
. 2009-06-10 15:16:13.281 Detected network event
. 2009-06-10 15:16:13.281 Enumerating network events for socket 1524
. 2009-06-10 15:16:13.281 Enumerated 1 network events making 1 cumulative events for socket 1524
. 2009-06-10 15:16:13.281 Handling network read event on socket 1524 with error 0
. 2009-06-10 15:16:13.281 Received 32 bytes (0)
. 2009-06-10 15:16:13.281 Read 4 bytes (28 pending)
. 2009-06-10 15:16:13.281 Read 28 bytes (0 pending)
< 2009-06-10 15:16:13.281 Type: SSH_FXP_STATUS, Size: 28, Number: 1797
< 2009-06-10 15:16:13.281 65,00,00,07,05,00,00,00,01,00,00,00,0B,45,6E,64,20,6F,66,20,66,69,6C,65,00,
< 2009-06-10 15:16:13.281 00,00,00,
< 2009-06-10 15:16:13.281 Status/error code: 1
> 2009-06-10 15:16:13.281 Type: SSH_FXP_CLOSE, Size: 13, Number: 2052
> 2009-06-10 15:16:13.281 04,00,00,08,04,00,00,00,04,00,00,00,00,
. 2009-06-10 15:16:13.281 Sent 17 bytes
. 2009-06-10 15:16:13.281 There are 0 bytes remaining in the send buffer
. 2009-06-10 15:16:13.281 Looking for network events
. 2009-06-10 15:16:13.281 Timeout waiting for network events
. 2009-06-10 15:16:13.281 1 requests to fill 1 data gaps were issued.
. 2009-06-10 15:16:13.281 Session upkeep
. 2009-06-10 15:16:13.281 Looking for network events
. 2009-06-10 15:16:13.281 Timeout waiting for network events
. 2009-06-10 15:16:13.281 Session upkeep
. 2009-06-10 15:16:13.281 Looking for network events
. 2009-06-10 15:16:13.281 Timeout waiting for network events
. 2009-06-10 15:16:13.281 Closing connection.
. 2009-06-10 15:16:13.281 Sending special code: 12
. 2009-06-10 15:16:13.281 Sent EOF message
. 2009-06-10 15:16:13.281 Selecting events 0 for socket 1524

Reply with quote

Guest

follow-up

2009-06-10 20:39

Note that the filename is something like:
AUXMXPET.TXT+20090601654646546

but the server responds to AUXMXPET.TXT just fine. I think this may be the cause of some of the problems because I cannot download the file from the GUI (I get "badly formatted packet or protocol" error)...

Reply with quote

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

Re: follow-up

2009-06-12

Cn you post a log file from your Mac client?

Anonymous wrote:

Note that the filename is something like:
AUXMXPET.TXT+20090601654646546

but the server responds to AUXMXPET.TXT just fine. I think this may be the cause of some of the problems because I cannot download the file from the GUI (I get "badly formatted packet or protocol" error)...

I do not understand this part. what is relation between AUXMXPET.TXT+20090601654646546 and AUXMXPET.TXT? What is the file you cannot download? Where do you download it from, if not from GUI?

Reply with quote

MattJP
Joined:: 2009-06-12
Posts:: 4

2009-06-12 21:16

Martin:

The filename is actually AUXMXPET.TXT+xxxxxxxxxxxxxxx

e.g.

sftp> ls -la
-r--r--r--    1 0        0             324 Jun 12 16:20 AUXMXPET.TXT+200906121502240e0u7s
dr-xr-xr-x    2 0        0            4096 Jun 12 15:39 canceled
dr-xr-xr-x    2 0        0            4096 Jun 12 15:39 downloaded

After I download it, their system moves it from the / to the downloaded directory and appends some more junk to it (timestamps etc.).

(note this is OS X 10.5 sftp)

sftp> cd downloaded
sftp> ls
AUXMXPET.TXT+2009060823154756lnja                                                                                                                           
AUXMXPET.TXT+200906120724300bg9jo                                                                                                                           
AUXMXPET.TXT_20090610133042007jdo_20090610133042007jdo+20090610133042007jdo

BUT -- I am supposed to download it just by asking for AUXMXPET.TXT, e.g.

sftp> ls
AUXMXPET.TXT+200906121502240e0u7s      canceled                               downloaded                             
sftp> get AUXMXPET.TXT
Fetching /MYUSERNAME/AUXMXPET.TXT to AUXMXPET.TXT
/MYUSERNAME/AUXMXPET.TXT                                                                                                   7%  324     0.3KB/s   00:11 ETA
sftp> ls
canceled   downloaded
sftp> cd downloaded
sftp> ls
AUXMXPET.TXT+2009060823154756lnja 
AUXMXPET.TXT+200906120724300bg9jo                                                                                                                           
AUXMXPET.TXT+200906121502240e0u7s                                                                                                                          
AUXMXPET.TXT_20090610133042007jdo_20090610133042007jdo+20090610133042007jdo

If I do a deeper log, e.g.

sftp -vvvv

I get (NOTE I had to fetch one I already grabbed since it's gone and I won't get another one til Monday):

sftp> get AUXMXPET.TXT
debug3: Looking up /MYUSERNAME/downloaded/AUXMXPET.TXT
debug3: Sent message fd 3 T:7 I:10
debug3: Received stat reply T:105 I:10
Fetching /MYUSERNAME/downloaded/AUXMXPET.TXT to AUXMXPET.TXT
debug3: Sent message fd 3 T:17 I:11
debug3: Received stat reply T:105 I:11
debug3: Sent message SSH2_FXP_OPEN I:12 P:/MYUSERNAME/downloaded/AUXMXPET.TXT
/MYUSERNAME/downloaded/AUXMXPET.TXT                                                                                        0%    0     0.0KB/s   --:-- ETAdebug3: Request range 0 -> 32767 (0/1)
debug3: Received reply T:103 I:13 R:1
debug3: Received data 0 -> 12716
debug3: Short data block, re-requesting 12717 -> 32767 ( 1)
debug3: Finish at 32768 ( 1)
debug3: Received reply T:101 I:14 R:1
/MYUSERNAME/downloaded/AUXMXPET.TXT                                                                                      310%   12KB   4.0KB/s   00:01    
debug3: Sent message SSH2_FXP_CLOSE I:15
debug3: SSH2_FXP_STATUS 0
sftp>

Is there a subtle difference in the way mac sftp downloads the file vs. WinSCP? Why would Mac SFTP trigger the server process to fire but WinSCP doesn't?

Thanks so much!!!!

Reply with quote

martin◆ Site Admin

2009-06-13

MattJP wrote:

Is there a subtle difference in the way mac sftp downloads the file vs. WinSCP? Why would Mac SFTP trigger the server process to fire but WinSCP doesn't?

From the log I'm not able to identify any difference. You should better contact the server provider/administrator.

Reply with quote

MattJP
Joined:: 2009-06-12
Posts:: 4

2009-06-15 00:12

Unfortunately the server admin(s) are, ahem, unavailable. Let's say they are a very big company (billions of $ in sales) and don't really care about us and our piddly little problem ("Can you download the file OK? Yes? Leave us alone.") leaving us high-and-dry and to resolve the issue on our client end.

I'm able to download the file successfully via the commercial software "FTPVoyager" and also "CoreFTP" but their automation tools are a lot more difficult to work with (and I prefer open source software)...

Reply with quote

MattJP
Joined:: 2009-06-12
Posts:: 4

2009-06-15 02:06

I did some more tracing and I noticed that as soon as I request the file transfer in WinSCP the file disappears from the server ('ls' does not show the file). The file re-appears after WinSCP is finished. In OSX sftp the file does *not* re-appear in the root folder... I wonder if the server is not processing a successful file transfer message from WinSCP but it DOES in OSX sftp?

Is it a difference between SSH2 and SSH file transfer? I noticed that OS X sftp issues a SSH2_FXP_CLOSE vs. WinSCP's SSH_FXP_CLOSE (even though I force the connection to be SSH2)?

Also -- I noticed WinSCP is saying Status: 1 whereas sftp is status:0 ?

I'm grasping at straws, but there's gotta be a solution to this! :D

Thanks again for a great product!!!

Reply with quote

MattJP
Joined:: 2009-06-12
Posts:: 4

2009-06-15 03:36

Ah! Perhaps Eureka!

I wondered how the system is set up and I *believe* that the AUXMXPET.TXT "file" is actually a symlink to the most recent AUXMXPET.TXT+XXXXXXXXXXXXXX file. Thus, I can ask for ls AUXMXPET.TXT and get a response; I can also issue a GET AUXMXPET.TXT.

When I do:

sftp> ls -la
dr-xr-xr-x    2 0        0            4096 Jun 14 22:17 ..
-r--r--r--    1 0        0          810000 Jun 14 17:39 AUXMXPET.TXT+200906121634180egc84
...

No file called AUXMXPET.TXT exists.

When I do:

sftp> ls -la AUXMXPET.TXT
-r--r--r--    0 0        0            4096 Jun 14 22:18 AUXMXPET.TXT

There it is (note the timestamp doesn't match any of the files I have... dunno why). I'm not sure how they do this magic but on my Mac OS X 10.5 sftp it seems to resolve it OK.

My guess is that WinSCP is using ls -l AUXMXPET.TXT, interpreting the 4096 as the size, and then wigging out when it keeps getting data after that -- thus interpreting the file download as unsuccessful?? Does that sound right? It certainly confirms some behavior I'm seeing in other sftp clients (some quit after 4096 bytes). I'm not sure what the OSX sftp client does but my guess is it is very liberal and disregards the size value in the ls output.

Thanks!!
--
Matt

Reply with quote

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

2009-06-22

MattJP wrote:

Is it a difference between SSH2 and SSH file transfer? I noticed that OS X sftp issues a SSH2_FXP_CLOSE vs. WinSCP's SSH_FXP_CLOSE (even though I force the connection to be SSH2)?

WinSCP does SSH2 too.

Also -- I noticed WinSCP is saying Status: 1 whereas sftp is status:0 ?

There's only one status 1 message in WinSCP log. It is response to the last read request, indicating an end of the file was reached.

Reply with quote

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

2009-06-22

MattJP wrote:

My guess is that WinSCP is using ls -l AUXMXPET.TXT, interpreting the 4096 as the size, and then wigging out when it keeps getting data after that -- thus interpreting the file download as unsuccessful?? Does that sound right?

Unfortunately not. WinSCP does take the reported file size into consideration only for optimizing the size of read requests. It can handle larger than reported files correctly. Moreover WinSCP interprets the download as successful. There's no error in the log. Again, I do not see any problem on WinSCP side. From its perspective everything went correctly.

Reply with quote

Successful download not successful from server perspective?