Scripts failing: Access is denied

shieldedge · February 12, 2022, 5:30am

I have two scripts to write log entries to Windows event logs and (if applicable) close outlook prior to running the backup.
On this particular machine the scripts will run as system with no problem… they will run in a user space with no problem, but when run as a pre and post script for a Duplicati job, they create a failure in the Duplicati log with the result of “access is denied” and cause the job to have warnings.

These are the exact same scripts I have used on other Windows implementations of Duplicati without issue

I have attempted the following to resolve without success:

Allowed full permissions to the scrips folder to all users, system and admin users
Changed the user running the Duplicati service
Made sure there were no User session Duplicati instances running
Made sure System acount has full control to Duplicati folder in Program Files folder
Changed the contents of the script file to write log files when executed to see if there were any internal errors (no output redirected when run through Duplicati job)
Made System account interactive and then changed it back

I am at a loss as to where to go next… any help is appreciated.

drwtsn32 · February 14, 2022, 5:13am

When you are doing this in user space, are you elevating by chance? If so, maybe Duplicati is running non-elevated and that’s the difference.

If that’s not the case, then I would probably run SysInternals Process Monitor to log exactly where the access denied occurs.

shieldedge · February 14, 2022, 1:46pm

I can run in either administrator or user space (with or without elevation), and the script throws no errors, completes the functions within the scritps (eventcreate & taskkill) and closes.

Only when run from a job is it apparently having a problem. I am starting to suspect that the launching of the job itself is actually the problem, not the script.

I have used process monitor before, but I am not certain how I would use it to troubleshoot this particular problem.

A little further troubleshooting information:
I modified the script to include one line… a REM statement. Nothing else. Same error:

2022-02-14 08:21:56 -05 - [Warning-Duplicati.Library.Modules.Builtin.RunScript-ScriptExecuteError]: Error while executing script “C:\Scripts\Duplicati_Pre.cmd”: Access is denied

I have to interpret this now as: I am sorry, Duplicati Service does not have the permissions to execute that script.

I had already removed the installed AV in an attempt to remove any impediment from a perceived technically bad standpoint (programs executing programs).

C:\Scripts>duplicati_pre
C:\Scripts>REM Testing Execution with no commands
C:\Scripts>whoami
nt authority\system
C:\Scripts>

drwtsn32 · February 14, 2022, 3:26pm

I wonder if it’s something within the script that is generating the error condition in Duplicati. (Although I kind of don’t think so…)

Can you confirm this by adding some logging to your script. Something as simple as

echo step 1 > C:\scripts\debug.log

before line 1, then

echo step 2 >> C:\scripts\debug.log

before line 2, and so on.

Then try to have Duplicati run the script again and see if a log file is generated.

shieldedge · February 14, 2022, 6:13pm

The only line in the script was changed to a REM statement… there is no line on which to take action or to fail.

Duplicati_Pre.cmd =

REM Testing Execution with no commands

I am pretty certain it is not an issue with an executed line of the script… since there is nothing in the script to execute.

drwtsn32 · February 14, 2022, 6:32pm

Yep, I agree with your conclusion. It must be that it can’t launch the actual script.

Changed the contents of the script file to write log files when executed

And sorry, I just realized you actually already did the suggestion in my earlier message.

Allowed full permissions to the scrips folder to all users, system and admin users

Looks like you have Duplicati configured to run as LocalSystem, so having SYSTEM in the ACL with read+execute should be all you need.

The only other thing I can think of is maybe it is some sort of antimalware software that is preventing it from running. But that doesn’t really make sense since you can run it manually.

Puzzling…

shieldedge · February 14, 2022, 7:10pm

They were good suggestions.

ts678 · February 15, 2022, 5:07pm

If you suspect a Duplicati access issue to a little-read file, maybe filter Path with a contains of script.

Process name filter might work too, but would give a lot more output, so might be a second approach.

I suppose you could Export As Command-line and run from there, if you haven’t tried that combination.
I’m not sure why it would differ from a service running as Local System account, but it’s another test.

