Upgrade to 15.9.1 has broken Task Scheduler :: Support Forum

ellie.coder
Joined:: 2021-07-07
Posts:: 2
Location:: Australia

Upgrade to 15.9.1 has broken Task Scheduler

2021-07-07 05:51

Since upgrading to 15.9.1 I am no longer able to run WinSCP via Task Scheduler. Is there anything in the upgrade that might be affecting this? I am running WinSCP on Windows Server 2012 R2. The problem occurred immediately after upgrading to version 15.9.1. I'm unsure what version I was on before but I think it was 15.9. WinSCP works when running a script via a batch file but does not work when running WinSCP via Task Scheduler. The log file records the following lines before the task hangs:

. 2021-07-07 10:56:49.956 --------------------------------------------------------------------------
. 2021-07-07 10:56:49.956 WinSCP Version 5.19.1 (Build 11552) (OS 6.3.9600 - Windows Server 2012 R2 Datacenter)
. 2021-07-07 10:56:49.956 Configuration: HKCU\Software\Martin Prikryl\WinSCP 2\
. 2021-07-07 10:56:49.956 Log level: Reduced, Rotating after: 10M
. 2021-07-07 10:56:49.956 Local account: ********
. 2021-07-07 10:56:49.956 Working directory: C:\Windows\system32
. 2021-07-07 10:56:49.956 Process ID: 8828

The next lines in the log file would normally be as per below. These are the commands as per the scheduled task.

. 2021-07-06 00:30:00.839 Parent process: 
. 2021-07-06 00:30:00.842 Command-line: "C:\Program Files (x86)\WinSCP\WinSCP.exe" /log=C:\********.log /loglevel=-1 /logsize=10M /script=C:\********.txt

I am currently uninstalling version 15.9.1 and reinstalling version 15.9 to hopefully resolve the issue but will need to be able to upgrade at some point.

Reply with quote

jcroussel
Joined:: 2021-07-07
Posts:: 2

same problem

2021-07-07 18:58

Hello,
I have the same problem with the same version.
For my part, it does not happen all the time but when it happens (see block at 10:15), the windows process is blocked
Thanks for answer

