Forum » Support and Bug Reports »

FTP transfers failing after WinSCP upgrade

Advertisement

Tink
Guest

FTP transfers failing after WinSCP upgrade

Just inherited a file transfer solution that was using WinSCP V5.1.0.2625 to FTP between networks to an MS IIS service on W2K8R2. Everything ran as expected.
After upgrading the client to WinSCP V5.19.5.11933 all the FTP transfers fail with "access denied". The userid and password used are valid and not locked out.
Using Task Schedular a .cmd is run to invoke WinSCP with a WinSCP script. All pretty simple on the face of it!
What has changed between WinSCP versions that could cause the failure? 
open ftp://userid:ComplexPassword@10.100.xxx.x:2121 -explicitSSL -hostkey="xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:f9:b3:e4:55:2b:17:dc:c9:fe:44" -timeout=30
cd /TransferIn
lcd D:\TransferIn\
get *
exit
The resulting logfile: 
. 2022-02-03 10:00:10.354 --------------------------------------------------------------------------
. 2022-02-03 10:00:10.354 WinSCP Version 5.19.5 (Build 11933 2021-11-25) (OS 6.1.7601 Service Pack 1 - Windows Server 2008 R2 Standard)
. 2022-02-03 10:00:10.354 Configuration: nul
. 2022-02-03 10:00:10.354 Log level: Normal
. 2022-02-03 10:00:10.354 Local account: DOMAIN\userid
. 2022-02-03 10:00:10.354 Working directory: C:\Users\userid.DOMAIN\Desktop
. 2022-02-03 10:00:10.354 Process ID: 8460
. 2022-02-03 10:00:10.354 Ancestor processes: ...
. 2022-02-03 10:00:10.354 Command-line: "D:\Program Files (x86)\WinSCP\WinSCP.exe"  /log="D:\Logs\Test519-Run.log" /ini=nul /script="D:\Program Files (x86)\WinSCP\Scripts\Test519-Run.txt"
. 2022-02-03 10:00:10.354 Time zone: Current: GMT+0, Standard: GMT+0 (GMT Standard Time), DST: GMT+1 (GMT Daylight Time), DST Start: 27/03/2022, DST End: 30/10/2022
. 2022-02-03 10:00:10.354 Login time: 03 February 2022 10:00:10
. 2022-02-03 10:00:10.354 --------------------------------------------------------------------------
. 2022-02-03 10:00:10.354 Script: Retrospectively logging previous script records:
> 2022-02-03 10:00:10.354 Script: open ftp://userid:***@10.100.xxx.x:2121 -explicitSSL -hostkey="xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:b3:e4:55:2b:17:dc:c9:fe:44" -timeout=30
. 2022-02-03 10:00:10.354 --------------------------------------------------------------------------
. 2022-02-03 10:00:10.354 Session name: userid@10.100.xxx.x (Ad-Hoc site)
. 2022-02-03 10:00:10.354 Host name: 10.100.xxx.x (Port: 2121)
. 2022-02-03 10:00:10.354 User name: userid (Password: Yes, Key file: No, Passphrase: No)
. 2022-02-03 10:00:10.354 Transfer Protocol: FTP
. 2022-02-03 10:00:10.354 Ping type: Dummy, Ping interval: 30 sec; Timeout: 30 sec
. 2022-02-03 10:00:10.354 Disable Nagle: No
. 2022-02-03 10:00:10.354 Proxy: None
. 2022-02-03 10:00:10.354 Send buffer: 262144
. 2022-02-03 10:00:10.354 UTF: Auto
. 2022-02-03 10:00:10.354 FTPS: Explicit SSL/TLS [Client certificate: No]
. 2022-02-03 10:00:10.354 FTP: Passive: Yes [Force IP: Auto]; MLSD: Auto [List all: Auto]; HOST: Auto
. 2022-02-03 10:00:10.354 Session reuse: Yes
. 2022-02-03 10:00:10.354 TLS/SSL versions: TLSv1.0-TLSv1.3
. 2022-02-03 10:00:10.354 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2022-02-03 10:00:10.354 Cache directory changes: Yes, Permanent: Yes
. 2022-02-03 10:00:10.354 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2022-02-03 10:00:10.354 Timezone offset: 0h 0m
. 2022-02-03 10:00:10.354 --------------------------------------------------------------------------
< 2022-02-03 10:00:10.354 Script: Connecting to 10.100.xxx.x:2121 ...
. 2022-02-03 10:00:10.354 Connecting to 10.100.xxx.x:2121 ...
. 2022-02-03 10:00:10.354 Connected with 10.100.xxx.x:2121, negotiating TLS connection...
< 2022-02-03 10:00:10.370 220 Microsoft FTP Service
> 2022-02-03 10:00:10.370 AUTH SSL
< 2022-02-03 10:00:10.370 234 AUTH command ok. Expecting TLS Negotiation.
. 2022-02-03 10:00:10.370 Verifying certificate for "XXX" with fingerprint xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:xx:3e:41:87:87:c4:11:9a:82:b4:15:62:85:59:26:c0:76:6f:37 and 20 failures
. 2022-02-03 10:00:10.370 Certificate for "XXX" matches configured fingerprint
. 2022-02-03 10:00:10.370 Using TLSv1, cipher SSLv3: AES128-SHA, 2048 bit RSA, AES128-SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(128)  Mac=SHA1
< 2022-02-03 10:00:10.370 Script: TLS connection established. Waiting for welcome message...
. 2022-02-03 10:00:10.370 TLS connection established. Waiting for welcome message...
> 2022-02-03 10:00:10.370 USER userid
< 2022-02-03 10:00:10.370 331 Password required for userid.
> 2022-02-03 10:00:10.370 PASS **
< 2022-02-03 10:00:10.386 530 User cannot log in.
. 2022-02-03 10:00:10.386 Connection failed.
< 2022-02-03 10:00:10.386 Script: Access denied.
. 2022-02-03 10:00:10.386 Password prompt (last login attempt failed)
< 2022-02-03 10:00:10.386 Script: Authentication failed.

