PASV command sometimes returns IP of client, not server

Advertisement

Guest

PASV command sometimes returns IP of client, not server

Hi,
I'm scripting download of a bunch of files from an SFTP site. When the script runs, it downloads most of the files, but not all - the reason being that PASV is returning the IP of the client that winscp (5.13.2) is being run on, and not the IP of the server.
Here's the script:
option batch on
option confirm off
open ftpes://SITE_AND_PASSWORD_HERE:2010/
cd csavp/outtrans
lcd C:\Users\USER1\AppData\Local\Temp\getfiles
get A037PRD4.ZIP
get A037PED4.ZIP
get A037SRD4.ZIP
get A037SED4.ZIP
get Z_AN2236_181003.CAB
get Z_AN2237_181003.CAB
get Z_AN2238_181003.CAB
get Z_AN2239_181003.CAB
get Z_AN2240_181003.CAB
get Z_AN2241_181003.CAB
get Z_AN2262_181003.CAB
exit
This is the command line used to execute the script:
c:/winscp/winscp.com /script=sftp.txt /log=sftp.log
This is being run on Windows 7.

Here's a snippet of the log file showing that all the files exist (I'll attach the entire log):

. 2018-10-04 08:30:12.850 size=95584;type=file;create=20061011204105;modify=20181003213909; A037PED4.ZIP
. 2018-10-04 08:30:12.850 size=105247;type=file;create=20061011204108;modify=20181003213916; A037PRD4.ZIP
. 2018-10-04 08:30:12.851 size=8097;type=file;create=20061011204110;modify=20181003213920; A037SED4.ZIP
. 2018-10-04 08:30:12.851 size=42836;type=file;create=20061011204112;modify=20181003213924; A037SRD4.ZIP
. 2018-10-04 08:30:12.851 size=4010;type=file;create=20181003011735;modify=20181003000102; Z_AN2236_181003.CAB
. 2018-10-04 08:30:12.852 size=3385;type=file;create=20181003011733;modify=20181003000102; Z_AN2237_181003.CAB
. 2018-10-04 08:30:12.852 size=5912;type=file;create=20181003011755;modify=20181003000103; Z_AN2238_181003.CAB
. 2018-10-04 08:30:12.852 size=2317;type=file;create=20181003011756;modify=20181003000101; Z_AN2239_181003.CAB
. 2018-10-04 08:30:12.852 size=4026;type=file;create=20181003011752;modify=20181003000102; Z_AN2240_181003.CAB
. 2018-10-04 08:30:12.853 size=7922;type=file;create=20181003011706;modify=20181003000108; Z_AN2241_181003.CAB
. 2018-10-04 08:30:12.853 size=3893;type=file;create=20181003011722;modify=20181003000111; Z_AN2262_181003.CAB
Here's a snip of the log showing one successful download of A037PED4.ZIP (note I changed the server's IP to 5.5.5.5) and a failed download of A037SRD4.ZIP ( the workstation's IP is 192.168.10.96):

> 2018-10-04 08:30:13.072 Script: get A037PED4.ZIP
. 2018-10-04 08:30:13.072 Listing file "A037PED4.ZIP".
. 2018-10-04 08:30:13.072 Retrieving file information...
> 2018-10-04 08:30:13.072 MLST /csavp/outtrans/A037PED4.ZIP
< 2018-10-04 08:30:13.130 250-MLST listing for /csavp/outtrans/A037PED4.ZIP
< 2018-10-04 08:30:13.130 size=95584;type=file;create=20061011204105;modify=20181003213909; A037PED4.ZIP
< 2018-10-04 08:30:13.130 250 MLST end
. 2018-10-04 08:30:13.130 size=95584;type=file;create=20061011204105;modify=20181003213909; A037PED4.ZIP
. 2018-10-04 08:30:13.130 Retrieving file information successful
. 2018-10-04 08:30:13.131 A037PED4.ZIP;-;95584;2018-10-03T21:39:09.000Z;3;"" [0];"" [0];---------;0
. 2018-10-04 08:30:13.131 Copying 1 files/directories to local directory "C:\Users\USER1\AppData\Local\Temp\getfiles" - total size: 95,584
. 2018-10-04 08:30:13.131 PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: No; Mask:
. 2018-10-04 08:30:13.131 TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; InclM: ; ResumeL: 0
. 2018-10-04 08:30:13.131 AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2018-10-04 08:30:13.131 File: '/csavp/outtrans/A037PED4.ZIP' [2018-10-03T21:39:09.000Z] [95584]
. 2018-10-04 08:30:13.131 Copying "/csavp/outtrans/A037PED4.ZIP" to local directory started.
. 2018-10-04 08:30:13.131 Binary transfer mode selected.
. 2018-10-04 08:30:13.132 Starting download of /csavp/outtrans/A037PED4.ZIP
> 2018-10-04 08:30:13.132 CWD /csavp/outtrans
< 2018-10-04 08:30:13.169 250 Command CWD succeed
> 2018-10-04 08:30:13.169 PWD
< 2018-10-04 08:30:13.188 257 "/CSAVP/outtrans" is current directory
> 2018-10-04 08:30:13.188 TYPE A
< 2018-10-04 08:30:13.208 200 Transfer mode set to ASCII
> 2018-10-04 08:30:13.208 PASV
< 2018-10-04 08:30:13.228 227 Entering Passive Mode (5,5,5,5,7,219).
> 2018-10-04 08:30:13.228 MLSD
. 2018-10-04 08:30:13.228 Connecting to 5.5.5.5:2011 ...
< 2018-10-04 08:30:13.268 150 Transferring directory
. 2018-10-04 08:30:13.270 Session ID reused
. 2018-10-04 08:30:13.270 Using TLSv1.2, cipher TLSv1/SSLv3: AES256-GCM-SHA384, 2048 bit RSA, AES256-GCM-SHA384 TLSv1.2 Kx=RSA Au=RSA Enc=AESGCM(256) Mac=AEAD
. 2018-10-04 08:30:13.270 TLS connection established
< 2018-10-04 08:30:13.340 226 Transfer completed
. 2018-10-04 08:30:13.356 Data connection closed

FILES ARE LISTED AGAIN HERE...


> 2018-10-04 08:30:13.583 Script: get A037SRD4.ZIP
. 2018-10-04 08:30:13.583 Listing file "A037SRD4.ZIP".
. 2018-10-04 08:30:13.583 Retrieving file information...
> 2018-10-04 08:30:13.583 MLST /csavp/outtrans/A037SRD4.ZIP
< 2018-10-04 08:30:13.672 250-MLST listing for /csavp/outtrans/A037SRD4.ZIP
< 2018-10-04 08:30:13.672 size=42836;type=file;create=20061011204112;modify=20181003213924; A037SRD4.ZIP
< 2018-10-04 08:30:13.672 250 MLST end
. 2018-10-04 08:30:13.672 size=42836;type=file;create=20061011204112;modify=20181003213924; A037SRD4.ZIP
. 2018-10-04 08:30:13.672 Retrieving file information successful
. 2018-10-04 08:30:13.672 A037SRD4.ZIP;-;42836;2018-10-03T21:39:24.000Z;3;"" [0];"" [0];---------;0
. 2018-10-04 08:30:13.673 Copying 1 files/directories to local directory "C:\Users\USER1\AppData\Local\Temp\getfiles" - total size: 42,836
. 2018-10-04 08:30:13.673 PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: No; Mask:
. 2018-10-04 08:30:13.673 TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; InclM: ; ResumeL: 0
. 2018-10-04 08:30:13.673 AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2018-10-04 08:30:13.673 File: '/csavp/outtrans/A037SRD4.ZIP' [2018-10-03T21:39:24.000Z] [42836]
. 2018-10-04 08:30:13.673 Copying "/csavp/outtrans/A037SRD4.ZIP" to local directory started.
. 2018-10-04 08:30:13.673 Binary transfer mode selected.
. 2018-10-04 08:30:13.674 Starting download of /csavp/outtrans/A037SRD4.ZIP
> 2018-10-04 08:30:13.674 CWD /csavp/outtrans
< 2018-10-04 08:30:13.723 250 Command CWD succeed
> 2018-10-04 08:30:13.723 PWD
< 2018-10-04 08:30:13.743 257 "/CSAVP/outtrans" is current directory
> 2018-10-04 08:30:13.743 TYPE A
< 2018-10-04 08:30:13.762 200 Transfer mode set to ASCII
> 2018-10-04 08:30:13.762 PASV
< 2018-10-04 08:30:13.783 550 Command PASV failed
> 2018-10-04 08:30:13.783 PORT 192,168,10,96,223,144


< 2018-10-04 08:30:13.803 550 Command PORT failed
. 2018-10-04 08:30:13.803 Copying files from remote side failed.
* 2018-10-04 08:30:13.803 (ExtException) **Copying files from remote side failed.**
* 2018-10-04 08:30:13.803 Command PORT failed
. 2018-10-04 08:30:13.803 Asking user:
. 2018-10-04 08:30:13.803 Error transferring file '/csavp/outtrans/A037SRD4.ZIP'. ("Copying files from remote side failed.","Command PORT failed")
< 2018-10-04 08:30:13.803 Script: Error transferring file '/csavp/outtrans/A037SRD4.ZIP'.
< 2018-10-04 08:30:13.804 Script: Copying files from remote side failed.

< 2018-10-04 08:30:13.804 Command PORT failed
* 2018-10-04 08:30:13.805 (ESkipFile) Error transferring file '/csavp/outtrans/A037SRD4.ZIP'.
* 2018-10-04 08:30:13.805 Copying files from remote side failed.
* 2018-10-04 08:30:13.805 Command PORT failed
. 2018-10-04 08:30:13.805 Copying finished: Transferred: 0, Elapsed: 0:00:00, CPS: 0/s
. 2018-10-04 08:30:13.805 Script: Failed

The next file was OK, then another failure, then OK.... please refer to the log.

So far, on different days, we've had different files fail to download. When I launch winscp.com from a command prompt and download them manually, everything is fine.

Thanks for your help...
  • sftp.log (167.07 KB, Private file)

Reply with quote

Advertisement

martin
Site Admin
martin avatar
Joined:
Posts:
29,303
Location:
Prague, Czechia

Re: PASV command sometimes returns IP of client, not server

I do not see PASV returning a wrong IP address anywhere. It's that WinSCP falls back to PORT, as PASV fails. And PORT sends (correctly) client IP address.

The root problem is the failing of PASV. That's a server-side problem. A common cause of this problem is that the server runs out of free passive ports, due to a large number of file transfers. Check FTP server configuration and increase a passive port range, if possible. If that's not possible, you can try decreasing transfer speed on WinSCP side.

Reply with quote

Advertisement

You can post new topics in this forum