--------------------------------------------------------------------------
. 2021-07-07 10:11:51.765 WinSCP Version 5.19.1 (Build 11552) (OS 6.1.7601 Service Pack 1 - Windows Embedded Standard)
. 2021-07-07 10:11:51.765 Configuration: nul
. 2021-07-07 10:11:51.765 Log level: Normal, Rotating after: 5M, Keeping at most 20 logs
. 2021-07-07 10:11:51.765 Local account: M297C1\CAISSE
. 2021-07-07 10:11:51.765 Working directory: C:\
. 2021-07-07 10:11:51.765 Process ID: 3676
. 2021-07-07 10:11:51.780 Ancestor processes: WinSCP, cmd, BDDCom
. 2021-07-07 10:11:51.796 Command-line: "C:\Winstore\WinSCP\WinSCP.exe" /console=5.19.1 /consoleinstance=_5524_437 "/script=C:\Winstore\WinSCP\RecupTRF.txt" "/ini=nul" "/log=C:\Partage\log\winSCP.log" "/loglevel=0" "/logsize=20*5M" 
. 2021-07-07 10:11:51.796 Time zone: Current: GMT+2, Standard: GMT+1 (Romance Standard Time), DST: GMT+2 (Romance Daylight Time), DST Start: 28/03/2021, DST End: 31/10/2021
. 2021-07-07 10:11:51.796 Login time: mercredi 7 juillet 2021 10:11:51
. 2021-07-07 10:11:51.796 --------------------------------------------------------------------------
. 2021-07-07 10:11:51.796 Script: Retrospectively logging previous script records:
> 2021-07-07 10:11:51.796 Script: option batch abort
< 2021-07-07 10:11:51.796 Script: batch           abort     
> 2021-07-07 10:11:51.796 Script: option confirm on
< 2021-07-07 10:11:51.796 Script: confirm         on        
> 2021-07-07 10:11:51.796 Script: open sftp://tAoCa1sseWsT_UR:***@srvlurfiler.tao.local -hostkey="ssh-ed25519 255 6VOXE3JDN8nZ+1IU8j9Qj7nzOlnrMGWan/BZDgo7g2c="
. 2021-07-07 10:11:51.796 --------------------------------------------------------------------------
. 2021-07-07 10:11:51.796 Session name: tAoCa1sseWsT_UR@srvlurfiler.tao.local (Ad-Hoc site)
. 2021-07-07 10:11:51.796 Host name: srvlurfiler.tao.local (Port: 22)
. 2021-07-07 10:11:51.796 User name: tAoCa1sseWsT_UR (Password: Yes, Key file: No, Passphrase: No)
. 2021-07-07 10:11:51.796 Tunnel: No
. 2021-07-07 10:11:51.796 Transfer Protocol: SFTP
. 2021-07-07 10:11:51.796 Ping type: Off, Ping interval: 30 sec; Timeout: 15 sec
. 2021-07-07 10:11:51.796 Disable Nagle: No
. 2021-07-07 10:11:51.796 Proxy: None
. 2021-07-07 10:11:51.796 Send buffer: 262144
. 2021-07-07 10:11:51.796 SSH protocol version: 2; Compression: No
. 2021-07-07 10:11:51.796 Bypass authentication: No
. 2021-07-07 10:11:51.796 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: Yes
. 2021-07-07 10:11:51.796 GSSAPI: KEX: No; Forwarding: No; Libs: gssapi32,sspi,custom; Custom: 
. 2021-07-07 10:11:51.796 Ciphers: aes,chacha20,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2021-07-07 10:11:51.796 KEX: ecdh,dh-gex-sha1,dh-group14-sha1,rsa,WARN,dh-group1-sha1
. 2021-07-07 10:11:51.796 SSH Bugs: Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto
. 2021-07-07 10:11:51.796 Simple channel: Yes
. 2021-07-07 10:11:51.796 Return code variable: Autodetect; Lookup user groups: Auto
. 2021-07-07 10:11:51.796 Shell: default
. 2021-07-07 10:11:51.796 EOL: LF, UTF: Auto
. 2021-07-07 10:11:51.796 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes; Follow directory symlinks: No
. 2021-07-07 10:11:51.796 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No; Exit code 1 is error: No
. 2021-07-07 10:11:51.796 SFTP Bugs: Auto,Auto
. 2021-07-07 10:11:51.796 SFTP Server: default
. 2021-07-07 10:11:51.796 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2021-07-07 10:11:51.796 Cache directory changes: Yes, Permanent: Yes
. 2021-07-07 10:11:51.796 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2021-07-07 10:11:51.796 DST mode: Unix
. 2021-07-07 10:11:51.796 --------------------------------------------------------------------------
< 2021-07-07 10:11:51.796 Script: Searching for host...
. 2021-07-07 10:11:51.796 Looking up host "srvlurfiler.tao.local" for SSH connection
. 2021-07-07 10:11:51.811 Connecting to 10.50.50.95 port 22
< 2021-07-07 10:11:51.843 Script: Connecting to host...
. 2021-07-07 10:11:51.843 We claim version: SSH-2.0-WinSCP_release_5.19.1
. 2021-07-07 10:11:51.936 Remote version: SSH-2.0-OpenSSH_7.4
. 2021-07-07 10:11:51.936 Using SSH protocol version 2
. 2021-07-07 10:11:51.936 Have a known host key of type ssh-ed25519
. 2021-07-07 10:11:52.014 Doing ECDH key exchange with curve Curve25519 and hash SHA-256
. 2021-07-07 10:11:52.326 Server also has ecdsa-sha2-nistp256/ssh-rsa host keys, but we don't know any of them
. 2021-07-07 10:11:52.326 Host key fingerprint is:
. 2021-07-07 10:11:52.326 ssh-ed25519 255 6e:63:c3:8e:12:44:0c:a4:0b:85:48:d6:0b:5c:62:12 6VOXE3JDN8nZ+1IU8j9Qj7nzOlnrMGWan/BZDgo7g2c=
< 2021-07-07 10:11:52.326 Script: Authenticating...
. 2021-07-07 10:11:52.326 Host key matches configured key fingerprint
. 2021-07-07 10:11:52.326 Initialised AES-256 SDCTR (unaccelerated) [aes256-ctr] outbound encryption
. 2021-07-07 10:11:52.326 Initialised HMAC-SHA-256 outbound MAC algorithm
. 2021-07-07 10:11:52.326 Initialised AES-256 SDCTR (unaccelerated) [aes256-ctr] inbound encryption
. 2021-07-07 10:11:52.326 Initialised HMAC-SHA-256 inbound MAC algorithm
! 2021-07-07 10:11:52.373 Using username "tAoCa1sseWsT_UR".
< 2021-07-07 10:11:52.373 Script: Using username "tAoCa1sseWsT_UR".
. 2021-07-07 10:11:52.404 Server offered these authentication methods: publickey,gssapi-keyex,gssapi-with-mic,password
. 2021-07-07 10:11:52.404 Using SSPI from SECUR32.DLL
. 2021-07-07 10:11:52.404 Trying gssapi-with-mic...
. 2021-07-07 10:11:52.404 Attempting GSSAPI authentication
. 2021-07-07 10:11:52.435 GSSAPI authentication request refused
. 2021-07-07 10:11:52.435 Server offered these authentication methods: publickey,gssapi-keyex,gssapi-with-mic,password
. 2021-07-07 10:11:52.435 Prompt (password, "SSH password", <no instructions>, "&Password: ")
. 2021-07-07 10:11:52.435 Using stored password.
< 2021-07-07 10:11:52.451 Script: Authenticating with pre-entered password.
. 2021-07-07 10:11:52.451 Sent password
. 2021-07-07 10:11:52.513 Access granted
. 2021-07-07 10:11:52.513 Opening main session channel
. 2021-07-07 10:11:52.794 Opened main channel
. 2021-07-07 10:11:52.841 Started a shell/command
< 2021-07-07 10:11:52.841 Script: Authenticated.
. 2021-07-07 10:11:52.841 --------------------------------------------------------------------------
. 2021-07-07 10:11:52.841 Using SFTP protocol.
. 2021-07-07 10:11:52.841 Doing startup conversation with host.
< 2021-07-07 10:11:52.841 Script: Starting the session...
> 2021-07-07 10:11:52.841 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2021-07-07 10:11:52.872 Type: SSH_FXP_VERSION, Size: 150, Number: -1
. 2021-07-07 10:11:52.872 SFTP version 3 negotiated.
. 2021-07-07 10:11:52.872 Unknown server extension posix-rename@openssh.com="1"
. 2021-07-07 10:11:52.872 Supports statvfs@openssh.com extension version "2"
. 2021-07-07 10:11:52.872 Unknown server extension fstatvfs@openssh.com="2"
. 2021-07-07 10:11:52.872 Supports hardlink@openssh.com extension version "1"
. 2021-07-07 10:11:52.872 Unknown server extension fsync@openssh.com="1"
. 2021-07-07 10:11:52.872 We believe the server has signed timestamps bug
. 2021-07-07 10:11:52.872 We will use UTF-8 strings until server sends an invalid UTF-8 string as with SFTP version 3 and older UTF-8 strings are not mandatory
. 2021-07-07 10:11:52.872 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes
. 2021-07-07 10:11:52.872 Getting current directory name.
. 2021-07-07 10:11:52.872 Getting real path for '.'
> 2021-07-07 10:11:52.872 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2021-07-07 10:11:52.903 Type: SSH_FXP_NAME, Size: 81, Number: 16
. 2021-07-07 10:11:52.903 Real path is '/app/UnitedRetail/InterfaceWST'
. 2021-07-07 10:11:52.903 Startup conversation with host finished.
< 2021-07-07 10:11:52.903 Script: Session started.
< 2021-07-07 10:11:52.903 Script: Active session: [1] tAoCa1sseWsT_UR@srvlurfiler.tao.local
> 2021-07-07 10:11:52.903 Script: Get -delete -preservetime -resumesupport=on outgoing/transtcj.297 C:\Winstore\Arrivee\Transfer.txt
. 2021-07-07 10:11:52.903 Listing file "outgoing/transtcj.297".
> 2021-07-07 10:11:52.903 Type: SSH_FXP_LSTAT, Size: 61, Number: 263
< 2021-07-07 10:11:52.950 Type: SSH_FXP_STATUS, Size: 29, Number: 263
< 2021-07-07 10:11:52.950 Status code: 2, Message: 263, Server: No such file, Language:  
< 2021-07-07 10:11:52.950 Script: Can't get attributes of file 'outgoing/transtcj.297'.
< 2021-07-07 10:11:52.950 No such file or directory.
< 2021-07-07 10:11:52.950 Error code: 2
< 2021-07-07 10:11:52.950 Error message from server: No such file
. 2021-07-07 10:11:52.950 Script: Failed
. 2021-07-07 10:11:52.950 Script: Exit code: 1
. 2021-07-07 10:11:52.950 Closing connection.
. 2021-07-07 10:11:52.950 Sending special code: 1
. 2021-07-07 10:11:52.981 Session sent command exit status 0
. 2021-07-07 10:11:52.981 Main session channel closed
. 2021-07-07 10:11:52.981 All channels closed
. 2021-07-07 10:15:55.485 --------------------------------------------------------------------------
. 2021-07-07 10:15:55.485 WinSCP Version 5.19.1 (Build 11552) (OS 6.1.7601 Service Pack 1 - Windows Embedded Standard)
. 2021-07-07 10:15:55.485 Configuration: nul
. 2021-07-07 10:15:55.485 Log level: Normal, Rotating after: 5M, Keeping at most 20 logs
. 2021-07-07 10:15:55.485 Local account: M297C1\CAISSE
. 2021-07-07 10:15:55.485 Working directory: C:\
. 2021-07-07 10:15:55.485 Process ID: 1224
. 2021-07-07 11:02:12.344 --------------------------------------------------------------------------
. 2021-07-07 11:02:12.344 WinSCP Version 5.19.1 (Build 11552) (OS 6.1.7601 Service Pack 1 - Windows Embedded Standard)
. 2021-07-07 11:02:12.344 Configuration: nul
. 2021-07-07 11:02:12.344 Log level: Normal, Rotating after: 5M, Keeping at most 20 logs
. 2021-07-07 11:02:12.344 Local account: M297C1\CAISSE
. 2021-07-07 11:02:12.344 Working directory: C:\
. 2021-07-07 11:02:12.344 Process ID: 5196
. 2021-07-07 11:15:42.570 --------------------------------------------------------------------------

