Description
Is there an existing issue for this?
- I have searched the existing issues
Describe the bug
Troubleshooting shadow copy-related issues can be difficult as the event log entries (and later the actual ANCM enhanced log output) don't surface much helpful information.
To figure out the simplest permission issue where the worker process has no permissions at all to the shadow copy directory requires either a ProcMon trace or the ANCM Enhanced Logging be enabled and captured.
Here's what the Application event log showed:
Source: IIS AspNetCore Module V2
Message: Could not load configuration. Exception message:
XML Details:
<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
<System>
<Provider Name="IIS AspNetCore Module V2" />
<EventID Qualifiers="0">1034</EventID>
<Version>0</Version>
<Level>2</Level>
<Task>0</Task>
<Opcode>0</Opcode>
<Keywords>0x80000000000000</Keywords>
<TimeCreated SystemTime="2025-05-28T20:28:01.5405669Z" />
<EventRecordID>167788</EventRecordID>
<Correlation />
<Execution ProcessID="36092" ThreadID="0" />
<Channel>Application</Channel>
<Computer>[redacted]</Computer>
<Security />
</System>
<EventData>
<Data>Could not load configuration. Exception message:</Data>
<Data>Process Id: 36092.</Data>
<Data>File Version: 19.0.25119.5. Description: IIS ASP.NET Core Module V2. Commit:</Data>
</EventData>
</Event>
There were no other related events in the Application log, and nothing to indicate a permissions-related issue.
However, both ProcMon and the ANCM Enhanced Logging output did show it:
ProcMon:
ANCM Enhanced logging:
[2025-05-28T20:28:01.533Z, PID: 36092] [aspnetcorev2.dll] Initializing logs for 'C:\Program Files\IIS\Asp.Net Core Module\V2\aspnetcorev2.dll'. Process Id: 36092. File Version: 19.0.25119.5. Description: IIS ASP.NET Core Module V2. Commit: .
[2025-05-28T20:28:01.537Z, PID: 36092] [aspnetcorev2.dll] Exception 'directory_entry::refresh: Access is denied.: "c:\behindiis-shadowcopy"' caught at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\applicationinfo.cpp:150
[2025-05-28T20:28:01.541Z, PID: 36092] [aspnetcorev2.dll] Event Log: 'Could not load configuration. Exception message:
'
End Event Log Message.
In addition, the HTTP 500 error page for the above is generic and also provides nothing helpful.
In this scenario, the event log should really be outputting an access-related error. In the Expected behavior section later I cover this.
Now, adding a tiny bit of complexity in the form of indirectly (via local Users group) allowing the worker process to read/traverse the shadow copy directory, but still not allowing any modification produces what I would argue to be an even more confusing set of outputs, including in the ANCM enhanced logs.
Application Event Viewer log:
(including just the raw XML data from the 2 events that were output)
first event:
<EventData>
<Data>Application 'c:\behindiis-shadowcopy\0' failed to start. Exception message: Executable was not found at 'c:\behindiis-shadowcopy\0\.\BehindIIS-servervars.exe'</Data>
<Data>Process Id: 38460.</Data>
<Data>File Version: 19.0.25119.5. Description: IIS ASP.NET Core Module V2. Commit:</Data>
</EventData>
second event:
<EventData>
<Data>Failed to start application '/LM/W3SVC/1/ROOT/behindiis-servervars', ErrorCode '0x8007023e'.</Data>
<Data>Process Id: 38460.</Data>
<Data>File Version: 19.0.25119.5. Description: IIS ASP.NET Core Module V2. Commit:</Data>
</EventData>
ProcMon:
ANCM enhanced logs:
[2025-05-28T20:31:41.946Z, PID: 38460] [aspnetcorev2.dll] Initializing logs for 'C:\Program Files\IIS\Asp.Net Core Module\V2\aspnetcorev2.dll'. Process Id: 38460. File Version: 19.0.25119.5. Description: IIS ASP.NET Core Module V2. Commit: .
[2025-05-28T20:31:41.949Z, PID: 38460] [aspnetcorev2.dll] Copying to shadow copy directory c:\behindiis-shadowcopy\0.
[2025-05-28T20:31:41.957Z, PID: 38460] [aspnetcorev2.dll] Finished copying 9 files to shadow copy directory c:\behindiis-shadowcopy.
[2025-05-28T20:31:41.958Z, PID: 38460] [aspnetcorev2.dll] Resolving hostfxr parameters for application: '.\BehindIIS-servervars.exe' arguments: '' path: 'c:\behindiis-shadowcopy\0'
[2025-05-28T20:31:41.959Z, PID: 38460] [aspnetcorev2.dll] Known dotnet.exe location: ''
[2025-05-28T20:31:41.959Z, PID: 38460] [aspnetcorev2.dll] Process path '.\BehindIIS-servervars.exe' is not dotnet, treating application as standalone or portable with bootstrapper
[2025-05-28T20:31:41.961Z, PID: 38460] [aspnetcorev2.dll] Event Log: 'Application 'c:\behindiis-shadowcopy\0' failed to start. Exception message:
Executable was not found at 'c:\behindiis-shadowcopy\0\.\BehindIIS-servervars.exe''
End Event Log Message.
[2025-05-28T20:31:41.962Z, PID: 38460] [aspnetcorev2.dll] InvalidOperationException 'Executable was not found at 'c:\behindiis-shadowcopy\0\.\BehindIIS-servervars.exe'' caught at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\CommonLib\HostFxrResolutionResult.cpp:64
[2025-05-28T20:31:41.963Z, PID: 38460] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\HandlerResolver.cpp:71
[2025-05-28T20:31:41.964Z, PID: 38460] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\HandlerResolver.cpp:177
[2025-05-28T20:31:41.964Z, PID: 38460] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\applicationinfo.cpp:198
[2025-05-28T20:31:41.965Z, PID: 38460] [aspnetcorev2.dll] Failed HRESULT returned: 0x8007023e at D:\a\_work\1\s\src\Servers\IIS\AspNetCoreModuleV2\AspNetCore\applicationinfo.cpp:111
[2025-05-28T20:31:41.966Z, PID: 38460] [aspnetcorev2.dll] Event Log: 'Failed to start application '/LM/W3SVC/1/ROOT/behindiis-servervars', ErrorCode '0x8007023e'.'
End Event Log Message.
One of the outputs above is particularly interesting:
[2025-05-28T20:31:41.957Z, PID: 38460] [aspnetcorev2.dll] Finished copying 9 files to shadow copy directory c:\behindiis-shadowcopy.
This is straight-up wrong as nothing was copied, and the attempt to create the initial 0 folder under the shadow copy directory failed with "access denied" outright as shown above.
Then ANCM logs show the attempt to load the app continued, from the shadow copy directory which we were led to believe contains 9 files in the above output, when in reality it contains 0. The error code 8007023e is also not helpful.
Only manually navigating to that directory and looking for the EXE that it couldn't find would show that it is, in fact, not there. So now trying to figure out why it's not there when it said it was makes it all the more difficult to figure out, especially since we now know it's a permissions-related issue and there's not a hint of that in any output here.
Expected Behavior
The errors being output to the various logs around shadow copy failures should be more concise and should help with diagnosing problems with it. Shadow copy historically has not been easy to troubleshoot, especially when even the simplest of permissions issues results in no useful, or, worse, misleading, debugging output.
At a minimum, being the only log enabled and used by default here, the Application Event Viewer log entries need to have something useful, because right now it doesn't. The issues demonstrated here are, yes, simple problems that could probably be figured out pretty quick to some people, but troubleshooting more complex issues with shadow copy could potentially be much more efficient and quick if even the basic output was valuable.
For the first issue above where no permissions were present on the shadow copy directory, the event log should really include the exception message as opposed to swallowing it and outputting the generic error:
This code is here:
catch (const ConfigurationLoadException &ex)
{
EventLog::Error(
ASPNETCORE_CONFIGURATION_LOAD_ERROR,
ASPNETCORE_CONFIGURATION_LOAD_ERROR_MSG,
ex.get_message().c_str());
}
catch (...)
{
OBSERVE_CAUGHT_EXCEPTION();
EventLog::Error(
ASPNETCORE_CONFIGURATION_LOAD_ERROR,
ASPNETCORE_CONFIGURATION_LOAD_ERROR_MSG,
L"");
}
For the 2nd scenario where the app has read-only permissions to the shadow copy directory, this is the code that outputs the successful-sounding "finished copying.." message even though it wasn't:
aspnetcore/src/Servers/IIS/AspNetCoreModuleV2/AspNetCore/applicationinfo.cpp
Lines 337 to 345 in 05c5d65
HRESULT hr = Environment::CopyToDirectory(physicalPath, shadowCopyPath, options.QueryCleanShadowCopyDirectory(), shadowCopyBaseDirectory.path(), copiedFileCount);
LOG_INFOF(L"Finished copying %d files to shadow copy directory %ls.", copiedFileCount, shadowCopyBaseDirectory.path().c_str());
if (hr != S_OK)
{
return std::wstring();
}
}
That is in the HandleShadowCopy function, and if the copy fails then an empty string is returned to the caller here:
aspnetcore/src/Servers/IIS/AspNetCoreModuleV2/AspNetCore/applicationinfo.cpp
Lines 196 to 198 in 05c5d65
auto shadowCopyPath = HandleShadowCopy(options, pHttpContext);
RETURN_IF_FAILED(m_handlerResolver.GetApplicationFactory(*pHttpContext.GetApplication(), shadowCopyPath, m_pApplicationFactory, options, error));
At that point, the code moves-on like nothing happened (and indeed the debug logging indicates all is well too at this point), only to fail down the road with a whole bunch of failure output that doesn't really help.
If shadow copy is enabled but returns an empty directory, should ANCM really continue moving forward?
Steps To Reproduce
Take any simple ANC project, ensure it's hosted in IIS and has shadow copy enabled in the web.config. Then ensure the needed permissions are not applied.
Exceptions (if any)
No response
.NET Version
No response
Anything else?
This is on the latest non-preview version of the hosting bundle (9.0.5) with ANCM version: 19.0.25119.5