Connection fails randomly. 425 Cannot open data connection. 501 Server cannot accept argument.

Hi!

I use a winscp script to retreive files from a FTP in a SSIS-package.
The package contains a loop that in each "lap" gets a file using winscp.

The problem is that it fails randomly (to me that is). It can go trough the loop 20 times, picking up files but then fails on the 21st.
Sometimes it picks up one and then fails at the second.

Log below:
. 2015-10-15 15:55:49.238 Copying "/Extract/MailingList_8377267.csv" to local directory started.
. 2015-10-15 15:55:49.238 Binary transfer mode selected.
. 2015-10-15 15:55:49.238 Starting download of /Extract/MailingList_8377267.csv
> 2015-10-15 15:55:49.238 TYPE I
< 2015-10-15 15:55:49.285 200 Type set to I.
> 2015-10-15 15:55:49.285 PASV
< 2015-10-15 15:55:49.332 227 Entering Passive Mode (62,216,253,139,193,45).
> 2015-10-15 15:55:49.332 RETR MailingList_8377267.csv
< 2015-10-15 15:55:49.379 150 Opening BINARY mode data connection.
. 2015-10-15 15:55:49.426 Session ID reused
. 2015-10-15 15:55:49.426 TLS connection established
< 2015-10-15 15:55:52.865 226 Transfer complete.
. 2015-10-15 15:55:52.865 Download successful
. 2015-10-15 15:55:52.865 Transfer done: '/Extract/MailingList_8377267.csv' [18706119]
. 2015-10-15 15:55:52.865 File: '/Extract/MailingList_8377269.csv' [2015-10-06T13:39:00.000Z] [917904]
. 2015-10-15 15:55:52.865 Copying "/Extract/MailingList_8377269.csv" to local directory started.
. 2015-10-15 15:55:52.865 Binary transfer mode selected.
. 2015-10-15 15:55:52.865 Starting download of /Extract/MailingList_8377269.csv
> 2015-10-15 15:55:52.865 TYPE I
< 2015-10-15 15:55:52.896 200 Type set to I.
> 2015-10-15 15:55:52.896 PASV
< 2015-10-15 15:55:52.959 227 Entering Passive Mode (62,216,253,139,193,46).
> 2015-10-15 15:55:52.959 RETR MailingList_8377269.csv
< 2015-10-15 15:55:53.006 150 Opening BINARY mode data connection.
. 2015-10-15 15:55:53.037 Session ID reused
. 2015-10-15 15:55:53.037 TLS connection established
< 2015-10-15 15:55:53.427 226 Transfer complete.
. 2015-10-15 15:55:53.427 Download successful
. 2015-10-15 15:55:53.427 Transfer done: '/Extract/MailingList_8377269.csv' [917904]
. 2015-10-15 15:55:53.427 File: '/Extract/MailingList_8377275.csv' [2015-10-06T13:42:00.000Z] [1207004]
. 2015-10-15 15:55:53.427 Copying "/Extract/MailingList_8377275.csv" to local directory started.
. 2015-10-15 15:55:53.427 Binary transfer mode selected.
. 2015-10-15 15:55:53.427 Starting download of /Extract/MailingList_8377275.csv
> 2015-10-15 15:55:53.427 TYPE I
< 2015-10-15 15:55:53.474 200 Type set to I.
> 2015-10-15 15:55:53.474 PASV
< 2015-10-15 15:55:53.521 425 Cannot open data connection.
> 2015-10-15 15:55:53.521 PORT 172,16,38,15,195,48
< 2015-10-15 15:55:53.552 501 Server cannot accept argument.
. 2015-10-15 15:55:53.552 Copying files from remote side failed.
* 2015-10-15 15:55:53.552 (ExtException) **Copying files from remote side failed.**
* 2015-10-15 15:55:53.552 Server cannot accept argument.
. 2015-10-15 15:55:53.552 Asking user:
. 2015-10-15 15:55:53.552 Error transferring file '/Extract/MailingList_8377275.csv'. ("Copying files from remote side failed.","Server cannot accept argument.")
< 2015-10-15 15:55:53.552 Script: Error transferring file '/Extract/MailingList_8377275.csv'.
< 2015-10-15 15:55:53.552 Script: Copying files from remote side failed.

< 2015-10-15 15:55:53.552 Server cannot accept argument.
* 2015-10-15 15:55:53.552 (EScpSkipFile) Error transferring file '/Extract/MailingList_8377275.csv'.
* 2015-10-15 15:55:53.552 Copying files from remote side failed.
* 2015-10-15 15:55:53.552 Server cannot accept argument.
. 2015-10-15 15:55:53.552 Script: Failed
. 2015-10-15 15:55:53.552 Script: Exit code: 1
. 2015-10-15 15:55:53.568 Disconnected from server

Thanks in advance!

Do you have an access to server-side log?

No, not at this moment, I may be able to get them from the FTP-server provider.

Would it help much in locating the problem?

Thanks.

Probably, the error message comes from the server.

I got the server side logs but it doesn't seem to have log any errors (also according to the supplier..).