There are some fine-grained views available. A lot of clicks, but right-click → Properties → Security → Advanced → (select a user) → View → Show advanced permissions. An example from my system is:

How the System Uses ACLs potentially factors in because an ACL is access control entries in an order.

How Windows orders Access Control Entries also covers subtle points behind access control decisions.

This is all getting pretty exotic. First thing to try is to see if Process Monitor shows a file access problem.

shieldedge · February 15, 2022, 7:26pm

Yes,
ProcMon shows a file access problem:
Class: File System
Operation: CreateFile
Result: Access Denied

The only thing this tells me is that the file system tried to open the file and it got smacked down.
Since the ShareMode is Read& Delete, I wouldn’t think something had it stuck open in write mode.

I checked the RSOP style permissions check and the System account result was all permissions allowed.
I don’t think it’s a permissions issue.

WebRoot is installed, and right after this call (0.001 seconds later) so I put in an exception in webroot thinking maybe it was opening it for review while the access was attempting and it failed for some reason.

The only other oddity are the calls before this is a call from Duplicati to a registry key: HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Image File Execution Options\Duplicati_Pre.cmd which it didn’t find, and just before that is six calls from Duplicati Service to open and read the script file that succeeded where the share mode was read, write, delete instead of just read, delete. Two opens, two functions, two closes.

6:32:07.9436942 PM	Duplicati.Server.exe	8444	CreateFile	C:\Scripts\Duplicati_Pre.cmd	SUCCESS	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
6:32:07.9437347 PM	Duplicati.Server.exe	8444	QueryBasicInformationFile	C:\Scripts\Duplicati_Pre.cmd	SUCCESS	CreationTime: 2/11/2022 4:54:46 PM, LastAccessTime: 2/14/2022 1:10:35 PM, LastWriteTime: 2/14/2022 8:21:35 AM, ChangeTime: 2/14/2022 8:21:35 AM, FileAttributes: A
6:32:07.9437471 PM	Duplicati.Server.exe	8444	CloseFile	C:\Scripts\Duplicati_Pre.cmd	SUCCESS
6:32:07.9439437 PM	Duplicati.Server.exe	8444	CreateFile	C:\Scripts\Duplicati_Pre.cmd	SUCCESS	Desired Access: Read Attributes, Disposition: Open, Options: Open Reparse Point, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened
6:32:07.9439757 PM	Duplicati.Server.exe	8444	QueryBasicInformationFile	C:\Scripts\Duplicati_Pre.cmd	SUCCESS	CreationTime: 2/11/2022 4:54:46 PM, LastAccessTime: 2/14/2022 1:10:35 PM, LastWriteTime: 2/14/2022 8:21:35 AM, ChangeTime: 2/14/2022 8:21:35 AM, FileAttributes: A
6:32:07.9439867 PM	Duplicati.Server.exe	8444	CloseFile	C:\Scripts\Duplicati_Pre.cmd	SUCCESS
6:32:07.9442732 PM	Duplicati.Server.exe	8444	RegOpenKey	HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Image File Execution Options\Duplicati_Pre.cmd	NAME NOT FOUND	Desired Access: Query Value, Enumerate Sub Keys
6:32:07.9444323 PM	Duplicati.Server.exe	8444	CreateFile	C:\Scripts\Duplicati_Pre.cmd	ACCESS DENIED	Desired Access: Read Data/List Directory, Execute/Traverse, Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Attributes: N, ShareMode: Read, Delete, AllocationSize: n/a
6:32:07.9456377 PM	WRSA.exe	1632	CreateFile	C:\Scripts\Duplicati_Pre.cmd	SUCCESS	Desired Access: Read Attributes, Synchronize, Disposition: Open, Options: Synchronous IO Non-Alert, Non-Directory File, Disallow Exclusive, Attributes: n/a, ShareMode: Read, Write, Delete, AllocationSize: n/a, OpenResult: Opened

I don’t know what to make of it.

ts678 · February 15, 2022, 8:39pm

