Jobs failing with no output, incorrect execution time

[Jori]

Product: PowerShell Universal
Version: 2.3.0

Since updating to 2.3.0 this job (and the only I am currently running on Universal) has been failing without any output, and it says it executed 121 years ago. The server has PSU installed via the MSI and is using a service account.

[adam]

I think you might be hitting a bug in 2.3: Changelog - PowerShell Universal

We fixed it in 2.3.1. I’m not 100% sure what type of output causes it but I know another customer was running a batch script that caused this to happen. They worked around it by piping the output of the batch script to Out-String.

.\batch.bat | Out-String

[Darragh]

I think I’m encountering the same problem as you. Running 2.1.4 here. Also running as a service. But if you are encountering the same problem, I might have a solution.

My script produces a custom object. I think that’s why it’s failing. Perhaps it’s the same for you? If so, modify it to use a System.Collections.ArrayList instead.

I am quite sure this was encountered with Universal in the past. So perhaps this is a regression

Script is:

Function Get-RDSGatewayWarnings {
$Events = Get-WinEvent -ProviderName ‘Microsoft-Windows-TerminalServices-Gateway’ -ComputerName <> -MaxEvents 100 | Where-Object { $_.LevelDisplayName -eq “Warning” }
$ReportOutput = @()
ForEach ($Event in $Events) {
$LogEntry = New-Object -TypeName PSObject
$LogEntry | Add-Member -Type NoteProperty -Name Date -Value $Event.TimeCreated $LogEntry | Add-Member -Type NoteProperty
-Name Username -Value $Event.Properties[0].Value
$LogEntry | Add-Member -Type NoteProperty `
-Name Hostname -Value $Event.Properties[3].Value
$ReportOutput += $LogEntry
}
Return $ReportOutput
}


Under the PowershellUniversal directory in c:\programdata, I see the following log when the script is run. There’s an unexpected error related to CORS here. But other scripts run. So this could be misleading:

2021-09-22T00:00:28.6109165+01:00 0HMBTA6D8LL1M:0000019D [INF] Request starting HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/script/GetRDSHostServerWarnings.ps1 - - (ca22a1cb) 2021-09-22T00:00:28.6122685+01:00 0HMBTA6D8LL1M:0000019D [WRN] Error unprotecting the session cookie. (65f95c31) System.Security.Cryptography.CryptographicException: The key {b57fdfc9-9c9a-450c-a15d-f931ace1bfbc} was not found in the key ring. at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData) at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger) 2021-09-22T00:00:28.6157105+01:00 0HMBTA6D8LL1M:0000019D [INF] Authorization was successful. (0d575a54) 2021-09-22T00:00:28.6157941+01:00 0HMBTA6D8LL1M:0000019D [INF] Executing endpoint '"UniversalAutomation.ScriptController.Get (UniversalAutomation)"' (500cc934) 2021-09-22T00:00:28.6159261+01:00 0HMBTA6D8LL1M:0000019D [INF] Route matched with "{action = \"Get\", controller = \"Script\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Get(System.String)" on controller "UniversalAutomation.ScriptController" ("UniversalAutomation"). (122b2fdf) 2021-09-22T00:00:28.6182107+01:00 0HMBTA6D8LL1M:0000019D [INF] Executing JsonResult, writing value of type '"PowerShellUniversal.Script"'. (2f513669) 2021-09-22T00:00:28.6185362+01:00 0HMBTA6D8LL1M:0000019D [INF] Executed action "UniversalAutomation.ScriptController.Get (UniversalAutomation)" in 2.5503ms (afa2e885) 2021-09-22T00:00:28.6185772+01:00 0HMBTA6D8LL1M:0000019D [INF] Executed endpoint '"UniversalAutomation.ScriptController.Get (UniversalAutomation)"' (99874f2b) 2021-09-22T00:00:28.6187214+01:00 0HMBTA6D8LL1M:0000019D [INF] Request finished HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/script/GetRDSHostServerWarnings.ps1 - - - 200 - application/json;+charset=utf-8 7.8422ms (791a596a) 2021-09-22T00:00:28.6789171+01:00 0HMBTA6D8LL1M:0000019F [INF] Request starting HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/environment - - (ca22a1cb) 2021-09-22T00:00:28.6800955+01:00 0HMBTA6D8LL1M:0000019F [WRN] Error unprotecting the session cookie. (65f95c31) System.Security.Cryptography.CryptographicException: The key {b57fdfc9-9c9a-450c-a15d-f931ace1bfbc} was not found in the key ring. at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData) at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger) 2021-09-22T00:00:28.6834574+01:00 0HMBTA6D8LL1M:0000019F [INF] Authorization was successful. (0d575a54) 2021-09-22T00:00:28.6835200+01:00 0HMBTA6D8LL1M:0000019F [INF] Executing endpoint '"UniversalAutomation.ExecutionEnvironmentController.Get (UniversalAutomation)"' (500cc934) 2021-09-22T00:00:28.6836358+01:00 0HMBTA6D8LL1M:0000019F [INF] Route matched with "{action = \"Get\", controller = \"ExecutionEnvironment\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[PowerShellUniversal.ExecutionEnvironment] Get()" on controller "UniversalAutomation.ExecutionEnvironmentController" ("UniversalAutomation"). (122b2fdf) 2021-09-22T00:00:28.6838069+01:00 0HMBTA6D8LL1M:0000019F [INF] Executing "ObjectResult", writing value of type '"PowerShellUniversal.ExecutionEnvironment[]"'. (605b4265) 2021-09-22T00:00:28.6840654+01:00 0HMBTA6D8LL1M:0000019F [INF] Executed action "UniversalAutomation.ExecutionEnvironmentController.Get (UniversalAutomation)" in 0.3856ms (afa2e885) 2021-09-22T00:00:28.6840992+01:00 0HMBTA6D8LL1M:0000019F [INF] Executed endpoint '"UniversalAutomation.ExecutionEnvironmentController.Get (UniversalAutomation)"' (99874f2b) 2021-09-22T00:00:28.6842131+01:00 0HMBTA6D8LL1M:0000019F [INF] Request finished HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/environment - - - 200 429 application/json;+charset=utf-8 5.3128ms (791a596a) 2021-09-22T00:00:28.6857381+01:00 0HMBTA6D8LL1M:000001A1 [INF] Request starting HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/variable - - (ca22a1cb) 2021-09-22T00:00:28.6866531+01:00 0HMBTA6D8LL1M:000001A1 [WRN] Error unprotecting the session cookie. (65f95c31) System.Security.Cryptography.CryptographicException: The key {b57fdfc9-9c9a-450c-a15d-f931ace1bfbc} was not found in the key ring. at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData) at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger) 2021-09-22T00:00:28.6884591+01:00 0HMBTA6D8LL1M:000001A1 [INF] Authorization was successful. (0d575a54) 2021-09-22T00:00:28.6884933+01:00 0HMBTA6D8LL1M:000001A1 [INF] Executing endpoint '"UniversalAutomation.VariableController.Get (UniversalAutomation)"' (500cc934) 2021-09-22T00:00:28.6885642+01:00 0HMBTA6D8LL1M:000001A1 [INF] Route matched with "{action = \"Get\", controller = \"Variable\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[PowerShellUniversal.Variable] Get()" on controller "UniversalAutomation.VariableController" ("UniversalAutomation"). (122b2fdf) 2021-09-22T00:00:28.6886898+01:00 0HMBTA6D8LL1M:000001A1 [INF] Executing "ObjectResult", writing value of type '"System.Linq.Enumerable+SelectIListIterator`2[[PowerShellUniversal.Variable, PowerShellUniversal, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null],[PowerShellUniversal.Variable, PowerShellUniversal, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (605b4265) 2021-09-22T00:00:28.6888526+01:00 0HMBTA6D8LL1M:000001A1 [INF] Executed action "UniversalAutomation.VariableController.Get (UniversalAutomation)" in 0.26ms (afa2e885) 2021-09-22T00:00:28.6888712+01:00 0HMBTA6D8LL1M:000001A1 [INF] Executed endpoint '"UniversalAutomation.VariableController.Get (UniversalAutomation)"' (99874f2b) 2021-09-22T00:00:28.6889372+01:00 0HMBTA6D8LL1M:000001A1 [INF] Request finished HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/variable - - - 200 1270 application/json;+charset=utf-8 3.2062ms (791a596a) 2021-09-22T00:00:28.6889865+01:00 0HMBTA6D8LL1M:000001A3 [INF] Request starting HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/tag - - (ca22a1cb) 2021-09-22T00:00:28.6899572+01:00 0HMBTA6D8LL1M:000001A3 [WRN] Error unprotecting the session cookie. (65f95c31) System.Security.Cryptography.CryptographicException: The key {b57fdfc9-9c9a-450c-a15d-f931ace1bfbc} was not found in the key ring. at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData) at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger) 2021-09-22T00:00:28.6916631+01:00 0HMBTA6D8LL1M:000001A3 [INF] Authorization was successful. (0d575a54) 2021-09-22T00:00:28.6916973+01:00 0HMBTA6D8LL1M:000001A3 [INF] Executing endpoint '"UniversalAutomation.TagController.GetTags (UniversalAutomation)"' (500cc934) 2021-09-22T00:00:28.6917697+01:00 0HMBTA6D8LL1M:000001A3 [INF] Route matched with "{action = \"GetTags\", controller = \"Tag\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[PowerShellUniversal.Tag] GetTags()" on controller "UniversalAutomation.TagController" ("UniversalAutomation"). (122b2fdf) 2021-09-22T00:00:28.6919617+01:00 0HMBTA6D8LL1M:000001A3 [INF] Executing "ObjectResult", writing value of type '"PowerShellUniversal.Tag[]"'. (605b4265) 2021-09-22T00:00:28.6920688+01:00 0HMBTA6D8LL1M:000001A3 [INF] Executed action "UniversalAutomation.TagController.GetTags (UniversalAutomation)" in 0.2741ms (afa2e885) 2021-09-22T00:00:28.6920898+01:00 0HMBTA6D8LL1M:000001A3 [INF] Executed endpoint '"UniversalAutomation.TagController.GetTags (UniversalAutomation)"' (99874f2b) 2021-09-22T00:00:28.6921504+01:00 0HMBTA6D8LL1M:000001A3 [INF] Request finished HTTP/2 GET https://HOSTNAME.FQDN:4443/api/v1/tag - - - 200 2 application/json;+charset=utf-8 3.1535ms (791a596a) 2021-09-22T00:00:53.1676460+01:00 0HMBTA6D8LL1M:000001A5 [INF] Request starting HTTP/2 PUT https://HOSTNAME.FQDN:4443/api/v1/script application/json;charset=UTF-8 834 (ca22a1cb) 2021-09-22T00:00:53.1706666+01:00 0HMBTA6D8LL1M:000001A5 [INF] CORS policy execution failed. (09b6f179) 2021-09-22T00:00:53.1707184+01:00 0HMBTA6D8LL1M:000001A5 [INF] Request origin "https://HOSTNAME.FQDN:4443" does not have permission to access the resource. (a03d560b) 2021-09-22T00:00:53.1715753+01:00 0HMBTA6D8LL1M:000001A5 [WRN] Error unprotecting the session cookie. (65f95c31) System.Security.Cryptography.CryptographicException: The key {b57fdfc9-9c9a-450c-a15d-f931ace1bfbc} was not found in the key ring. at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData) at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger) 2021-09-22T00:00:53.1753448+01:00 0HMBTA6D8LL1M:000001A5 [INF] Authorization was successful. (0d575a54) 2021-09-22T00:00:53.1753736+01:00 0HMBTA6D8LL1M:000001A5 [INF] Executing endpoint '"UniversalAutomation.ScriptController.Put (UniversalAutomation)"' (500cc934) 2021-09-22T00:00:53.1754499+01:00 0HMBTA6D8LL1M:000001A5 [INF] Route matched with "{action = \"Put\", controller = \"Script\"}". Executing controller action with signature "System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Put(PowerShellUniversal.Script)" on controller "UniversalAutomation.ScriptController" ("UniversalAutomation"). (122b2fdf) 2021-09-22T00:00:53.3570921+01:00 0HMBTA6D8LL1M:000001A5 [INF] Executing HttpStatusCodeResult, setting HTTP status code 200 (e28ccfae) 2021-09-22T00:00:53.3571645+01:00 0HMBTA6D8LL1M:000001A5 [INF] Executed action "UniversalAutomation.ScriptController.Put (UniversalAutomation)" in 181.6821ms (afa2e885) 2021-09-22T00:00:53.3571835+01:00 0HMBTA6D8LL1M:000001A5 [INF] Executed endpoint '"UniversalAutomation.ScriptController.Put (UniversalAutomation)"' (99874f2b) 2021-09-22T00:00:53.3578390+01:00 0HMBTA6D8LL1M:000001A5 [INF] Request finished HTTP/2 PUT https://HOSTNAME.FQDN:4443/api/v1/script application/json;charset=UTF-8 834 - 200 0 - 190.2306ms (791a596a) 2021-09-22T00:00:58.3956234+01:00 0HMBTA6D8LL1M:000001A7 [INF] Request starting HTTP/2 PUT https://HOSTNAME.FQDN:4443/api/v1/script application/json;charset=UTF-8 834 (ca22a1cb) 2021-09-22T00:00:58.3960399+01:00 0HMBTA6D8LL1M:000001A7 [INF] CORS policy execution failed. (09b6f179) 2021-09-22T00:00:58.3960956+01:00 0HMBTA6D8LL1M:000001A7 [INF] Request origin "https://HOSTNAME.FQDN:4443" does not have permission to access the resource. (a03d560b) 2021-09-22T00:00:58.3970536+01:00 0HMBTA6D8LL1M:000001A7 [WRN] Error unprotecting the session cookie. (65f95c31) System.Security.Cryptography.CryptographicException: The key {b57fdfc9-9c9a-450c-a15d-f931ace1bfbc} was not found in the key ring. at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.DangerousUnprotect(Byte[] protectedData, Boolean ignoreRevocationErrors, Boolean& requiresMigration, Boolean& wasRevoked) at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData) at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger) 2021-09-22T00:00:58.4002762+01:00 0HMBTA6D8LL1M:000001A7 [INF] Authorization was successful. (0d575a54)

In the errors tab, I find the following:

at Lazy at n (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:846935) at Suspense at j (https://HOSTNAME.FQDN:4443/admin/static/js/main.71067197.chunk.js:1:798) at div at div at y (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:942610) at p (https://HOSTNAME.FQDN:4443/admin/static/js/33.c5554a52.chunk.js:1:6519) at div at https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:254851 at S (https://HOSTNAME.FQDN:4443/admin/static/js/34.23b1d4e3.chunk.js:1:1999) at div at https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:376561 at E (https://HOSTNAME.FQDN:4443/admin/static/js/34.23b1d4e3.chunk.js:1:1629) at n (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:846935) at Suspense at j (https://HOSTNAME.FQDN:4443/admin/static/js/main.71067197.chunk.js:1:798) at j (https://HOSTNAME.FQDN:4443/admin/static/js/34.23b1d4e3.chunk.js:1:1125) at k (https://HOSTNAME.FQDN:4443/admin/static/js/34.23b1d4e3.chunk.js:1:1303) at C (https://HOSTNAME.FQDN:4443/admin/static/js/33.c5554a52.chunk.js:1:8256) at d (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:24784) at h (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:25112) at p at d (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:24784) at h (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:25112) at n (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:846935) at Suspense at j (https://HOSTNAME.FQDN:4443/admin/static/js/main.71067197.chunk.js:1:798) at main at h (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208717) at o (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208547) at section at https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208977 at o (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208547) at div at div at t (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:731285) at X (https://HOSTNAME.FQDN:4443/admin/static/js/main.71067197.chunk.js:1:64830) at section at https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208977 at o (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208547) at section at https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208977 at o (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:208547) at Ut (https://HOSTNAME.FQDN:4443/admin/static/js/main.71067197.chunk.js:1:76051) at d (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:24784) at n (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:846935) at Suspense at j (https://HOSTNAME.FQDN:4443/admin/static/js/main.71067197.chunk.js:1:798) at p (https://HOSTNAME.FQDN:4443/admin/static/js/main.71067197.chunk.js:1:60082) at l (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:224269) at c (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:139287) at h (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:25112) at p (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:24849) at s (https://HOSTNAME.FQDN:4443/admin/static/js/20.601becba.chunk.js:2:59813) at Ht

[Jori]

Update, so I ran the job manually and noticed it worked when I told it to run as “Windows Powershell 5.1”…

I’ve since changed the schedule, but I think this is fixed now.