Reply with quote

Advertisement

martin◆
Site Admin
martin avatar
Joined:
Posts:
41,454
Location:
Prague, Czechia

Re: FTP transfers failing after WinSCP upgrade

Can you post log file from 5.1.0 too? Are there any special characters in your credentials?

Reply with quote

Guest

Martin,

Yes, special characters used in password ; and $ 
. 2022-02-06 22:30:00.322 --------------------------------------------------------------------------
. 2022-02-06 22:30:00.322 WinSCP Version 5.1.0 (Build 2625) (OS 6.1.7601 Service Pack 1)
. 2022-02-06 22:30:00.322 Configuration: HKEY_CURRENT_USER\Software\Martin Prikryl\WinSCP 2\
. 2022-02-06 22:30:00.322 Local account: DOMAIN\userid
. 2022-02-06 22:30:00.322 Working directory: D:\Program Files (x86)\WinSCP
. 2022-02-06 22:30:00.322 Command-line: "D:\Program Files (x86)\WinSCP\WinSCP.exe" /script=scripts\intelliupdates.txt /log=logs\intelliupdateslogs.txt
. 2022-02-06 22:30:00.322 Login time: 06 February 2022 22:30:00
. 2022-02-06 22:30:00.322 --------------------------------------------------------------------------
. 2022-02-06 22:30:00.322 Session name: userid@10.100.xxx.x (Ad-Hoc session)
. 2022-02-06 22:30:00.322 Host name: 10.100.xxx.x (Port: 2121)
. 2022-02-06 22:30:00.322 User name: userid (Password: Yes, Key file: No)
. 2022-02-06 22:30:00.322 Tunnel: No
. 2022-02-06 22:30:00.322 Transfer Protocol: FTP
. 2022-02-06 22:30:00.322 Ping type: C, Ping interval: 30 sec; Timeout: 15 sec
. 2022-02-06 22:30:00.322 Proxy: none
. 2022-02-06 22:30:00.322 FTP: FTPS: Explicit SSL; Passive: Yes [Force IP: A]
. 2022-02-06 22:30:00.322 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2022-02-06 22:30:00.322 Cache directory changes: Yes, Permanent: Yes
. 2022-02-06 22:30:00.322 DST mode: 1
. 2022-02-06 22:30:00.322 --------------------------------------------------------------------------
. 2022-02-06 22:30:00.322 Connecting to 10.100.xxx.x:2121 ...
. 2022-02-06 22:30:00.322 Connected with 10.100.xxx.x:2121, negotiating SSL connection...
< 2022-02-06 22:30:00.322 220 Microsoft FTP Service
> 2022-02-06 22:30:00.322 AUTH SSL
< 2022-02-06 22:30:00.337 234 AUTH command ok. Expecting TLS Negotiation.
. 2022-02-06 22:30:00.446 SSL connection established. Waiting for welcome message...
> 2022-02-06 22:30:00.446 USER userid
< 2022-02-06 22:30:00.446 331 Password required for userid.
> 2022-02-06 22:30:00.446 PASS *************************
< 2022-02-06 22:30:00.446 230 User logged in.
> 2022-02-06 22:30:00.446 SYST
< 2022-02-06 22:30:00.462 215 Windows_NT
> 2022-02-06 22:30:00.462 FEAT
< 2022-02-06 22:30:00.462 211-Extended features supported:
< 2022-02-06 22:30:00.462  LANG EN*
< 2022-02-06 22:30:00.462  UTF8
< 2022-02-06 22:30:00.462  AUTH TLS;TLS-C;SSL;TLS-P;
< 2022-02-06 22:30:00.462  PBSZ
< 2022-02-06 22:30:00.462  PROT C;P;
< 2022-02-06 22:30:00.462  CCC
< 2022-02-06 22:30:00.462  HOST
< 2022-02-06 22:30:00.462  SIZE
< 2022-02-06 22:30:00.462  MDTM
< 2022-02-06 22:30:00.462  REST STREAM
< 2022-02-06 22:30:00.462 211 END
> 2022-02-06 22:30:00.462 OPTS UTF8 ON
< 2022-02-06 22:30:00.462 200 OPTS UTF8 command successful - UTF8 encoding now ON.
> 2022-02-06 22:30:00.462 PBSZ 0
< 2022-02-06 22:30:00.478 200 PBSZ command successful.
> 2022-02-06 22:30:00.478 PROT P
< 2022-02-06 22:30:00.478 200 PROT command successful.
. 2022-02-06 22:30:00.478 Connected
. 2022-02-06 22:30:00.478 --------------------------------------------------------------------------
. 2022-02-06 22:30:00.478 Using FTP protocol.
. 2022-02-06 22:30:00.478 Doing startup conversation with host.
> 2022-02-06 22:30:00.478 PWD
< 2022-02-06 22:30:00.478 257 "/" is current directory.
. 2022-02-06 22:30:00.478 Getting current directory name.
. 2022-02-06 22:30:00.478 Startup conversation with host finished.
< 2022-02-06 22:30:00.478 Script: Active session: [1] userid@10.100.xxx.x
. 2022-02-07 22:30:00.423 --------------------------------------------------------------------------
. 2022-02-07 22:30:00.423 WinSCP Version 5.1.0 (Build 2625) (OS 6.1.7601 Service Pack 1)
. 2022-02-07 22:30:00.423 Configuration: HKEY_CURRENT_USER\Software\Martin Prikryl\WinSCP 2\
. 2022-02-07 22:30:00.423 Local account: DOMAIN\userid
. 2022-02-07 22:30:00.423 Working directory: D:\Program Files (x86)\WinSCP
. 2022-02-07 22:30:00.423 Command-line: "D:\Program Files (x86)\WinSCP\WinSCP.exe" /script=scripts\intelliupdates.txt /log=logs\intelliupdateslogs.txt
. 2022-02-07 22:30:00.423 Login time: 07 February 2022 22:30:00
. 2022-02-07 22:30:00.423 --------------------------------------------------------------------------
. 2022-02-07 22:30:00.423 Session name: userid@10.100.xxx.x (Ad-Hoc session)
. 2022-02-07 22:30:00.423 Host name: 10.100.xxx.x (Port: 2121)
. 2022-02-07 22:30:00.423 User name: userid (Password: Yes, Key file: No)
. 2022-02-07 22:30:00.423 Tunnel: No
. 2022-02-07 22:30:00.423 Transfer Protocol: FTP
. 2022-02-07 22:30:00.423 Ping type: C, Ping interval: 30 sec; Timeout: 15 sec
. 2022-02-07 22:30:00.423 Proxy: none
. 2022-02-07 22:30:00.423 FTP: FTPS: Explicit SSL; Passive: Yes [Force IP: A]
. 2022-02-07 22:30:00.423 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2022-02-07 22:30:00.423 Cache directory changes: Yes, Permanent: Yes
. 2022-02-07 22:30:00.423 DST mode: 1
. 2022-02-07 22:30:00.423 --------------------------------------------------------------------------
. 2022-02-07 22:30:00.438 Connecting to 10.100.xxx.x:2121 ...
. 2022-02-07 22:30:00.438 Connected with 10.100.xxx.x:2121, negotiating SSL connection...
< 2022-02-07 22:30:00.438 220 Microsoft FTP Service
> 2022-02-07 22:30:00.438 AUTH SSL
< 2022-02-07 22:30:00.438 234 AUTH command ok. Expecting TLS Negotiation.
. 2022-02-07 22:30:00.594 SSL connection established. Waiting for welcome message...
> 2022-02-07 22:30:00.594 USER userid
< 2022-02-07 22:30:00.594 331 Password required for userid.
> 2022-02-07 22:30:00.594 PASS *************************
< 2022-02-07 22:30:00.594 230 User logged in.
> 2022-02-07 22:30:00.594 SYST
< 2022-02-07 22:30:00.594 215 Windows_NT
> 2022-02-07 22:30:00.594 FEAT
< 2022-02-07 22:30:00.594 211-Extended features supported:
< 2022-02-07 22:30:00.594  LANG EN*
< 2022-02-07 22:30:00.594  UTF8
< 2022-02-07 22:30:00.594  AUTH TLS;TLS-C;SSL;TLS-P;
< 2022-02-07 22:30:00.594  PBSZ
< 2022-02-07 22:30:00.594  PROT C;P;
< 2022-02-07 22:30:00.594  CCC
< 2022-02-07 22:30:00.594  HOST
< 2022-02-07 22:30:00.594  SIZE
< 2022-02-07 22:30:00.594  MDTM
< 2022-02-07 22:30:00.594  REST STREAM
< 2022-02-07 22:30:00.594 211 END
> 2022-02-07 22:30:00.594 OPTS UTF8 ON
< 2022-02-07 22:30:00.610 200 OPTS UTF8 command successful - UTF8 encoding now ON.
> 2022-02-07 22:30:00.610 PBSZ 0
< 2022-02-07 22:30:00.610 200 PBSZ command successful.
> 2022-02-07 22:30:00.610 PROT P
< 2022-02-07 22:30:00.610 200 PROT command successful.
. 2022-02-07 22:30:00.610 Connected
. 2022-02-07 22:30:00.610 --------------------------------------------------------------------------
. 2022-02-07 22:30:00.610 Using FTP protocol.
. 2022-02-07 22:30:00.610 Doing startup conversation with host.
> 2022-02-07 22:30:00.610 PWD
< 2022-02-07 22:30:00.610 257 "/" is current directory.
. 2022-02-07 22:30:00.610 Getting current directory name.
. 2022-02-07 22:30:00.610 Startup conversation with host finished.
< 2022-02-07 22:30:00.610 Script: Active session: [1] userid@10.100.xxx.x
> 2022-02-07 22:30:00.610 Script: cd /IntelliUpdate
. 2022-02-07 22:30:00.610 Cached directory change via "/IntelliUpdate" to "/IntelliUpdate".
. 2022-02-07 22:30:00.610 Getting current directory name.
< 2022-02-07 22:30:00.610 Script: /IntelliUpdate
> 2022-02-07 22:30:00.610 Script: Get *.* d:\transfer\IntelliUpdate\
. 2022-02-07 22:30:00.610 Retrieving directory listing...
> 2022-02-07 22:30:00.610 CWD /IntelliUpdate/
< 2022-02-07 22:30:00.610 250 CWD command successful.
> 2022-02-07 22:30:00.610 PWD
< 2022-02-07 22:30:00.610 257 "/IntelliUpdate" is current directory.
> 2022-02-07 22:30:00.610 TYPE A
< 2022-02-07 22:30:00.625 200 Type set to A.
> 2022-02-07 22:30:00.625 PASV
< 2022-02-07 22:30:00.625 227 Entering Passive Mode (10,100,xxx,x,197,253).
> 2022-02-07 22:30:00.625 LIST -a
< 2022-02-07 22:30:00.625 150 Opening ASCII mode data connection.
. 2022-02-07 22:30:00.641 SSL connection established
< 2022-02-07 22:30:00.641 226 Transfer complete.
. 2022-02-07 22:30:00.641 Directory listing successful
. 2022-02-07 22:30:00.641 File: "/IntelliUpdate/vd608c02core3sds.jdb"
. 2022-02-07 22:30:00.641 Copying "/IntelliUpdate/vd608c02core3sds.jdb" to local directory started.
. 2022-02-07 22:30:00.641 Binary transfer mode selected.
. 2022-02-07 22:30:00.641 Starting download of /IntelliUpdate/vd608c02core3sds.jdb
> 2022-02-07 22:30:00.641 TYPE I
< 2022-02-07 22:30:00.641 200 Type set to I.
> 2022-02-07 22:30:00.641 PASV
< 2022-02-07 22:30:00.641 227 Entering Passive Mode (10,100,xxx,x,197,251).
> 2022-02-07 22:30:00.641 RETR vd608c02core3sds.jdb
< 2022-02-07 22:30:00.641 150 Opening BINARY mode data connection.
. 2022-02-07 22:30:01.437 SSL connection established
< 2022-02-07 22:30:11.639 226 Transfer complete.
. 2022-02-07 22:30:11.655 Download successful
. 2022-02-07 22:30:11.655 File: "/IntelliUpdate/vd608c02core3sdsi64.jdb"
. 2022-02-07 22:30:11.655 Copying "/IntelliUpdate/vd608c02core3sdsi64.jdb" to local directory started.
. 2022-02-07 22:30:11.655 Binary transfer mode selected.
. 2022-02-07 22:30:11.655 Starting download of /IntelliUpdate/vd608c02core3sdsi64.jdb
> 2022-02-07 22:30:11.655 TYPE I
< 2022-02-07 22:30:11.655 200 Type set to I.
> 2022-02-07 22:30:11.655 PASV
< 2022-02-07 22:30:11.655 227 Entering Passive Mode (10,100,xxx,x,197,253).
> 2022-02-07 22:30:11.655 RETR vd608c02core3sdsi64.jdb
< 2022-02-07 22:30:11.655 150 Opening BINARY mode data connection.
. 2022-02-07 22:30:12.591 SSL connection established
< 2022-02-07 22:30:23.901 226 Transfer complete.
. 2022-02-07 22:30:23.916 Download successful
> 2022-02-07 22:30:23.916 Script: exit
. 2022-02-07 22:30:23.916 Script: Exit code: 0
. 2022-02-07 22:30:23.916 Disconnected from server