2015-10-15 13:55:51 188.65.153.171 COM\ftpnlfl 20.1.1.23 49451 DataChannelOpened - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:51 188.65.153.171 COM\ftpnlfl 20.1.1.23 49451 DataChannelClosed - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:51 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 RETR MailingList_8377260.csv 226 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba /Extract/MailingList_8377260.csv
2015-10-15 13:55:51 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 TYPE I 200 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:51 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 PASV - 227 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:51 188.65.153.171 COM\ftpnlfl 20.1.1.23 49452 DataChannelOpened - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:52 188.65.153.171 COM\ftpnlfl 20.1.1.23 49452 DataChannelClosed - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:52 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 RETR MailingList_8377263.csv 226 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba /Extract/MailingList_8377263.csv
2015-10-15 13:55:52 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 TYPE I 200 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:52 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 PASV - 227 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:52 188.65.153.171 COM\ftpnlfl 20.1.1.23 49453 DataChannelOpened - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 49453 DataChannelClosed - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 RETR MailingList_8377267.csv 226 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba /Extract/MailingList_8377267.csv
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 TYPE I 200 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 PASV - 227 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 49454 DataChannelOpened - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 49454 DataChannelClosed - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 RETR MailingList_8377269.csv 226 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba /Extract/MailingList_8377269.csv
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 TYPE I 200 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 PASV - 425 10013 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 PORT 172,16,38,15,195,48 501 87 38 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 ControlChannelClosed - - 0 0 4f4c45b7-5f45-4147-896b-63eb83378aba

But you can see in the logs that the server really fails the requests:

2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 PASV - 425 10013 0 4f4c45b7-5f45-4147-896b-63eb83378aba -
2015-10-15 13:55:56 188.65.153.171 COM\ftpnlfl 20.1.1.23 21 PORT 172,16,38,15,195,48 501 87 38 4f4c45b7-5f45-4147-896b-63eb83378aba -

But cannot help you without knowing why it failed the requests.

What server is that? IIS?

Hi!

Yes, it is an IIS server.

Isn't the server running out of free data connection ports?

Hi!

Got this from the server provider:

After the 425 error occurs, another connection is attempted in active mode (PORT 172,16,38,15,224,85).
The 501 error is then returned because this mode is not supported by the server.

Therefore the relevant error here is the 425 Cannot open data connection.
[...]
This error is one that is almost always a result of a network or configuration issue on the client side.

WHat do you make of this?

Thanks in advance!

NOS wrote:

This error is one that is almost always a result of a network or configuration issue on the client side.

WHat do you make of this?

Well, that would be true if the server responded first 227 Entering Passive Mode to the PASV command and WinSCP failed to connect to the provided port. But in this case the server responded 425 directly to the PASV command, so WinSCP could not even try to connect. (Assuming the log file you've sent is complete).

Ok!

I've attached the complete log file. The error occurs at the end of it.

Thanks.

Thanks. I do not see any possibility for a client-side network/firewall issue here.


The server fails the PASV request immediately. So it is the server that has problems opening the data connection port.

For this to be a client-side issue, the server would had to have responded with 227 Entering Passive Mode and only then timed out waiting for the client to connect. This didn't happen.

Thanks a lot for your response. The vendor replied the following:

"The ‘PASV – 425 10013’ error indicates that the session either ran out of available dynamic ports or attempted to use a port that was already in use. Either way, this is a transient error that is not uncommon on busy servers.

Typically, applications include error handling to retry the connection after a given delay or delay cycle.

I understand that there is no native error handling in WinSCP scripts. Our DBA writes the error handling into the calling application e.g.:

1. The calling application triggers the WinSCP script
2. After the script finishes running (with or without success), the calling application verifies the existence of the expected files and continues appropriately"

Is there any way to prevent this error from happening? Can I within WinSCP retry until it succeeds?

Thanks.

nos wrote:

Is there any way to prevent this error from happening? Can I within WinSCP retry until it succeeds?

WinSCP cannot retry in this case.

You run WinSCP in loop already. So it should pickup the file the ext time, right?

martin wrote:

nos wrote:

Is there any way to prevent this error from happening? Can I within WinSCP retry until it succeeds?

WinSCP cannot retry in this case.

You run WinSCP in loop already. So it should pickup the file the ext time, right?

Yes, it runs in a loop but it takes a new file each "lap". I have to make sure that it tries to move the file until it succeeds.

Isn't it possible to do with "option reconnecttime 30"? Or that doesn't mean that it will try to reconnect every 30 seconds until it succeeds?

Thanks.

NOS wrote:

Isn't it possible to do with "option reconnecttime 30"? Or that doesn't mean that it will try to reconnect every 30 seconds until it succeeds?

It's to reconnect the control connection. But that does not disconnect.

martin wrote:

NOS wrote:

Isn't it possible to do with "option reconnecttime 30"? Or that doesn't mean that it will try to reconnect every 30 seconds until it succeeds?

It's to reconnect the control connection. But that does not disconnect.

Ah, okey.
Do you have any suggestion on how we can deal with this problem?

At the moment the WinSCP script is called by a "Execute process Task" component in SSIS. I was thinking that maybe with the use of a script component run a shell command with the C# code and try to implement error handling within that component. Any input?

NOS wrote:

At the moment the WinSCP script is called by a "Execute process Task" component in SSIS. I was thinking that maybe with the use of a script component run a shell command with the C# code and try to implement error handling within that component. Any input?

That's definitely doable.

But wouldn't it be easier to just wrap your current script to a batch file and loop until it succeeds?