Reply with quote

ellie.coder

Reverting to version 15.9 has fixed the issue

2021-07-07 23:54

I have uninstalled version 15.9.1 and reinstalled version 15.9. The issue is fixed for now. Obviously I will have to upgrade at some point. Will keep an eye on this post to see if anyone else has the same issue or a solution is suggested.

Reply with quote

piercedj
Joined:: 2019-11-11
Posts:: 5
Location:: Lake Villa, IL

Same Issue Here - Reverted Back to 5.18.6

2021-07-08 16:42

Running BAT file via Task Manager on 5.19.1 gets this:

. 2021-06-30 13:31:43.917 --------------------------------------------------------------------------
. 2021-06-30 13:31:43.917 WinSCP Version 5.19.1 (Build 11552) (OS 10.0.14393 - Windows Server 2016 Standard)
. 2021-06-30 13:31:43.917 Configuration: nul
. 2021-06-30 13:31:43.917 Log level: Normal
. 2021-06-30 13:31:43.917 Local account: NCH\svc_nchops
. 2021-06-30 13:31:43.917 Working directory: C:\SYS\BIN
. 2021-06-30 13:31:43.917 Process ID: 5200
. 2021-06-30 14:42:10.232 --------------------------------------------------------------------------
. 2021-06-30 14:42:10.232 WinSCP Version 5.19.1 (Build 11552) (OS 10.0.14393 - Windows Server 2016 Standard)
. 2021-06-30 14:42:10.248 Configuration: nul
. 2021-06-30 14:42:10.248 Log level: Normal
. 2021-06-30 14:42:10.248 Local account: NCH\svc_nchops
. 2021-06-30 14:42:10.248 Working directory: C:\SYS\BIN
. 2021-06-30 14:42:10.248 Process ID: 1732

Reply with quote