Problem transferring file to remote location

Hi

I am trying to transfer a fairly simple text file onto a remote sftp site.

The process is called from a vbscript using WINSCP's console utility. We have successfully transferred files of simialr type and content. Attached is the log file contents.

I have looked at the file in question and can't see any visible signs of corruption or file locking etc


. 2008-06-06 11:57:35.623 --------------------------------------------------------------------------
. 2008-06-06 11:57:35.623 Looking up host "62.160.47.14"
. 2008-06-06 11:57:35.623 Connecting to 62.160.47.14 port 22
. 2008-06-06 11:57:35.686 Server version: SSH-2.0-XFB.Gateway Windows
. 2008-06-06 11:57:35.686 We claim version: SSH-2.0-WinSCP_release_4.1.2
. 2008-06-06 11:57:35.701 SSPI: acquired credentials for: JamesB@MMGROUP
. 2008-06-06 11:57:35.701 Cannot convert IP address to SPN: DNS is not trusted
. 2008-06-06 11:57:35.701 GSSKEX disabled: The operation completed successfully.

. 2008-06-06 11:57:35.701 Using SSH protocol version 2
. 2008-06-06 11:57:35.717 Doing Diffie-Hellman group exchange
. 2008-06-06 11:57:35.998 Doing Diffie-Hellman key exchange with hash SHA-1
. 2008-06-06 11:57:36.108 Host key fingerprint is:
. 2008-06-06 11:57:36.108 ssh-rsa 1023 7e:1f:c2:86:d0:a3:4c:73:a9:fa:50:30:96:2a:d9:60
. 2008-06-06 11:57:36.108 Initialised AES-128 CBC client->server encryption
. 2008-06-06 11:57:36.108 Initialised HMAC-SHA1 client->server MAC algorithm
. 2008-06-06 11:57:36.108 Initialised AES-128 CBC server->client encryption
. 2008-06-06 11:57:36.108 Initialised HMAC-SHA1 server->client MAC algorithm
! 2008-06-06 11:57:36.326 Using username "FORMPRO_CLIENT".
. 2008-06-06 11:57:36.373 Prompt (6, SSH password, , &Password: )
. 2008-06-06 11:57:36.373 Using stored password.
. 2008-06-06 11:57:36.373 Sent password
. 2008-06-06 11:57:36.405 Access granted
. 2008-06-06 11:57:36.436 Opened channel for session
. 2008-06-06 11:57:36.467 Started a shell/command
. 2008-06-06 11:57:36.467 --------------------------------------------------------------------------
. 2008-06-06 11:57:36.467 Using SFTP protocol.
. 2008-06-06 11:57:36.467 Doing startup conversation with host.
> 2008-06-06 11:57:36.467 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2008-06-06 11:57:36.498 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2008-06-06 11:57:36.498 SFTP version 3 negotiated.
. 2008-06-06 11:57:36.498 We believe the server has signed timestamps bug
. 2008-06-06 11:57:36.498 We will use UTF-8 strings for status messages only
. 2008-06-06 11:57:36.498 Getting current directory name.
. 2008-06-06 11:57:36.498 Getting real path for '.'
> 2008-06-06 11:57:36.498 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2008-06-06 11:57:36.530 Type: SSH_FXP_NAME, Size: 99, Number: 16
. 2008-06-06 11:57:36.530 Real path is '/'
. 2008-06-06 11:57:36.530 Startup conversation with host finished.
. 2008-06-06 11:57:36.545 Cached directory change via "ARRIVEE" to "/ARRIVEE".
. 2008-06-06 11:57:36.545 Getting current directory name.
. 2008-06-06 11:57:36.545 Cached directory change via "MAINFRAME" to "/ARRIVEE/MAINFRAME".
. 2008-06-06 11:57:36.545 Getting current directory name.
. 2008-06-06 11:57:36.545 Copying 1 files/directories to remote directory "/ARRIVEE/MAINFRAME"
. 2008-06-06 11:57:36.545 PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 01; Resume: N (102400); CalcS: No; Mask:
. 2008-06-06 11:57:36.545 TM: M; ClAr: No; CPS: 0; ExclM(No):
. 2008-06-06 11:57:36.545 AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2008-06-06 11:57:36.545 File: "FORX02.DAT"
. 2008-06-06 11:57:36.545 Copying "FORX02.DAT" to remote directory started.
. 2008-06-06 11:57:36.545 Binary transfer mode selected.
. 2008-06-06 11:57:36.545 Opening remote file.
> 2008-06-06 11:57:36.545 Type: SSH_FXP_OPEN, Size: 54, Number: 259
< 2008-06-06 11:57:36.576 Type: SSH_FXP_HANDLE, Size: 10, Number: 259
> 2008-06-06 11:57:36.576 Type: SSH_FXP_WRITE, Size: 2871, Number: 774
> 2008-06-06 11:57:36.576 Type: SSH_FXP_CLOSE, Size: 10, Number: 1028
> 2008-06-06 11:57:36.576 Type: SSH_FXP_SETSTAT, Size: 50, Number: 521
. 2008-06-06 11:57:36.655 Disconnected: All channels closed
. 2008-06-06 11:57:36.655 Fatal error while disposing the SFTP queue.
. 2008-06-06 11:57:36.655 Connection was lost, asking what to do.
. 2008-06-06 11:57:36.655 Asking user:
. 2008-06-06 11:57:36.655 Connection has been unexpectedly closed. Server sent command exit status 0. ()
. 2008-06-06 11:57:42.905 Looking up host "62.160.47.14"
. 2008-06-06 11:57:42.905 Connecting to 62.160.47.14 port 22
. 2008-06-06 11:57:42.967 Server version: SSH-2.0-XFB.Gateway Windows
. 2008-06-06 11:57:42.967 We claim version: SSH-2.0-WinSCP_release_4.1.2
. 2008-06-06 11:57:42.967 SSPI: acquired credentials for: JamesB@MMGROUP
. 2008-06-06 11:57:42.967 Cannot convert IP address to SPN: DNS is not trusted
. 2008-06-06 11:57:42.967 GSSKEX disabled: The operation completed successfully.

