Lost connection, no auto reconnection with script

Running WinSCP 4.1.9.416, using WinSCP.com and script. This particular host seems a bit flaky, if I download file manually using UI it works, but several times during big file download (2 gig) it will indicate "Incorrect MAC received on packet" and then countdown, reconnect, and continue. However, when scripting it doesn't seem to auto reconnect. Here is the relevant part of the log:
. 2009-11-16 09:27:04.886 Incorrect MAC received on packet
. 2009-11-16 09:27:04.886 Connection was lost, asking what to do.
. 2009-11-16 09:27:04.886 Asking user:
. 2009-11-16 09:27:04.886 Incorrect MAC received on packet ()

Of course, since this is a scripted download, there is no 'user' to ask.

After that last log entry the app terminates.

Thanks in advance for assistance - great program!

Can you post a full log file?

Sure - here it is:

. 2009-11-16 09:21:59.286 WinSCP Version 4.1.9 (Build 416) (OS 5.2.3790 Service Pack 2)
. 2009-11-16 09:21:59.286 Login time: Monday, November 16, 2009 9:21:59 AM
. 2009-11-16 09:21:59.286 --------------------------------------------------------------------------
. 2009-11-16 09:21:59.286 Session name: <username>@11.22.33.44
. 2009-11-16 09:21:59.286 Host name: 11.22.33.44 (Port: 22)
. 2009-11-16 09:21:59.286 User name: <username> (Password: Yes, Key file: No)
. 2009-11-16 09:21:59.286 Tunnel: No
. 2009-11-16 09:21:59.286 Transfer Protocol: SFTP (SCP)
. 2009-11-16 09:21:59.286 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2009-11-16 09:21:59.286 Proxy: none
. 2009-11-16 09:21:59.286 SSH protocol version: 2; Compression: No
. 2009-11-16 09:21:59.286 Bypass authentication: No
. 2009-11-16 09:21:59.286 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2009-11-16 09:21:59.286 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2009-11-16 09:21:59.286 SSH Bugs: -,-,-,-,-,-,-,-
. 2009-11-16 09:21:59.286 SFTP Bugs: -,-
. 2009-11-16 09:21:59.286 Return code variable: Autodetect; Lookup user groups: Yes
. 2009-11-16 09:21:59.286 Shell: default, EOL: 0
. 2009-11-16 09:21:59.286 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2009-11-16 09:21:59.286 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2009-11-16 09:21:59.286 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2009-11-16 09:21:59.286 Cache directory changes: Yes, Permanent: Yes
. 2009-11-16 09:21:59.286 DST mode: 1
. 2009-11-16 09:21:59.286 --------------------------------------------------------------------------
. 2009-11-16 09:21:59.286 Looking up host "11.22.33.44"
. 2009-11-16 09:21:59.286 Connecting to 11.22.33.44 port 22
. 2009-11-16 09:21:59.458 Server version: SSH-2.0-WS_FTP-SSH_1.0
. 2009-11-16 09:21:59.458 We claim version: SSH-2.0-WinSCP_release_4.1.9
. 2009-11-16 09:21:59.474 SSPI: acquired credentials for: <user>@<domain>
. 2009-11-16 09:21:59.474 Cannot convert IP address to SPN: DNS is not trusted
. 2009-11-16 09:21:59.474 GSSKEX disabled: The operation completed successfully.

