Script works when run manually but fails when scheduled :: Support Forum

jmangan Guest

Script works when run manually but fails when scheduled

2021-09-17 10:24

I'm running WinSCP 5.19.2 (Build 11614) on Windows Server 2012R2.

I've written a PowerShell script to run on a schedule, check for the presence of some '.csv' files and transfer them, over SFTP, to another server.
There's a minor issue which I don't think is related to my main problem (but I'll mention it for completeness) when I connect through the WinSCP GUI.
Initially the connection pauses saying the 'Host is not communicating for more that 15 secs'. I tried disabling 'Optimize connection buffer size' as suggested but it made no difference. After around 30 seconds the connection is made successfully so I'm not overly concerned about this. I tried attaching screenshots but '.rtf' files are not accepted.

If I run the command:

C:\"Program Files (x86)"\WinSCP\WinSCP.exe /ini=nul /nointeractiveinput /log=E:\AdurDocuments\"Adur Homes Services"\"Regular Reports from Orchard"\"MATS Imports"\TransferScript\WinSCPLog.txt /script=E:\AdurDocuments\"Adur Homes Services"\"Regular Reports from Orchard"\"MATS Imports"\TransferScript\OrchardWinSCP.txt

in the Powershell ISE as the account that I'm using for the Scheduled Task then the transfer works. I've attached the WinSCP script file and the log output.

If I run the script from the Task Scheduler using the same account then the transfer fails saying there are no files and I've attached the log for this as well.

What am I missing, please?

OrchardWinSCP.txt (439 Bytes)

Description: This is the script file I'm using for WinSCP. I tried using the 'put' with the full filepath and then used 'lcd' to simplify the 'put' but I get the same results either way.

Run Script.txt (10.32 KB)

Description: When run as a script using the required account no *.csv files are seen.

Run manually.txt (20.04 KB)

Description: Run manually as the required account. Transfer works

Reply with quote

jmangan
Joined:: 2021-09-17
Posts:: 5
Location:: West Sussex, UK

Solved!

2021-09-17 15:16

I got another call about a connection problem with the same server. From that it looked like the long connection time was an issue. Looking around I found a couple of suggestions for modifying the SSH configuration on the server. That fixed my new problem and it looks like it fixed this one as well.

I didn't see this in the log output but I'm going to go back and see if I managed to miss it.

Thanks.

Reply with quote

jmangan

NOT solved

2021-09-18 11:09

Sorry, it's failed again and I just can't see why.
Any suggestions gratefully received.

Reply with quote

jmangan
Joined:: 2021-09-17
Posts:: 5
Location:: West Sussex, UK

It's something to do with the way the script reads paths.

2021-09-20 11:53

So far as I can see there is something odd with the way the script is dealing with the path to the files.

In the WinSCP script I have tried:

lcd E:\AdurDocuments\"Adur Homes Services"\"Regular Reports from Orchard"\"MATS imports"
put *.csv /SFTP_Dir/orchard/

I've tried with and without a trailing \. I've tried with the double quotes (as shown) and with a single quote before the E: and after the imports.

AND

put E:\AdurDocuments\"Adur Homes Services"\"Regular Reports from Orchard"\"MATS imports"\*.csv

Same again, I've tried with double-quotes, as shown and all-encompassing single quotes.

None of these throw an error message but they don't seem to be opening the correct directory and so it can't see the target files.

Any suggestions, please?

Reply with quote

martin◆ Site Admin
Joined:: 2002-12-10
Posts:: 41,454
Location:: Prague, Czechia

Re: Script works when run manually but fails when scheduled

2021-09-20

From the logs, it does not look like you have used the same account. The "manually" log shows johnawadmin account, while "script" log shows ss account.
This looks like a variation of
https://winscp.net/eng/docs/faq_scheduler
Except that in you case the E: seems to be mapped in both cases, but either to a different network drive, or the accounts have different permissions.

Reply with quote

jmangan
Joined:: 2021-09-17
Posts:: 5
Location:: West Sussex, UK

Script works when run manually but fails when scheduled

2021-09-20 14:04

Thank you! The E: drive is local to the computer but you made me look at the account I was running the scheduled task as again.

Since I posted this I had been trying various things to try to identify the issue and I had been running everything, I thought, with the correct account. But I must have missed a couple and confused myself about it working.

It looks like the account I was using to run the script didn't have the 'Logon as a batch job' permission (I also must have missed the warning that would have popped up when I first set it up). I've now created a new local account, made sure it can 'Logon as batch job' and given it permissions to the files and folders it needs access to.

But nothing seems to have changed:

. 2021-09-20 14:01:25.907 --------------------------------------------------------------------------
. 2021-09-20 14:01:25.907 WinSCP Version 5.19.2 (Build 11614) (OS 6.3.9600 - Windows Server 2012 R2 Standard)
. 2021-09-20 14:01:25.907 Configuration: nul
. 2021-09-20 14:01:25.907 Log level: Normal
. 2021-09-20 14:01:25.907 Local account: ADURDOCS\OrchMATS
. 2021-09-20 14:01:25.907 Working directory: C:\Users\OrchMATS\Documents
. 2021-09-20 14:01:25.907 Process ID: 3928
. 2021-09-20 14:01:25.907 Ancestor processes: ...
. 2021-09-20 14:01:25.907 Command-line: "C:\Program Files (x86)\WinSCP\WinSCP.exe"  /ini=nul /nointeractiveinput "/log=E:\AdurDocuments\Adur Homes Services\Regular Reports from Orchard\MATS Imports\TransferScript\WinSCPLog.txt" "/script=E:\AdurDocuments\Adur Homes Services\Regular Reports from Orchard\MATS Imports\TransferScript\OrchardWinSCP.txt"
. 2021-09-20 14:01:25.907 Time zone: Current: GMT+1, Standard: GMT+0 (GMT Standard Time), DST: GMT+1 (GMT Daylight Time), DST Start: 28/03/2021, DST End: 31/10/2021
. 2021-09-20 14:01:25.907 Login time: 20 September 2021 14:01:25
. 2021-09-20 14:01:25.907 --------------------------------------------------------------------------
. 2021-09-20 14:01:25.907 Script: Retrospectively logging previous script records:
> 2021-09-20 14:01:25.907 Script: open sftp://orchard:***@awFTP.awdmz.local/
. 2021-09-20 14:01:25.907 --------------------------------------------------------------------------
. 2021-09-20 14:01:25.907 Session name: orchard@awFTP.awdmz.local (Ad-Hoc site)
. 2021-09-20 14:01:25.907 Host name: awFTP.awdmz.local (Port: 22)
. 2021-09-20 14:01:25.907 User name: orchard (Password: Yes, Key file: No, Passphrase: No)
. 2021-09-20 14:01:25.907 Tunnel: No
. 2021-09-20 14:01:25.907 Transfer Protocol: SFTP
. 2021-09-20 14:01:25.907 Ping type: Off, Ping interval: 30 sec; Timeout: 15 sec
. 2021-09-20 14:01:25.907 Disable Nagle: No
. 2021-09-20 14:01:25.907 Proxy: None
. 2021-09-20 14:01:25.907 Send buffer: 262144
. 2021-09-20 14:01:25.907 SSH protocol version: 2; Compression: No
. 2021-09-20 14:01:25.907 Bypass authentication: No
. 2021-09-20 14:01:25.907 Try agent: Yes; Agent forwarding: No; TIS/CryptoCard: No; KI: Yes; GSSAPI: Yes
. 2021-09-20 14:01:25.907 GSSAPI: KEX: No; Forwarding: No; Libs: gssapi32,sspi,custom; Custom: 
. 2021-09-20 14:01:25.907 Ciphers: aes,chacha20,blowfish,3des,WARN,arcfour,des; Ssh2DES: No
. 2021-09-20 14:01:25.907 KEX: ecdh,dh-gex-sha1,dh-group14-sha1,rsa,WARN,dh-group1-sha1
. 2021-09-20 14:01:25.907 SSH Bugs: Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto,Auto
. 2021-09-20 14:01:25.907 Simple channel: Yes
. 2021-09-20 14:01:25.907 Return code variable: Autodetect; Lookup user groups: Auto
. 2021-09-20 14:01:25.907 Shell: default
. 2021-09-20 14:01:25.907 EOL: LF, UTF: Auto
. 2021-09-20 14:01:25.907 Clear aliases: Yes, Unset nat.vars: Yes, Resolve symlinks: Yes; Follow directory symlinks: No
. 2021-09-20 14:01:25.907 LS: ls -la, Ign LS warn: Yes, Scp1 Comp: No; Exit code 1 is error: No
. 2021-09-20 14:01:25.907 SFTP Bugs: Auto,Auto
. 2021-09-20 14:01:25.907 SFTP Server: default
. 2021-09-20 14:01:25.907 Local directory: default, Remote directory: home, Update: Yes, Cache: Yes
. 2021-09-20 14:01:25.907 Cache directory changes: Yes, Permanent: Yes
. 2021-09-20 14:01:25.907 Recycle bin: Delete to: No, Overwritten to: No, Bin path: 
. 2021-09-20 14:01:25.907 DST mode: Unix
. 2021-09-20 14:01:25.907 --------------------------------------------------------------------------
< 2021-09-20 14:01:25.907 Script: Searching for host...
. 2021-09-20 14:01:25.907 Looking up host "awFTP.awdmz.local" for SSH connection
. 2021-09-20 14:01:25.923 Connecting to 10.2.0.170 port 22
< 2021-09-20 14:01:25.923 Script: Connecting to host...
. 2021-09-20 14:01:25.923 We claim version: SSH-2.0-WinSCP_release_5.19.2
. 2021-09-20 14:01:25.954 Remote version: SSH-2.0-OpenSSH_7.4
. 2021-09-20 14:01:25.954 Using SSH protocol version 2
. 2021-09-20 14:01:25.970 Have a known host key of type ssh-ed25519
. 2021-09-20 14:01:25.970 Doing ECDH key exchange with curve Curve25519 and hash SHA-256
. 2021-09-20 14:01:26.126 Server also has ecdsa-sha2-nistp256/ssh-rsa host keys, but we don't know any of them
. 2021-09-20 14:01:26.126 Host key fingerprint is:
. 2021-09-20 14:01:26.126 ssh-ed25519 255 87:00:de:47:a2:52:69:89:69:13:5c:f9:d3:ca:0e:dc WxInjxkxYdjiT4dLe/X+X4GwUyKVZjjGkMGJWFLE/es=
< 2021-09-20 14:01:26.126 Script: Authenticating...
. 2021-09-20 14:01:26.126 Host key matches configured key fingerprint
. 2021-09-20 14:01:26.126 Initialised AES-256 SDCTR (unaccelerated) [aes256-ctr] outbound encryption
. 2021-09-20 14:01:26.126 Initialised HMAC-SHA-256 outbound MAC algorithm
. 2021-09-20 14:01:26.126 Initialised AES-256 SDCTR (unaccelerated) [aes256-ctr] inbound encryption
. 2021-09-20 14:01:26.126 Initialised HMAC-SHA-256 inbound MAC algorithm
! 2021-09-20 14:01:26.126 Using username "orchard".
< 2021-09-20 14:01:26.126 Script: Using username "orchard".
. 2021-09-20 14:01:26.126 Server offered these authentication methods: publickey,password
. 2021-09-20 14:01:26.126 Prompt (password, "SSH password", <no instructions>, "&Password: ")
. 2021-09-20 14:01:26.126 Using stored password.
< 2021-09-20 14:01:26.126 Script: Authenticating with pre-entered password.
. 2021-09-20 14:01:26.126 Sent password
. 2021-09-20 14:01:26.204 Access granted
. 2021-09-20 14:01:26.204 Opening main session channel
. 2021-09-20 14:01:26.736 Opened main channel
. 2021-09-20 14:01:26.736 Started a shell/command
< 2021-09-20 14:01:26.736 Script: Authenticated.
. 2021-09-20 14:01:26.736 --------------------------------------------------------------------------
. 2021-09-20 14:01:26.736 Using SFTP protocol.
. 2021-09-20 14:01:26.736 Doing startup conversation with host.
< 2021-09-20 14:01:26.736 Script: Starting the session...
> 2021-09-20 14:01:26.736 Type: SSH_FXP_INIT, Size: 5, Number: -1
< 2021-09-20 14:01:26.736 Type: SSH_FXP_VERSION, Size: 150, Number: -1
. 2021-09-20 14:01:26.736 SFTP version 3 negotiated.
. 2021-09-20 14:01:26.736 Unknown server extension posix-rename@openssh.com="1"
. 2021-09-20 14:01:26.736 Supports statvfs@openssh.com extension version "2"
. 2021-09-20 14:01:26.736 Unknown server extension fstatvfs@openssh.com="2"
. 2021-09-20 14:01:26.736 Supports hardlink@openssh.com extension version "1"
. 2021-09-20 14:01:26.736 Unknown server extension fsync@openssh.com="1"
. 2021-09-20 14:01:26.736 We believe the server has signed timestamps bug
. 2021-09-20 14:01:26.736 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-09-20 14:01:26.736 Limiting packet size to OpenSSH sftp-server limit of 262148 bytes
. 2021-09-20 14:01:26.736 Getting current directory name.
. 2021-09-20 14:01:26.736 Getting real path for '.'
> 2021-09-20 14:01:26.736 Type: SSH_FXP_REALPATH, Size: 10, Number: 16
< 2021-09-20 14:01:26.736 Type: SSH_FXP_NAME, Size: 23, Number: 16
. 2021-09-20 14:01:26.736 Real path is '/'
. 2021-09-20 14:01:26.736 Startup conversation with host finished.
< 2021-09-20 14:01:26.736 Script: Session started.
< 2021-09-20 14:01:26.736 Script: Active session: [1] orchard@awFTP.awdmz.local
> 2021-09-20 14:01:26.736 Script: put E:\AdurDocuments\"Adur Homes Services"\"Regular Reports from Orchard"\"MATS imports"\*.csv /SFTP_Dir/orchard/
< 2021-09-20 14:01:26.736 Script: No file matching '*.csv' found.
. 2021-09-20 14:01:26.736 Copying 0 files/directories to remote directory "/SFTP_Dir/orchard/" - total size: 0
. 2021-09-20 14:01:26.736   PrTime: Yes; PrRO: No; Rght: rw-r--r--; PrR: No (No); FnCs: N; RIC: 0100; Resume: S (102400); CalcS: No; Mask: 
. 2021-09-20 14:01:26.736   TM: B; ClAr: No; RemEOF: No; RemBOM: No; CPS: 0; NewerOnly: No; EncryptNewFiles: Yes; ExcludeHiddenFiles: No; ExcludeEmptyDirectories: No; InclM: ; ResumeL: 0
. 2021-09-20 14:01:26.736   AscM: *.*html; *.htm; *.txt; *.php; *.php3; *.cgi; *.c; *.cpp; *.h; *.pas; *.bas; *.tex; *.pl; *.js; .htaccess; *.xtml; *.css; *.cfg; *.ini; *.sh; *.xml
. 2021-09-20 14:01:26.736 Copying finished: Transferred: 0, Elapsed: 0:00:00, CPS: 0/s
> 2021-09-20 14:01:26.736 Script: exit
. 2021-09-20 14:01:26.736 Script: Exit code: 0
. 2021-09-20 14:01:26.736 Closing connection.
. 2021-09-20 14:01:26.736 Sending special code: 1
. 2021-09-20 14:01:26.751 Session sent command exit status 0
. 2021-09-20 14:01:26.751 Main session channel closed
. 2021-09-20 14:01:26.751 All channels closed

Very grateful for the fresh eyes.

Reply with quote

jmangan

It's like peeling an onion!

2021-09-20 15:03

I think once I had fixed the account issue I found a new one where the PowerShell script was progressing before WinSCP had finished its work generating a superfluous error message.

I think I've got it sorted now. Thanks again for the pointers.

Reply with quote