. 2008-06-06 11:57:42.967 Using SSH protocol version 2
. 2008-06-06 11:57:42.998 Doing Diffie-Hellman group exchange
. 2008-06-06 11:57:43.248 Doing Diffie-Hellman key exchange with hash SHA-1
. 2008-06-06 11:57:43.389 Host key fingerprint is:
. 2008-06-06 11:57:43.389 ssh-rsa 1023 7e:1f:c2:86:d0:a3:4c:73:a9:fa:50:30:96:2a:d9:60
. 2008-06-06 11:57:43.389 Initialised AES-128 CBC client->server encryption
. 2008-06-06 11:57:43.389 Initialised HMAC-SHA1 client->server MAC algorithm
. 2008-06-06 11:57:43.389 Initialised AES-128 CBC server->client encryption
. 2008-06-06 11:57:43.389 Initialised HMAC-SHA1 server->client MAC algorithm
! 2008-06-06 11:57:43.655 Using username "FORMPRO_CLIENT".
. 2008-06-06 11:57:43.686 Prompt (6, SSH password, , &Password: )
. 2008-06-06 11:57:43.686 Using stored password.
. 2008-06-06 11:57:43.686 Sent password
. 2008-06-06 11:57:43.733 Access granted
. 2008-06-06 11:57:43.795 Opened channel for session
. 2008-06-06 11:57:43.858 Started a shell/command
. 2008-06-06 11:57:43.858 Doing startup conversation with host.
> 2008-06-06 11:57:43.858 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2008-06-06 11:57:43.889 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2008-06-06 11:57:43.889 SFTP version 3 negotiated.
. 2008-06-06 11:57:43.889 We believe the server has signed timestamps bug
. 2008-06-06 11:57:43.889 We will use UTF-8 strings for status messages only
. 2008-06-06 11:57:43.889 Changing directory to "/ARRIVEE/MAINFRAME".
. 2008-06-06 11:57:43.889 Getting real path for '/ARRIVEE/MAINFRAME'
> 2008-06-06 11:57:43.889 Type: SSH_FXP_REALPATH, Size: 27, Number: 1296
< 2008-06-06 11:57:43.920 Type: SSH_FXP_NAME, Size: 118, Number: 1296
. 2008-06-06 11:57:43.920 Real path is '/ARRIVEE/MAINFRAME'
. 2008-06-06 11:57:43.920 Trying to open directory "/ARRIVEE/MAINFRAME".
> 2008-06-06 11:57:43.920 Type: SSH_FXP_LSTAT, Size: 27, Number: 1543
< 2008-06-06 11:57:43.952 Type: SSH_FXP_ATTRS, Size: 37, Number: 1543
. 2008-06-06 11:57:43.952 Getting current directory name.
. 2008-06-06 11:57:43.952 Startup conversation with host finished.
. 2008-06-06 11:57:43.952 File: "FORX02.DAT"
. 2008-06-06 11:57:43.952 Copying "FORX02.DAT" to remote directory started.
. 2008-06-06 11:57:43.952 Binary transfer mode selected.
. 2008-06-06 11:57:43.952 Opening remote file.
> 2008-06-06 11:57:43.952 Type: SSH_FXP_OPEN, Size: 54, Number: 1795
< 2008-06-06 11:57:43.998 Type: SSH_FXP_HANDLE, Size: 10, Number: 1795
> 2008-06-06 11:57:43.998 Type: SSH_FXP_WRITE, Size: 2871, Number: 2310
> 2008-06-06 11:57:43.998 Type: SSH_FXP_CLOSE, Size: 10, Number: 2564
> 2008-06-06 11:57:43.998 Type: SSH_FXP_SETSTAT, Size: 50, Number: 2057
. 2008-06-06 11:57:44.077 Disconnected: All channels closed
. 2008-06-06 11:57:44.077 Fatal error while disposing the SFTP queue.
. 2008-06-06 11:57:44.077 Connection was lost, asking what to do.
. 2008-06-06 11:57:44.077 Asking user:
. 2008-06-06 11:57:44.077 Connection has been unexpectedly closed. Server sent command exit status 0. ()