. 2009-11-16 09:21:59.474 Using SSH protocol version 2
. 2009-11-16 09:21:59.552 Using Diffie-Hellman with standard group "group14"
. 2009-11-16 09:21:59.552 Doing Diffie-Hellman key exchange with hash SHA-1
. 2009-11-16 09:22:00.099 Host key fingerprint is:
. 2009-11-16 09:22:00.099 ssh-rsa 1024 blah.blah.blah
. 2009-11-16 09:22:00.099 Initialised AES-256 CBC client->server encryption
. 2009-11-16 09:22:00.099 Initialised HMAC-SHA1 client->server MAC algorithm
. 2009-11-16 09:22:00.192 Initialised AES-256 CBC server->client encryption
. 2009-11-16 09:22:00.192 Initialised HMAC-SHA1 server->client MAC algorithm
! 2009-11-16 09:22:00.271 Using username "<username>".
. 2009-11-16 09:22:00.599 Prompt (6, SSH password, , &Password: )
. 2009-11-16 09:22:00.599 Using stored password.
. 2009-11-16 09:22:00.599 Sent password
. 2009-11-16 09:22:00.724 Access granted
. 2009-11-16 09:22:00.802 Opened channel for session
. 2009-11-16 09:22:00.942 Started a shell/command
. 2009-11-16 09:22:00.942 --------------------------------------------------------------------------
. 2009-11-16 09:22:00.942 Using SFTP protocol.
. 2009-11-16 09:22:00.942 Doing startup conversation with host.
> 2009-11-16 09:22:00.942 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2009-11-16 09:22:01.021 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2009-11-16 09:22:01.021 SFTP version 4 negotiated.
. 2009-11-16 09:22:01.021 We will use UTF-8 strings when appropriate
. 2009-11-16 09:22:01.021 Getting current directory name.
. 2009-11-16 09:22:01.021 Getting real path for '.'
> 2009-11-16 09:22:01.021 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2009-11-16 09:22:02.005 Type: SSH_FXP_NAME, Size: 41, Number: 16
. 2009-11-16 09:22:02.005 Real path is '/sftphome/<username>'
. 2009-11-16 09:22:02.005 Startup conversation with host finished.
. 2009-11-16 09:22:02.005 Cached directory change via "/sftphome/<username>" to "/sftphome/<username>".
. 2009-11-16 09:22:02.005 Getting current directory name.
. 2009-11-16 09:22:02.005 Listing file "<filename>.bak".
> 2009-11-16 09:22:02.005 Type: SSH_FXP_LSTAT, Size: 48, Number: 263
< 2009-11-16 09:22:02.130 Type: SSH_FXP_ATTRS, Size: 46, Number: 263
. 2009-11-16 09:22:02.130 File: "/sftphome/<username>/<filename>.bak"
. 2009-11-16 09:22:02.130 Copying "/sftphome/<username>/<filename>.bak" to local directory started.
. 2009-11-16 09:22:02.130 Binary transfer mode selected.
. 2009-11-16 09:22:02.130 Checking existence of partially transfered file.
. 2009-11-16 09:22:02.130 Resuming file transfer.
. 2009-11-16 09:22:02.130 Opening remote file.
> 2009-11-16 09:22:02.130 Type: SSH_FXP_OPEN, Size: 53, Number: 515
< 2009-11-16 09:22:02.286 Type: SSH_FXP_HANDLE, Size: 12, Number: 515
> 2009-11-16 09:22:02.286 Type: SSH_FXP_FSTAT, Size: 16, Number: 776
> 2009-11-16 09:22:02.286 Type: SSH_FXP_READ, Size: 24, Number: 1029
. 2009-11-16 09:22:02.567 Storing reserved response
. 2009-11-16 09:27:04.886 Incorrect MAC received on packet
. 2009-11-16 09:27:04.886 Connection was lost, asking what to do.
. 2009-11-16 09:27:04.886 Asking user:
. 2009-11-16 09:27:04.886 Incorrect MAC received on packet ()

Thanks. Can you try the same with 4.2.4 beta?

martin wrote:

Thanks. Can you try the same with 4.2.4 beta?

Martin, I got the same result. Here is the log:

. 2009-11-30 15:25:19.521 --------------------------------------------------------------------------
. 2009-11-30 15:25:19.521 WinSCP Version 4.2.4 (Build 610) (OS 5.2.3790 Service Pack 2)
. 2009-11-30 15:25:19.521 Login time: Monday, November 30, 2009 3:25:19 PM
. 2009-11-30 15:25:19.521 --------------------------------------------------------------------------
. 2009-11-30 15:25:19.521 Session name: <username>@11.22.33.44
. 2009-11-30 15:25:19.521 Host name: 11.22.33.44 (Port: 22)
. 2009-11-30 15:25:19.521 User name: <username> (Password: Yes, Key file: No)
. 2009-11-30 15:25:19.521 Tunnel: No
. 2009-11-30 15:25:19.521 Transfer Protocol: SFTP (SCP)
. 2009-11-30 15:25:19.521 Ping type: -, Ping interval: 30 sec; Timeout: 15 sec
. 2009-11-30 15:25:19.521 Proxy: none
. 2009-11-30 15:25:19.521 SSH protocol version: 2; Compression: No
. 2009-11-30 15:25:19.521 Bypass authentication: No
. 2009-11-30 15:25:19.521 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: No
. 2009-11-30 15:25:19.521 Ciphers: aes,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2009-11-30 15:25:19.521 SSH Bugs: -,-,-,-,-,-,-,-,-
. 2009-11-30 15:25:19.521 SFTP Bugs: -,-
. 2009-11-30 15:25:19.521 Return code variable: Autodetect; Lookup user groups: Yes
. 2009-11-30 15:25:19.521 Shell: default, EOL: 0
. 2009-11-30 15:25:19.521 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes
. 2009-11-30 15:25:19.521 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No
. 2009-11-30 15:25:19.521 Local directory: default, Remote directory: home, Update: No, Cache: Yes
. 2009-11-30 15:25:19.521 Cache directory changes: Yes, Permanent: Yes
. 2009-11-30 15:25:19.521 DST mode: 1
. 2009-11-30 15:25:19.521 --------------------------------------------------------------------------
. 2009-11-30 15:25:19.521 Looking up host "11.22.33.44"
. 2009-11-30 15:25:19.521 Connecting to 11.22.33.44 port 22
. 2009-11-30 15:25:19.709 Server version: SSH-2.0-WS_FTP-SSH_1.0
. 2009-11-30 15:25:19.709 Using SSH protocol version 2
. 2009-11-30 15:25:19.709 We claim version: SSH-2.0-WinSCP_release_4.2.4
. 2009-11-30 15:25:19.803 Using Diffie-Hellman with standard group "group14"
. 2009-11-30 15:25:19.803 Doing Diffie-Hellman key exchange with hash SHA-1
. 2009-11-30 15:25:20.349 Host key fingerprint is:
. 2009-11-30 15:25:20.349 ssh-rsa 1024 blah:blah:blah
. 2009-11-30 15:25:20.349 Initialised AES-256 CBC client->server encryption
. 2009-11-30 15:25:20.349 Initialised HMAC-SHA1 client->server MAC algorithm
. 2009-11-30 15:25:20.443 Initialised AES-256 CBC server->client encryption
. 2009-11-30 15:25:20.443 Initialised HMAC-SHA1 server->client MAC algorithm
! 2009-11-30 15:25:20.537 Using username "<username>".
. 2009-11-30 15:25:20.803 Prompt (6, SSH password, , &Password: )
. 2009-11-30 15:25:20.803 Using stored password.
. 2009-11-30 15:25:20.803 Sent password
. 2009-11-30 15:25:20.928 Access granted
. 2009-11-30 15:25:21.021 Opened channel for session
. 2009-11-30 15:25:21.459 Started a shell/command
. 2009-11-30 15:25:21.459 --------------------------------------------------------------------------
. 2009-11-30 15:25:21.459 Using SFTP protocol.
. 2009-11-30 15:25:21.459 Doing startup conversation with host.
> 2009-11-30 15:25:21.474 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2009-11-30 15:25:21.568 Type: SSH_FXP_VERSION, Size: 5, Number: -1
. 2009-11-30 15:25:21.568 SFTP version 4 negotiated.
. 2009-11-30 15:25:21.568 We will use UTF-8 strings when appropriate
. 2009-11-30 15:25:21.568 Getting current directory name.
. 2009-11-30 15:25:21.568 Getting real path for '.'
> 2009-11-30 15:25:21.568 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2009-11-30 15:25:22.053 Type: SSH_FXP_NAME, Size: 41, Number: 16
. 2009-11-30 15:25:22.053 Real path is '/sftphome/<username>'
. 2009-11-30 15:25:22.053 Startup conversation with host finished.
. 2009-11-30 15:25:22.053 Cached directory change via "/sftphome/<username>" to "/sftphome/<username>".
. 2009-11-30 15:25:22.053 Getting current directory name.
. 2009-11-30 15:25:22.053 Listing file "<filename>.bak".
> 2009-11-30 15:25:22.053 Type: SSH_FXP_LSTAT, Size: 48, Number: 263
< 2009-11-30 15:25:22.193 Type: SSH_FXP_ATTRS, Size: 46, Number: 263
. 2009-11-30 15:25:22.193 File: "/sftphome/<username>/<filename>.bak"
. 2009-11-30 15:25:22.193 Copying "/sftphome/<username>/<filename>.bak" to local directory started.
. 2009-11-30 15:25:22.193 Binary transfer mode selected.
. 2009-11-30 15:25:22.193 Checking existence of partially transfered file.
. 2009-11-30 15:25:22.193 Confirming overwriting of file.
. 2009-11-30 15:25:22.193 Opening remote file.
> 2009-11-30 15:25:22.193 Type: SSH_FXP_OPEN, Size: 53, Number: 515
< 2009-11-30 15:25:22.303 Type: SSH_FXP_HANDLE, Size: 11, Number: 515
> 2009-11-30 15:25:22.303 Type: SSH_FXP_FSTAT, Size: 15, Number: 776
> 2009-11-30 15:25:22.303 Type: SSH_FXP_READ, Size: 23, Number: 1029
. 2009-11-30 15:25:22.537 Storing reserved response
. 2009-11-30 15:29:07.760 No valid incoming packet found
. 2009-11-30 15:29:07.760 Connection was lost, asking what to do.
. 2009-11-30 15:29:07.760 Asking user:
. 2009-11-30 15:29:07.760 No valid incoming packet found ()

____________________
David

Strange. Though I'm not aware of any related problem in WinSCP, so it may be as well caused by a bug in the server. Have you find any useful information in the server's log?

martin wrote:

... Have you find any useful information in the server's log?