and I see in original post that you worked with that a lot. Maybe something else caused “smacked down”.

Changing Procmon’s Altitude (Capturing Lower-Level Events) was one of my first seen bits of information about filter drivers, how to see what you have, and where Process Monitor lives (influencing what it sees).

There are other materials (as found by Google search for “procmon” "altitude), for example this new one:

Change Altitude of Process Monitor (ProcMon)

If that looks too dangerous, you can safely check if your filter drivers look the same on different systems. You’re apparently having this run fine on others, but on this one it can do the backups but not the scripts.

How’s your PowerShell? I think it (like Duplicati) uses .NET Framework so might be able to repro issues.
Start-Process might be similar to the Process.Start that Duplicati runs below before it gets the exception:

github.com

duplicati/duplicati/blob/27ff8cd20b3e349f6efd7b3b754637c0d940ea9c/Duplicati/Library/Modules/Builtin/RunScript.cs#L253-L253


      
          using (System.Diagnostics.Process p = System.Diagnostics.Process.Start(psi))

github.com

duplicati/duplicati/blob/27ff8cd20b3e349f6efd7b3b754637c0d940ea9c/Duplicati/Library/Modules/Builtin/RunScript.cs#L391-L396


      
          catch (Exception ex)

          {

              Logging.Log.WriteWarningMessage(LOGTAG, "ScriptExecuteError", ex, Strings.RunScript.ScriptExecuteError(scriptpath, ex.Message));

              if (requiredScript)

                  throw;

          }

Running low on ideas… Anyone else have any?

drwtsn32 · February 16, 2022, 1:58am

I’m stumped on this one!

It shouldn’t be needed, but can you grant Everyone:Full access to the script?

ts678 · February 16, 2022, 12:50pm

Now that Process Monitor is working, although still hard to interpret, you could try running something else, such as a harmless .exe file, perhaps a copy of some benign Windows command-line-suitable command. Looking in C:\Windows\System32 I see whoami.exe which is happy to run without any arguments. This is good because Duplicati can’t supply arguments, so usually people have to put the arguments in the script.

The .NET Framework program starter also prefers .exe files, but will do .bat files. I had to test if it could start a cmd file, and it did here, but you could check file associations and different kinds of program types.

Although it’s not the same as running a script, you could see if Duplicati can access the folder for backup and restore. You could also test other folders, maybe even test a FAT32 filesystem on a USB thumb drive.

NTFS is complicated and I don’t understand it completely, but you can get it out of the way by not using it.

I see another post being written now, so maybe it will do better than I’m doing.

shieldedge · February 16, 2022, 12:52pm

I have no error running the script… it didn’t bomb out.
The above change is the only change. It has to be the reason.

Thank you everyone for putting your heads together with me for this. I really appreciate it.

JimboJones · February 16, 2022, 1:05pm

Are the scripts you’re running PowerShell scripts and if so have you enabled the execution of scripts? set-executionpolicy remotesigned You can manually run a .ps1 without changing the policy but it won’t run on it’s own unless the executionpolicy has been changed from the default.

Did you have the service running under the “Local System” account or as the local “System” account? The first should just work, anything else would require a bunch of permission modifications and still probably won’t be enough, landing you right where you are.

ts678 · February 16, 2022, 1:18pm

I was always confused about the setup here and on the other systems (the ones that were working).

Is the installed AV different from WebRoot? If not, a removal seems like it should have been effective.

Regardless, if you’re happy with current situation, that’s great.

shieldedge · February 16, 2022, 6:21pm

I had installed Sentinel One days earlier as I didn’t see anything in the system tray on that device… My reference initially was to the removal of that product. It was only later (when looking at the Process Monitor output) that I realized they must have Webroot on there too (I just took over support of these computers). I am really glad that the double stack didn’t conflict (usually two stacks bring a system to a snail’s pace), but it left me with the incorrect impression there was nothing else installed.
I gained access to the WebRoot management interface for that company and saw that the agent was checking in.

Thank you for your patience and help, it is much appreciated.