Open phdavis opened 3 months ago
Hey @phdavis,
I've an idea as to what might be causing it based on the first exception, but need a lil' more info:
Add-PodeSchedule
scriptblock? pki
module beforehand, similar to the AD one above?$_.Exception | Out-File "E:\Logs\_UnhandledExceptions.log" -Append
, could you also log $_.ScriptStackTrace
as well? Hopefully this should output a stacktrace with line numbers in Pode scripts 😃 As a test, I can see you only want this to run once when the server starts? What happens if you replace the Schedule with Register-PodeEvent -Type Running -Name 'StartupTasks' -Scriptblock { ... }
instead? Based on the first exception I think the Schedule might be loading other modules or state changes, which is altering a Collection while the Web Runspaces are spinning-up 🤔
Are there any other Pode functions called within the Add-PodeSchedule scriptblock?
Only some Invoke-PodeTask
What happens if you try to import the pki module beforehand, similar to the AD one above? It took a bit, but I eventually got this exception
ErrorRecord : Exception calling "BeginInvoke" with "0" argument(s): "The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
"
WasThrownFromThrowStatement : True
TargetSite : Void CheckActionPreference(System.Management.Automation.Language.FunctionContext, System.Exception)
Message : Exception calling "BeginInvoke" with "0" argument(s): "The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
"
Data : {[System.Management.Automation.Interpreter.InterpretedFrameInfo, System.Management.Automation.Interpreter.InterpretedFrameInfo[]]}
InnerException : System.Management.Automation.CmdletInvocationException: The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
---> System.Management.Automation.RuntimeException: The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
at System.Management.Automation.Runspaces.InitialSessionState.ThrowTypeOrFormatErrors(String resourceString, String errorMsg, String errorId)
at System.Management.Automation.Runspaces.InitialSessionState.UpdateTypes(ExecutionContext context, Boolean updateOnly)
at System.Management.Automation.Runspaces.InitialSessionState.Bind_UpdateTypes(ExecutionContext context, Boolean updateOnly)
at System.Management.Automation.Runspaces.InitialSessionState.Bind(ExecutionContext context, Boolean updateOnly, PSModuleInfo module, Boolean noClobber, Boolean local, Boolean setLocation)
at Microsoft.PowerShell.Commands.ModuleCmdletBase.LoadModuleManifest(String moduleManifestPath, ExternalScriptInfo manifestScriptInfo, Hashtable data, Hashtable localizedData, ManifestProcessingFlags manifestProcessingFlags, Version minimumVersion, Version maximumVersion, Version requiredVersion, Nullable`1 requiredModuleGuid, ImportModuleOptions& options, Boolean& containedErrors)
--- End of inner exception stack trace ---
at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input)
at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke)
at System.Management.Automation.PowerShell.Worker.CreateRunspaceIfNeededAndDoWork(Runspace rsToUse, Boolean isSync)
at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
at System.Management.Automation.Runspaces.InitialSessionState.ProcessOneModule(Runspace initializedRunspace, String name, PSModuleInfo moduleInfoToLoad, String path, HashSet`1 publicCommands, List`1 processedModules)
at System.Management.Automation.Runspaces.InitialSessionState.ProcessModulesToImport(Runspace initializedRunspace, IEnumerable moduleList, String path, HashSet`1 publicCommands, HashSet`1 unresolvedCmdsToExpose)
at System.Management.Automation.Runspaces.InitialSessionState.BindRunspace(Runspace initializedRunspace, PSTraceSource runspaceInitTracer)
at System.Management.Automation.Runspaces.LocalRunspace.DoOpenHelper()
at System.Management.Automation.Runspaces.RunspaceBase.CoreOpen(Boolean syncCall)
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.CreateRunspace()
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.ServicePendingRequests(Object useCallingThreadState)
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.EnqueueCheckAndStartRequestServicingThread(GetRunspaceAsyncResult requestToEnqueue, Boolean useCallingThread)
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.BeginGetRunspace(AsyncCallback callback, Object state)
at System.Management.Automation.PowerShell.CoreInvokeAsync[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings, AsyncCallback callback, Object state, PSDataCollection`1 asyncResultOutput)
at System.Management.Automation.PowerShell.BeginInvoke[T](PSDataCollection`1 input, PSInvocationSettings settings, AsyncCallback callback, Object state)
at CallSite.Target(Closure, CallSite, Object)
HelpLink :
Source : System.Management.Automation
HResult : -2146233087
StackTrace : at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext funcContext, Exception exception)
at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)
at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
at Add-PodeRunspace, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\Helpers.ps1: line 579
at <ScriptBlock>, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\PodeServer.ps1: line 279
at Start-PodeWebServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\PodeServer.ps1: line 278
at Start-PodeInternalServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\Server.ps1: line 120
at Start-PodeServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Public\Core.ps1: line 183
at <ScriptBlock>, E:\Server\server.ps1: line 21
Could you also log $_.ScriptStackTrace I got this for the AD module importing, which appears to be pointing to the same thing
at Add-PodeRunspace, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\Helpers.ps1: line 579
at <ScriptBlock>, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\PodeServer.ps1: line 279
at Start-PodeWebServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\PodeServer.ps1: line 278
at Start-PodeInternalServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\Server.ps1: line 120
at Start-PodeServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Public\Core.ps1: line 183
at <ScriptBlock>, E:\Server\server.ps1: line 21
Register-PodeEvent When I did this I got this exception and as far as I can tell the server just restarts over and over with the same exception. I reverted back to using the original Schedule.
ErrorRecord : Exception calling "BeginInvoke" with "0" argument(s): "The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
"
WasThrownFromThrowStatement : True
TargetSite : Void CheckActionPreference(System.Management.Automation.Language.FunctionContext, System.Exception)
Message : Exception calling "BeginInvoke" with "0" argument(s): "The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
"
Data : {[System.Management.Automation.Interpreter.InterpretedFrameInfo, System.Management.Automation.Interpreter.InterpretedFrameInfo[]]}
InnerException : System.Management.Automation.CmdletInvocationException: The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
---> System.Management.Automation.RuntimeException: The following error occurred while loading the extended type data file:
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member PolicyId is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentServerEndPoint is already present.
Error in TypeData "System.Security.Cryptography.X509Certificates.X509Certificate2": The member EnrollmentPolicyEndPoint is already present.
at System.Management.Automation.Runspaces.InitialSessionState.ThrowTypeOrFormatErrors(String resourceString, String errorMsg, String errorId)
at System.Management.Automation.Runspaces.InitialSessionState.UpdateTypes(ExecutionContext context, Boolean updateOnly)
at System.Management.Automation.Runspaces.InitialSessionState.Bind_UpdateTypes(ExecutionContext context, Boolean updateOnly)
at System.Management.Automation.Runspaces.InitialSessionState.Bind(ExecutionContext context, Boolean updateOnly, PSModuleInfo module, Boolean noClobber, Boolean local, Boolean setLocation)
at Microsoft.PowerShell.Commands.ModuleCmdletBase.LoadModuleManifest(String moduleManifestPath, ExternalScriptInfo manifestScriptInfo, Hashtable data, Hashtable localizedData, ManifestProcessingFlags manifestProcessingFlags, Version minimumVersion, Version maximumVersion, Version requiredVersion, Nullable`1 requiredModuleGuid, ImportModuleOptions& options, Boolean& containedErrors)
--- End of inner exception stack trace ---
at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input)
at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke)
at System.Management.Automation.PowerShell.Worker.CreateRunspaceIfNeededAndDoWork(Runspace rsToUse, Boolean isSync)
at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings)
at System.Management.Automation.PowerShell.Invoke[T]()
at System.Management.Automation.Runspaces.InitialSessionState.ProcessOneModule(Runspace initializedRunspace, String name, PSModuleInfo moduleInfoToLoad, String path, HashSet`1 publicCommands, List`1 processedModules)
at System.Management.Automation.Runspaces.InitialSessionState.ProcessModulesToImport(Runspace initializedRunspace, IEnumerable moduleList, String path, HashSet`1 publicCommands, HashSet`1 unresolvedCmdsToExpose)
at System.Management.Automation.Runspaces.InitialSessionState.BindRunspace(Runspace initializedRunspace, PSTraceSource runspaceInitTracer)
at System.Management.Automation.Runspaces.LocalRunspace.DoOpenHelper()
at System.Management.Automation.Runspaces.RunspaceBase.CoreOpen(Boolean syncCall)
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.CreateRunspace()
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.ServicePendingRequests(Object useCallingThreadState)
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.EnqueueCheckAndStartRequestServicingThread(GetRunspaceAsyncResult requestToEnqueue, Boolean useCallingThread)
at System.Management.Automation.Runspaces.Internal.RunspacePoolInternal.BeginGetRunspace(AsyncCallback callback, Object state)
at System.Management.Automation.PowerShell.CoreInvokeAsync[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings, AsyncCallback callback, Object state, PSDataCollection`1 asyncResultOutput)
at System.Management.Automation.PowerShell.BeginInvoke[T](PSDataCollection`1 input, PSInvocationSettings settings, AsyncCallback callback, Object state)
at CallSite.Target(Closure, CallSite, Object)
HelpLink :
Source : System.Management.Automation
HResult : -2146233087
StackTrace : at System.Management.Automation.ExceptionHandlingOps.CheckActionPreference(FunctionContext funcContext, Exception exception)
at System.Management.Automation.Interpreter.ActionCallInstruction`2.Run(InterpretedFrame frame)
at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
at System.Management.Automation.Interpreter.EnterTryCatchFinallyInstruction.Run(InterpretedFrame frame)
at Add-PodeRunspace, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\Helpers.ps1: line 579
at Start-PodeTimerRunspace, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\Timers.ps1: line 61
at Start-PodeInternalServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Private\Server.ps1: line 70
at Start-PodeServer, C:\Program Files\PowerShell\Modules\Pode\2.10.1\Public\Core.ps1: line 183
at <ScriptBlock>, E:\Server\server.ps1: line 21
I had some more time to try narrowing this down. It seems the worst of it is directly related to pki
. After commenting out all the code, it stops doing the crash loop. I was then able to start uncommenting some stuff. The very first line when running manually auto imports pki
if (Test-Path "Cert:\LocalMachine\My\$CertThumbprint"){}
Before running command
After running command
I noticed it was Manifest
instead of Script
(if that matters) and after looking, there's really no files related to pki itself. I decided to try ripping the code out of server.ps1 and placed it into its own Pode task, then added that task to our OnStartSchedule
which seems to have resolved the exceptions related to pki
. We get the information we need on start and it doesn't appear to cause the startup loop anymore.
We are still getting the ActiveDirectory
and the Collection was modified; enumeration operation may not execute.
exceptions, but they're less common and easy enough to ignore for now.
I've just tried reproducing this myself, but I can't get it to throw any errors - all loads for me.
While researching the error, I found that the Collection was modified; enumeration operation may not execute
is being thrown by Import-Module
itself, and this only normally happens if the module's manifest is being manipulated by another process. I can't see anything in PKI or AD which would do this, so wondering if you might have any other modules loaded when Pode starts?
If not, one option could be that I add a config item to force all Runspaces to load sequentially rather than parallel/async. That might resolve, or a least further reduce, the occurrence of the error 🤔
Thank you for digging! Based on what I can see it looks like these are getting loaded at start. These have been in use since day one more or less, so I can't really narrow it down to any in particular.
Az.Accounts
Az.KeyVault
SqlServer
VMware.Vim
VMware.VimAutomation.Cis.Core
VMware.VimAutomation.Common
VMWare.VimAutomation.Sdk
Describe the Bug
This seems to be a random bug that occurs only when restarting the server/service and doesn't happen every time. Usually, when we restart our API, it'll begin, get through a few tasks, then automatically restart and throw one of these exceptions. It will usually do this once or twice before finally deciding everything is loaded (?) then run normally without any further issues until we restart again.
I believe the issue is specifically while loading the
ActiveDirectory
module and/or thepki
module. I've seen other past issues similar to this, but they were much older and not necessarily the same.Steps To Reproduce
Steps to reproduce the behavior: We're not entirely sure what's causing it, but at a high level we have a server setup like so running as a service with NSSM.
Expected Behavior
We would expect the server to either always have the exception, or never have the exception during startup. Ultimately the server does fire up fine, but when it does this it usually takes several extra minutes to straighten itself out.
At the very least we'd like to understand the root cause even if it's not resolvable on the Pode side.
Logs
Here's the main exception we see -
The other exceptions are more specific. They could be entirely unrelated but do seem to always occur around the same time during these restart cycles. I've chopped most off for brevity -
Platform