Any help you can give me will be greatfully received!

I also get the same error when I try to drag and drop using the GUI interface!

As it seems to be the server who closes the connection, please first check its logs file to see if you can find there a reason.

Hi this is the target sftp site's log from a failure. Just to put things into context. We upload other files of a simialar format and they work. The process is 1) locate files of a similar 'type' 2) Create Header for new output file 3) Read through each file line by line and output that line to new file 4) Add footer line 5) Close file 6) Transmit file

The scenario's we have tested were

File a - old file created three weeks ago
File b - new
File c - new

sending header + a + b + c + footer -> transmits ok
header + a + (b or c) + footer transmits ok
header + a + footer transmits ok
header + b + c + footer causes connection to drop
header + b or c + footer causes connection to drop

when the connection drops the files are actually on the remote server but WINSCP keeps trying to resume the transfer indefinitely.

It's bizarre that the inclusion of an old file cures the issue! The files being concatenated are simple text files nothing special. I've looked at them with a hex viewer and all the files looks identical in format. If they failed with the old file included I'd understand it more!!!

Cheers

NET102I 06.06.2008 09:51:22 (13319) incoming connection indication [src_add="62.173.119.59/36346",dest_add="192.168.10.14/22"].
SECS106I 06.06.2008 09:51:22 Server(13318) Net profile PORTE_FORMPRO1 selected [src_add="62.173.119.59/36346"] [dest_add="192.168.10.14/22"].
SECS111I 06.06.2008 09:51:22 Server(13318) SSH profile SFTP_IN_FORMPRO selected .
NET103I 06.06.2008 09:51:22 (13319) incoming connection response [resp_add=""].
SECS115I 06.06.2008 09:51:23 Server(13318) RSA signature achieved with private key ATLAS_PRIVEE.
SECS102S 06.06.2008 09:51:24 Server(13318) Session established for user FORMPRO_CLIENT, key exchange algo: dh-group-exchange, public key algo: ssh-rsa, cipher algo: aes128-cbc, mac algo: sha1, no compression.
NET060I 06.06.2008 09:51:24 (13319) session success.
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Read) ID:0 SSH_FXP_INIT version:5.
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Write) ID:0 SSH_FXP_VERSION version:3.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Read) ID:16 SSH_FXP_REALPATH.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Write) ID:16 SSH_FXP_NAME.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Read) ID:267 SSH_FXP_OPENDIR.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Write) ID:267 SSH_FXP_HANDLE.
SFTP019I 06.06.2008 09:51:24 XFBATLAS(77) [0] begin sending from , LIST: .
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Read) ID:524 SSH_FXP_READDIR.
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Write) ID:524 SSH_FXP_NAME count:2.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Read) ID:780 SSH_FXP_READDIR.
SFTP023I 06.06.2008 09:51:24 XFBATLAS(77) [0] end sending from , LIST: .
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Write) ID:780 SSH_FXP_STATUS errnum:1.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Read) ID:1028 SSH_FXP_CLOSE.
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Write) ID:1028 SSH_FXP_STATUS SSH_FX_OK:0.
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Read) ID:1283 SSH_FXP_OPEN pflags:26.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Write) ID:1283 SSH_FXP_HANDLE.
SFTP104I 06.06.2008 09:51:24 XFBATLAS(Read) ID:1798 SSH_FXP_WRITE (int)offset:0 newdataLen:2856.
SFTP016I 06.06.2008 09:51:24 XFBATLAS(77) [53830] begin receiving to XFBATLAS, file: F:/ARCHIVES/XFB 53830_FORX02.DAT.
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Write) ID:1798 SSH_FXP_STATUS SSH_FX_OK:0.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Read) ID:2052 SSH_FXP_CLOSE.
SFTP102I 06.06.2008 09:51:24 XFBATLAS(Read) ID:1545 SSH_FXP_SETSTAT.
SFTP103I 06.06.2008 09:51:24 XFBATLAS(Write) ID:1545 SSH_FXP_STATUS SSH_FX_OK:0.
SFTP011E 06.06.2008 09:51:24 XFBATLAS(77) ABORT sent : 0 18.
NET061I 06.06.2008 09:51:24 (13319) session ended correctly.
NET105I 06.06.2008 09:51:24 (13319) disconnection request [reason="0"].
SECS104I 06.06.2008 09:51:24 Server(13318) Session ended for user FORMPRO_CLIENT.
NET102I 06.06.2008 09:51:31 (13320) incoming connection indication [src_add="62.173.119.59/36394",dest_add="192.168.10.14/22"].
SECS106I 06.06.2008 09:51:31 Server(13319) Net profile PORTE_FORMPRO1 selected [src_add="62.173.119.59/36394"] [dest_add="192.168.10.14/22"].
SECS111I 06.06.2008 09:51:31 Server(13319) SSH profile SFTP_IN_FORMPRO selected .
NET103I 06.06.2008 09:51:31 (13320) incoming connection response [resp_add=""].
SECS115I 06.06.2008 09:51:32 Server(13319) RSA signature achieved with private key ATLAS_PRIVEE.
SECS102S 06.06.2008 09:51:32 Server(13319) Session established for user FORMPRO_CLIENT, key exchange algo: dh-group-exchange, public key algo: ssh-rsa, cipher algo: aes128-cbc, mac algo: sha1, no compression.
NET060I 06.06.2008 09:51:32 (13320) session success.
SFTP103I 06.06.2008 09:51:33 XFBATLAS(Read) ID:0 SSH_FXP_INIT version:5.
SFTP103I 06.06.2008 09:51:33 XFBATLAS(Write) ID:0 SSH_FXP_VERSION version:3.
SFTP102I 06.06.2008 09:51:33 XFBATLAS(Read) ID:2320 SSH_FXP_REALPATH.
SFTP102I 06.06.2008 09:51:33 XFBATLAS(Write) ID:2320 SSH_FXP_NAME.
SFTP102I 06.06.2008 09:51:33 XFBATLAS(Read) ID:2567 SSH_FXP_LSTAT.
SFTP102I 06.06.2008 09:51:33 XFBATLAS(Write) ID:2567 SSH_FXP_ATTRS.
SFTP103I 06.06.2008 09:51:33 XFBATLAS(Read) ID:2819 SSH_FXP_OPEN pflags:26.
SFTP102I 06.06.2008 09:51:33 XFBATLAS(Write) ID:2819 SSH_FXP_HANDLE.
SFTP104I 06.06.2008 09:51:33 XFBATLAS(Read) ID:3334 SSH_FXP_WRITE (int)offset:0 newdataLen:2856.
SFTP016I 06.06.2008 09:51:33 XFBATLAS(78) [53830] begin receiving to XFBATLAS, file: F:/ARCHIVES/XFB 53830_FORX02.DAT.
SFTP103I 06.06.2008 09:51:33 XFBATLAS(Write) ID:3334 SSH_FXP_STATUS SSH_FX_OK:0.
SFTP102I 06.06.2008 09:51:33 XFBATLAS(Read) ID:3588 SSH_FXP_CLOSE.
SFTP102I 06.06.2008 09:51:33 XFBATLAS(Read) ID:3081 SSH_FXP_SETSTAT.
SFTP103I 06.06.2008 09:51:33 XFBATLAS(Write) ID:3081 SSH_FXP_STATUS SSH_FX_OK:0.
SFTP011E 06.06.2008 09:51:33 XFBATLAS(78) ABORT sent : 0 18.
NET061I 06.06.2008 09:51:33 (13320) session ended correctly.
NET105I 06.06.2008 09:51:33 (13320) disconnection request [reason="0"].
SECS104I 06.06.2008 09:51:33 Server(13319) Session ended for user FORMPRO_CLIENT.
NET102I 06.06.2008 09:51:39 (13321) incoming connection indication [src_add="62.173.119.59/36398",dest_add="192.168.10.14/22"].
SECS106I 06.06.2008 09:51:39 Server(13320) Net profile PORTE_FORMPRO1 selected [src_add="62.173.119.59/36398"] [dest_add="192.168.10.14/22"].
SECS111I 06.06.2008 09:51:39 Server(13320) SSH profile SFTP_IN_FORMPRO selected .
NET103I 06.06.2008 09:51:39 (13321) incoming connection response [resp_add=""].
SECS115I 06.06.2008 09:51:40 Server(13320) RSA signature achieved with private key ATLAS_PRIVEE.
SECS102S 06.06.2008 09:51:40 Server(13320) Session established for user FORMPRO_CLIENT, key exchange algo: dh-group-exchange, public key algo: ssh-rsa, cipher algo: aes128-cbc, mac algo: sha1, no compression.
NET060I 06.06.2008 09:51:40 (13321) session success.
SFTP103I 06.06.2008 09:51:40 XFBATLAS(Read) ID:0 SSH_FXP_INIT version:5.
SFTP103I 06.06.2008 09:51:40 XFBATLAS(Write) ID:0 SSH_FXP_VERSION version:3.
SFTP102I 06.06.2008 09:51:40 XFBATLAS(Read) ID:3856 SSH_FXP_REALPATH.
SFTP102I 06.06.2008 09:51:40 XFBATLAS(Write) ID:3856 SSH_FXP_NAME.
SFTP102I 06.06.2008 09:51:40 XFBATLAS(Read) ID:4103 SSH_FXP_LSTAT.
SFTP102I 06.06.2008 09:51:40 XFBATLAS(Write) ID:4103 SSH_FXP_ATTRS.
SFTP103I 06.06.2008 09:51:40 XFBATLAS(Read) ID:4355 SSH_FXP_OPEN pflags:26.
SFTP102I 06.06.2008 09:51:40 XFBATLAS(Write) ID:4355 SSH_FXP_HANDLE.
SFTP104I 06.06.2008 09:51:40 XFBATLAS(Read) ID:4870 SSH_FXP_WRITE (int)offset:0 newdataLen:2856.
SFTP016I 06.06.2008 09:51:40 XFBATLAS(79) [53830] begin receiving to XFBATLAS, file: F:/ARCHIVES/XFB 53830_FORX02.DAT.
SFTP103I 06.06.2008 09:51:40 XFBATLAS(Write) ID:4870 SSH_FXP_STATUS SSH_FX_OK:0.
SFTP102I 06.06.2008 09:51:40 XFBATLAS(Read) ID:5124 SSH_FXP_CLOSE.
SFTP102I 06.06.2008 09:51:40 XFBATLAS(Read) ID:4617 SSH_FXP_SETSTAT.
SFTP103I 06.06.2008 09:51:40 XFBATLAS(Write) ID:4617 SSH_FXP_STATUS SSH_FX_OK:0.
SFTP011E 06.06.2008 09:51:40 XFBATLAS(79) ABORT sent : 0 18.
NET061I 06.06.2008 09:51:40 (13321) session ended correctly.
NET105I 06.06.2008 09:51:40 (13321) disconnection request [reason="0"].
SECS104I 06.06.2008 09:51:40 Server(13320) Session ended for user FORMPRO_CLIENT.

If we revert to WINSCP 3.8.2 we can now send the files via the GUI but not with the console! As this is an automated process I really need to send via the console. Could you let me know what the difference is between WINSCP 3.8.2 and the latest versions and if there is an older console version I could try.

Cheers

James

JamesBarnaby1 wrote:

If we revert to WINSCP 3.8.2 we can now send the files via the GUI but not with the console! As this is an automated process I really need to send via the console. Could you let me know what the difference is between WINSCP 3.8.2 and the latest versions and if there is an older console version I could try.

Since 4.0, WinSCP is able to utilize available bandwidth when uploading more efficiently. So the difference may be in transfer rate (maybe only slight).

Unfortunately there is nothing useful about reason of disconnecting the server's log. I do not know what "ABORT sent : 0 18" means. Maybe you can ask supplier of your server.