Reply with quote

martin◆
Site Admin
martin avatar
Joined:
Posts:
41,454
Location:
Prague, Czechia

Did you edit the PASS command in the logs? The 5.19.5 log show 2-letter password, while 5.1 log shows 25-letter password. Please double check the password in the 5.19.5 script. Also, the logs show that you are not using the same script. Please test the two versions with the exactly same script and in the exactly same environment.

If the passwords, scripts and environment match, can you try to find out, what is the last version of WinSCP that works with the password, script and environment used by 5.10?

Reply with quote

Tink
Guest

Martin,
I think it's todo with special characters in the password.
The 3rd character of the password is in fact $, so I substituded it for %24 and it works.

You said, "The 5.19.5 log show 2-letter password, while 5.1 log shows 25-letter password"
Could WinSCP be only recognising the first 2 valid characters then dropping out at the $?

I will do more testing to confirm but pretty sure it special characters in the password, in the scripts.

Reply with quote

Advertisement

martin◆
Site Admin
martin avatar
Joined:
Posts:
41,454
Location:
Prague, Czechia

The $ is not a special character for WinSCP.
Are you putting the $ to manually created script file? That should not cause any problems.
Or are you actually generating the WinSCP script in some scripting language, where $ sign has special meaning (such a PowerShell or PHP)? Then the $ won't make it to the WinSCP script.
Enable password logging using /loglevel=* to see the exact commands (including the password) that WinSCP reads from the script. If you can reproduce WinSCP reading a different password, that what is stored in the script file, please post the script file (even with fake credentials).