Unfortunately, this is the server of a only slightly cooperative 3rd party (vendor), so I don't have access to server logs...

Martin, it occurred to me that regardless of what is causing the problem in communications in the first place, the real issue is that the program is attempting to ask the user what to do. In this case, where it is running from a script, there really isn't a user to ask. Would it be possible for the program to default the answer if it was running from a script?

davids wrote:

Martin, it occurred to me that regardless of what is causing the problem in communications in the first place, the real issue is that the program is attempting to ask the user what to do. In this case, where it is running from a script, there really isn't a user to ask. Would it be possible for the program to default the answer if it was running from a script?

The script should reconnect, if you have auto reconnect enabled (it has to be set in the GUI).

martin wrote:

The script should reconnect, if you have auto reconnect enabled (it has to be set in the GUI).

Auto reconnect is set in the GUI, and it works fine if I download using the GUI. (that's how I've been dealing with this weekly download so far - I have to run it manually from the GUI - and it typically automatically reconnects several times during the download)

It's just when I'm using the script that it seems to want the phantom user to answer a question, and then aborts, instead of automatically reconnecting.

This issue has been added to tracker.

martin wrote:

This issue has been added to tracker.

Martin, has there been any progress on this issue? The item in the Tracker still shows 'New'....

Not yet. Please wait for the next release.

Dear Martin,
we have a ssh server which port from openssh 5.3pl, and openssl 0.9.8l cropto toolkits. when I download a file larger than 30Mbytes, psftp works well, but when I use winscp4.2.7 as the sftp client, the following error often happened(about 50 persent):
"Incorrect MAC received on packet " and the ask for reconnect or disconnect .....
just as davids's problem.
Is this a known bug of winscp? Is it be resolved in version 4.2.7.
Thank you for your help.

What version of PSFTP are you using?

martin wrote:

Not yet. Please wait for the next release.

Martin, I may be confused, but it appears that there have been two releases since you wrote this... I keep hoping this bug will be addressed...

But these were bug-fixing releases. I do not consider this a bug.

Actually, if you prompt for a response when in scripting mode (where it is impossible to respond), then it should be considered a bug, don't you think?

Unless there is a way to respond in scripting mode to a (Abort, Retry) prompt that I dont know of.

Thanks for your help, I hope this is solved because Im having trouble with the same issue.
Here is my log:
******************************************
TIME OF UPLOAD 19:39:21
confirm off
batch on
reconnecttime 5
Connecting to ftp.spscommerce.net ...
Connected with ftp.spscommerce.net. Waiting for welcome message...
Connected
Starting the session...
Reading remote directory...
Session started.
Active session: [1] fendermi@ftp.spscommerce.net
/datamatxin
O_500_0000000004324916 | 18 KiB | 1.7 KiB/s | binary | 100%
O_500_0000000004324917 | 18 KiB | 10.3 KiB/s | binary | 100%
O_500_0000000004324918 | 18 KiB | 6.5 KiB/s | binary | 100%
O_500_0000000004324919 | 17 KiB | 8.6 KiB/s | binary | 100%
O_500_0000000004324920 | 17 KiB | 10.4 KiB/s | binary | 100%
O_500_0000000004324921 | 19 KiB | 12.2 KiB/s | binary | 100%
O_500_0000000004324922 | 18 KiB | 13.5 KiB/s | binary | 100%
O_500_0000000004324923 | 19 KiB | 14.8 KiB/s | binary | 100%
O_500_0000000004324924 | 19 KiB | 15.8 KiB/s | binary | 100%
O_500_0000000004324925 | 18 KiB | 16.7 KiB/s | binary | 100%
O_500_0000000004324926 | 19 KiB | 17.6 KiB/s | binary | 100%
O_500_0000000004324927 | 19 KiB | 18.4 KiB/s | binary | 100%
O_500_0000000004324928 | 18 KiB | 18.9 KiB/s | binary | 100%
O_500_0000000004324929 | 18 KiB | 19.5 KiB/s | binary | 100%
O_500_0000000004324930 | 16 KiB | 9.3 KiB/s | binary | 89%
Lost connection.
Timeout detected.
Copying files to remote side failed.
Opening BINARY mode data connection.
(A)bort, (R)econnect (5 s): Abort
Lost connection.
Timeout detected.
Copying files to remote side failed.
Opening BINARY mode data connection.
Copying files to remote side failed.
Session 'fendermi@ftp.spscommerce.net' closed.
No session.

LaFoca wrote:

Actually, if you prompt for a response when in scripting mode (where it is impossible to respond), then it should be considered a bug, don't you think?

Unless there is a way to respond in scripting mode to a (Abort, Retry) prompt that I dont know of.

I cannot read the whole thread over. So what is actually your problem? What version of WinSCP are you using?