Reply with quote

Tink
Guest

Hi Martin,

Had to use Portable version of V5.19 so as not to interfere with existing setup but clearly shows the issue with passwords. It looks like $ is a special character

The script invoked via MS Task Scheduler: 
option batch continue
option confirm off
option transfer binary
 
# logon details to drop server
open ftp://LogonId:VJ%3BP%24tXpN6SMZiEsa%24ydquMbX@xx.xxx.xxx.x:2121/ -explicitSSL -hostkey="obsfucated"
 
cd /IntelliUpdate
lcd D:\Transfer\IntelliUpdate
 
# Get files from \transfer\Intelliupdate to equivalent on IL5 server
Get *.* d:\transfer\IntelliUpdate\
exit

The captured logfile with loglevel=*: 
. 2022-02-14 10:59:36.633 --------------------------------------------------------------------------
. 2022-02-14 10:59:36.633 WinSCP Version 5.19.5 (Build 11933 2021-11-25) (OS 6.1.7601 Service Pack 1 - Windows Server 2008 R2 Standard)
. 2022-02-14 10:59:36.633 Configuration: nul
. 2022-02-14 10:59:36.633 Log level: Normal, Logging passwords
. 2022-02-14 10:59:36.633 Local account: DOMAIN\LogonId
. 2022-02-14 10:59:36.633 Working directory: D:\Buildsoftware\WinSCPPortable V5.19\App\winscp
. 2022-02-14 10:59:36.633 Process ID: 2812
. 2022-02-14 10:59:36.633 Ancestor processes: ...
. 2022-02-14 10:59:36.633 Command-line: winscp.exe  /loglevel=* /ini=nul /script=MGTEST.TXT /log=MGTESTlog.txt 
. 2022-02-14 10:59:36.633 Time zone: Current: GMT+0, Standard: GMT+0 (GMT Standard Time), DST: GMT+1 (GMT Daylight Time), DST Start: 27/03/2022, DST End: 30/10/2022
. 2022-02-14 10:59:36.633 Login time: 14 February 2022 10:59:36
. 2022-02-14 10:59:36.633 --------------------------------------------------------------------------
. 2022-02-14 10:59:36.633 Script: Retrospectively logging previous script records:
> 2022-02-14 10:59:36.633 Script: option batch continue
< 2022-02-14 10:59:36.633 Script: batch           continue  
> 2022-02-14 10:59:36.633 Script: option confirm off
< 2022-02-14 10:59:36.633 Script: confirm         off       
> 2022-02-14 10:59:36.633 Script: option transfer binary
< 2022-02-14 10:59:36.633 Script: transfer        binary    
> 2022-02-14 10:59:36.633 Script: open ftp://LogonId:VJ%3BP%24tXpN6SMZiEsa%24ydquMbX@xx.xxx.xxx.x:2121/ -explicitSSL -hostkey="obsfucated !"
. 2022-02-14 10:59:36.633 --------------------------------------------------------------------------
. 2022-02-14 10:59:36.633 Session name: LogonId@xx.xxx.xxx.x (Ad-Hoc site)
. 2022-02-14 10:59:36.633 Host name: xx.xxx.xxx.x (Port: 2121)
. 2022-02-14 10:59:36.633 User name: LogonId (Password: VJ;P$tXpN6SMZiEsa$ydquMbX, Key file: No, Passphrase: No)
. 2022-02-14 10:59:36.633 Transfer Protocol: FTP
. 2022-02-14 10:59:36.633 Ping type: Dummy, Ping interval: 30 sec; Timeout: 15 sec
. 2022-02-14 10:59:36.633 Disable Nagle: No
. 2022-02-14 10:59:36.633 Proxy: None
. 2022-02-14 10:59:36.633 Send buffer: 262144
. 2022-02-14 10:59:36.633 UTF: Auto
. 2022-02-14 10:59:36.633 FTPS: Explicit SSL/TLS [Client certificate: No]
. 2022-02-14 10:59:36.633 FTP: Passive: Yes [Force IP: Auto]; MLSD: Auto [List all: Auto]; HOST: Auto
. 2022-02-14 10:59:36.633 Session reuse: Yes
. 2022-02-14 10:59:36.633 TLS/SSL versions: TLSv1.0-TLSv1.3
. 2022-02-14 10:59:36.633 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2022-02-14 10:59:36.633 Cache directory changes: Yes, Permanent: Yes
. 2022-02-14 10:59:36.633 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2022-02-14 10:59:36.633 Timezone offset: 0h 0m
. 2022-02-14 10:59:36.633 --------------------------------------------------------------------------
< 2022-02-14 10:59:36.633 Script: Connecting to xx.xxx.xxx.x:2121 ...
. 2022-02-14 10:59:36.633 Connecting to xx.xxx.xxx.x:2121 ...
. 2022-02-14 10:59:36.648 Connected with xx.xxx.xxx.x:2121, negotiating TLS connection...
< 2022-02-14 10:59:36.648 220 Microsoft FTP Service
> 2022-02-14 10:59:36.648 AUTH SSL
< 2022-02-14 10:59:36.648 234 AUTH command ok. Expecting TLS Negotiation.
. 2022-02-14 10:59:36.648 Verifying certificate for "XXX" with fingerprint "obsfucated" and 20 failures
. 2022-02-14 10:59:36.648 Certificate for "XXX" matches configured fingerprint
. 2022-02-14 10:59:36.648 Using TLSv1, cipher SSLv3: AES128-SHA, 2048 bit RSA, AES128-SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(128)  Mac=SHA1
< 2022-02-14 10:59:36.648 Script: TLS connection established. Waiting for welcome message...
. 2022-02-14 10:59:36.648 TLS connection established. Waiting for welcome message...
> 2022-02-14 10:59:36.648 USER LogonId
< 2022-02-14 10:59:36.648 331 Password required for LogonId.
> 2022-02-14 10:59:36.648 PASS VJ;P$tXpN6SMZiEsa$ydquMbX
< 2022-02-14 10:59:36.648 230 User logged in.
> 2022-02-14 10:59:36.648 SYST
. 2022-02-14 10:59:36.648 The server is probably running Windows, assuming that directory listing timestamps are affected by DST.
< 2022-02-14 10:59:36.648 215 Windows_NT
> 2022-02-14 10:59:36.664 FEAT
< 2022-02-14 10:59:36.664 211-Extended features supported:
< 2022-02-14 10:59:36.664  LANG EN*
< 2022-02-14 10:59:36.664  UTF8
< 2022-02-14 10:59:36.664  AUTH TLS;TLS-C;SSL;TLS-P;
< 2022-02-14 10:59:36.664  PBSZ
< 2022-02-14 10:59:36.664  PROT C;P;
< 2022-02-14 10:59:36.664  CCC
< 2022-02-14 10:59:36.664  HOST
< 2022-02-14 10:59:36.664  SIZE
< 2022-02-14 10:59:36.664  MDTM
< 2022-02-14 10:59:36.664  REST STREAM
< 2022-02-14 10:59:36.664 211 END
> 2022-02-14 10:59:36.664 OPTS UTF8 ON
< 2022-02-14 10:59:36.664 200 OPTS UTF8 command successful - UTF8 encoding now ON.
> 2022-02-14 10:59:36.664 PBSZ 0
< 2022-02-14 10:59:36.664 200 PBSZ command successful.
> 2022-02-14 10:59:36.664 PROT P
< 2022-02-14 10:59:36.664 200 PROT command successful.
< 2022-02-14 10:59:36.664 Script: Connected
. 2022-02-14 10:59:36.664 Connected
. 2022-02-14 10:59:36.664 --------------------------------------------------------------------------
. 2022-02-14 10:59:36.664 Using FTP protocol.
. 2022-02-14 10:59:36.664 Doing startup conversation with host.
< 2022-02-14 10:59:36.664 Script: Starting the session...
> 2022-02-14 10:59:36.664 PWD
< 2022-02-14 10:59:36.664 257 "/" is current directory.
. 2022-02-14 10:59:36.664 Getting current directory name.
. 2022-02-14 10:59:36.664 Startup conversation with host finished.
< 2022-02-14 10:59:36.664 Script: Session started.
< 2022-02-14 10:59:36.664 Script: Active session: [1] LogonId@xx.xxx.xxx.x
> 2022-02-14 10:59:36.664 Script: cd /IntelliUpdate
. 2022-02-14 10:59:36.664 Changing directory to "/IntelliUpdate".
> 2022-02-14 10:59:36.664 CWD /IntelliUpdate
< 2022-02-14 10:59:36.664 250 CWD command successful.
. 2022-02-14 10:59:36.664 Getting current directory name.
> 2022-02-14 10:59:36.664 PWD
< 2022-02-14 10:59:36.664 257 "/IntelliUpdate" is current directory.
< 2022-02-14 10:59:36.664 Script: /IntelliUpdate
> 2022-02-14 10:59:36.664 Script: lcd D:\Transfer\IntelliUpdate
< 2022-02-14 10:59:36.664 Script: D:\Transfer\IntelliUpdate
> 2022-02-14 10:59:36.664 Script: Get *.* d:\transfer\IntelliUpdate\
. 2022-02-14 10:59:36.664 Retrieving directory listing...
> 2022-02-14 10:59:36.664 TYPE A
< 2022-02-14 10:59:36.664 200 Type set to A.
> 2022-02-14 10:59:36.664 PASV
< 2022-02-14 10:59:36.664 227 Entering Passive Mode (xx,xxx,xxx,x,197,253).
> 2022-02-14 10:59:36.664 LIST -a
. 2022-02-14 10:59:36.664 Connecting to xx.xxx.xxx.x:50685 ...
< 2022-02-14 10:59:36.664 150 Opening ASCII mode data connection.
. 2022-02-14 10:59:36.664 Session ID reused
. 2022-02-14 10:59:36.664 Using TLSv1, cipher SSLv3: AES128-SHA, 2048 bit RSA, AES128-SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(128)  Mac=SHA1
. 2022-02-14 10:59:36.664 TLS connection established
. 2022-02-14 10:59:36.664 <Empty directory listing>
< 2022-02-14 10:59:36.664 226 Transfer complete.
. 2022-02-14 10:59:36.664 Directory listing successful
. 2022-02-14 10:59:36.664 Detecting timezone difference...
. 2022-02-14 10:59:36.664 Found no file to use for detecting timezone difference
. 2022-02-14 10:59:36.664 LIST with -a switch returned empty directory listing, will try pure LIST
. 2022-02-14 10:59:36.664 Retrieving directory listing...
> 2022-02-14 10:59:36.664 TYPE A
< 2022-02-14 10:59:36.664 200 Type set to A.
> 2022-02-14 10:59:36.664 PASV
< 2022-02-14 10:59:36.679 227 Entering Passive Mode (xx,xxx,xxx,x,197,251).
> 2022-02-14 10:59:36.679 LIST
. 2022-02-14 10:59:36.679 Connecting to xx.xxx.xxx.x:50683 ...
< 2022-02-14 10:59:36.679 150 Opening ASCII mode data connection.
. 2022-02-14 10:59:36.679 Session ID reused
. 2022-02-14 10:59:36.679 Using TLSv1, cipher SSLv3: AES128-SHA, 2048 bit RSA, AES128-SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(128)  Mac=SHA1
. 2022-02-14 10:59:36.679 TLS connection established
. 2022-02-14 10:59:36.679 <Empty directory listing>
< 2022-02-14 10:59:36.679 226 Transfer complete.
. 2022-02-14 10:59:36.679 Directory listing successful
. 2022-02-14 10:59:36.679 Detecting timezone difference...
. 2022-02-14 10:59:36.679 Found no file to use for detecting timezone difference
. 2022-02-14 10:59:36.679 ..;D;0;1899-12-30T00:00:00.000Z;0;"" [0];"" [0];---------;0
< 2022-02-14 10:59:36.679 Script: No file matching '*.*' found.
. 2022-02-14 10:59:36.679 Copying 0 files/directories to local directory "d:\transfer\IntelliUpdate\" - total size: 0
. 2022-02-14 10:59:36.679   PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: No; Mask: 
. 2022-02-14 10:59:36.679   TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; EncryptNewFiles: Yes; ExcludeHiddenFiles: No; ExcludeEmptyDirectories: No; InclM: ; ResumeL: 0
. 2022-02-14 10:59:36.679   AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2022-02-14 10:59:36.679 Copying finished: Transferred: 0, Elapsed: 0:00:00, CPS: 0/s
> 2022-02-14 10:59:36.679 Script: exit
. 2022-02-14 10:59:36.679 Script: Exit code: 0
. 2022-02-14 10:59:36.679 Disconnected from server

Reply with quote

Tink
Guest

So just to clarify, the existing WinSCP V5.1 script contained % and $ in the password but when I upgraded to V5.19 the scripts failed.
After testing and amending the password to reflect %3B and %24 for those characters and running script with WinSCP V5.19 it all works.

Reply with quote

martin◆
Site Admin
martin avatar

Sorry, but the log you have posted does not "clearly show the issue with passwords". Can you post a log with your original script that failed (with /loglevel=*)?

Reply with quote

Advertisement

Tink
Guest

Failing V5.19 script logfile:
Note the truncation of the password after the 2nd character. 
. 2022-02-22 11:03:16.214 --------------------------------------------------------------------------
. 2022-02-22 11:03:16.214 WinSCP Version 5.19.5 (Build 11933 2021-11-25) (OS 6.1.7601 Service Pack 1 - Windows Server 2008 R2 Standard)
. 2022-02-22 11:03:16.214 Configuration: nul
. 2022-02-22 11:03:16.214 Log level: Normal, Logging passwords
. 2022-02-22 11:03:16.215 Local account: DOMAIN\logonid
. 2022-02-22 11:03:16.215 Working directory: D:\Buildsoftware\WinSCPPortable V5.19\App\winscp
. 2022-02-22 11:03:16.215 Process ID: 5268
. 2022-02-22 11:03:16.218 Ancestor processes: ...
. 2022-02-22 11:03:16.218 Command-line: "D:\Buildsoftware\WinSCPPortable V5.19\App\winscp\WinSCP.exe" /loglevel=* /ini=nul /script=MGtest.txt /log=MGtestlogs.txt
. 2022-02-22 11:03:16.218 Time zone: Current: GMT+0, Standard: GMT+0 (GMT Standard Time), DST: GMT+1 (GMT Daylight Time), DST Start: 27/03/2022, DST End: 30/10/2022
. 2022-02-22 11:03:16.218 Login time: 22 February 2022 11:03:16
. 2022-02-22 11:03:16.218 --------------------------------------------------------------------------
. 2022-02-22 11:03:16.218 Script: Retrospectively logging previous script records:
> 2022-02-22 11:03:16.218 Script: option batch continue
< 2022-02-22 11:03:16.218 Script: batch           continue  
> 2022-02-22 11:03:16.218 Script: option confirm off
< 2022-02-22 11:03:16.218 Script: confirm         off       
> 2022-02-22 11:03:16.218 Script: option transfer binary
< 2022-02-22 11:03:16.218 Script: transfer        binary    
> 2022-02-22 11:03:16.218 Script: open ftp://logonid:VJ;P$tXpN6SMZiEsa$ydquMbX@xxx.xxx.xxx.xxx:2121/ -explicitSSL -hostkey="07:d5:53:92:8f:78:b1:96:d9:9d:f9:b3:e4:55:2b:17:dc:c9:fe:44"
. 2022-02-22 11:03:16.218 --------------------------------------------------------------------------
. 2022-02-22 11:03:16.218 Session name: logonid@xxx.xxx.xxx.xxx (Ad-Hoc site)
. 2022-02-22 11:03:16.218 Host name: xxx.xxx.xxx.xxx (Port: 2121)
. 2022-02-22 11:03:16.219 User name: logonid (Password: VJ, Key file: No, Passphrase: No)
. 2022-02-22 11:03:16.219 Transfer Protocol: FTP
. 2022-02-22 11:03:16.219 Ping type: Dummy, Ping interval: 30 sec; Timeout: 15 sec
. 2022-02-22 11:03:16.219 Disable Nagle: No
. 2022-02-22 11:03:16.219 Proxy: None
. 2022-02-22 11:03:16.219 Send buffer: 262144
. 2022-02-22 11:03:16.219 UTF: Auto
. 2022-02-22 11:03:16.219 FTPS: Explicit SSL/TLS [Client certificate: No]
. 2022-02-22 11:03:16.219 FTP: Passive: Yes [Force IP: Auto]; MLSD: Auto [List all: Auto]; HOST: Auto
. 2022-02-22 11:03:16.219 Session reuse: Yes
. 2022-02-22 11:03:16.219 TLS/SSL versions: TLSv1.0-TLSv1.3
. 2022-02-22 11:03:16.219 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2022-02-22 11:03:16.219 Cache directory changes: Yes, Permanent: Yes
. 2022-02-22 11:03:16.219 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2022-02-22 11:03:16.219 Timezone offset: 0h 0m
. 2022-02-22 11:03:16.219 --------------------------------------------------------------------------
< 2022-02-22 11:03:16.232 Script: Connecting to xxx.xxx.xxx.xxx:2121 ...
. 2022-02-22 11:03:16.232 Connecting to xxx.xxx.xxx.xxx:2121 ...
. 2022-02-22 11:03:16.239 Connected with xxx.xxx.xxx.xxx:2121, negotiating TLS connection...
< 2022-02-22 11:03:16.240 220 Microsoft FTP Service
> 2022-02-22 11:03:16.240 AUTH SSL
< 2022-02-22 11:03:16.240 234 AUTH command ok. Expecting TLS Negotiation.
. 2022-02-22 11:03:16.650 Verifying certificate for "XXXX" with fingerprint 94:de:6b:5c:30:8b:83:4f:ca:2b:33:18:9c:75:3e:41:87:87:c4:11:9a:82:b4:15:62:85:59:26:c0:76:6f:37 and 20 failures
. 2022-02-22 11:03:16.650 Certificate for "XXXX" matches configured fingerprint
. 2022-02-22 11:03:16.650 Using TLSv1, cipher SSLv3: AES128-SHA, 2048 bit RSA, AES128-SHA              SSLv3 Kx=RSA      Au=RSA  Enc=AES(128)  Mac=SHA1
< 2022-02-22 11:03:16.650 Script: TLS connection established. Waiting for welcome message...
. 2022-02-22 11:03:16.650 TLS connection established. Waiting for welcome message...
> 2022-02-22 11:03:16.650 USER logonid
< 2022-02-22 11:03:16.650 331 Password required for logonid.
> 2022-02-22 11:03:16.650 PASS VJ
< 2022-02-22 11:03:17.679 530 User cannot log in.
. 2022-02-22 11:03:17.679 Connection failed.
< 2022-02-22 11:03:17.679 Script: Access denied.
. 2022-02-22 11:03:17.679 Password prompt (last login attempt failed)
< 2022-02-22 11:03:17.679 Script: Authentication failed.

Reply with quote

Advertisement

You can post new topics in this forum

Documentation

Support

Associations

Follow Us