search

ironmansoftware / powershell-universal

Issue tracker for PowerShell Universal
https://powershelluniversal.com
38 stars 4 forks source link

admin/home throws errors #2575

Closed insomniacc closed 1 year ago

insomniacc commented 1 year ago

Version

4.0.7

Severity

Low

Steps to Reproduce

Tested on both V4.0.7 & V4.0.8 Login to the PSU admin page, once the home page attempts to load it throws an error and no other links work without refreshing the page acter clicking them.

Expected behavior

See the admin dashboard and summary cards

Actual behavior

See the below visuals for error.

Unable to spot anything obvious in the logs other than this:

2023-07-24 12:08:07.750 +01:00 [ERR] Error when dispatching 'OnConnectedAsync' on hub.
System.NullReferenceException: Object reference not set to an instance of an object.
   at UniversalDashboard.DashboardHub.OnConnectedAsync() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Hubs\DashboardHub.cs:line 52
   at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.OnConnectedAsync(HubConnectionContext connection)
   at Microsoft.AspNetCore.SignalR.Internal.DefaultHubDispatcher`1.OnConnectedAsync(HubConnectionContext connection)
   at Microsoft.AspNetCore.SignalR.HubConnectionHandler`1.RunHubAsync(HubConnectionContext connection)

Additional Environment data

Azure Web App, linux/docker. Storage account/file share mounted to /Data

Visuals

image

adamdriscoll commented 1 year ago

This issue has been mentioned on Ironman Software Forums. There might be relevant details there:

https://forums.ironmansoftware.com/t/admin-home-page-is-throwing-cannot-read-properties-of-undefined-4-0-8/9494/2

adamdriscoll commented 1 year ago

@insomniacc Can you press F12 in your browser and check the error stack trace there? I can't reproduce this at the moment and that should provide an unobfuscated stack trace.

insomniacc commented 1 year ago

image

insomniacc commented 1 year ago

Please let me know if there's anything else you need. I have completely wiped my web app and rebuilt with docker so it's nothing environment side causing this. The only thing I havent done is remove/recreate the database on my storage account which I can do if you think this might be worthwhile?

adamdriscoll commented 1 year ago

@insomniacc Do you have any other exceptions in your logs? I'm looking specifically for the HealthController. It's throwing a 500 (unhandled exception) that should be logged.

I've put a patch in to prevent the page from completely blowing up when this happens but the root cause is likely server based.

insomniacc commented 1 year ago

Unfortunately I don't have the logs any more, (they ended up getting purged amidst troubleshooting other issues) I loaded up the PSU admin page this morning and was presented with 'No authentication handler is registered for the scheme 'OpenIdConnect'.' No idea why, I checked both my git history for my repository and couldn't see any changes that would be relevant to the platform itself, only to the dashboard pages I was working on. I also looked at my terraform code and saw no relevant changes there. To troubleshoot I performed the following in order:

  1. restarted the web app, same issue
  2. deleted the web app and app serviceplan & rebuilt via terraform, same issue
  3. disabled OIDC in my web app env vars, used the login form to attempt a login, and was presented with a different red JS error stating something was unhandled/undefined (sorry I didnt capture this), completely unable to login
  4. Updated from 4.0.8 to 4.0.9, same issue
  5. Deleted the database file (I've made a point to avoid storing anything in the database and keep everything in the .universal settings or an external keyvault because I've found occasional issues that lead me to deleting this file) and restarted my web app, I was then able to login with default admin/admin and OIDC. No further errors.

Also on that note, since I've updated, I no longer get the admin home page error raised initially in this issue - I did notice the patch you made for this in 4.0.9 so thanks for that! I also did check my existing logs after a successful reboot and login, and cant see specifically 'HealthController' only 'HealthCheckController' with INF and DBG messages, no errors or 500's.

I did see this:

2023-07-31 10:50:22.582 +01:00 [ERR] An unhandled exception has occurred while executing the request.
System.InvalidOperationException: No authentication handler is registered for the scheme 'OpenIdConnect'. The registered schemes are: Identity.External, Cookies, Bearer, Deny. Did you forget to call AddAuthentication().Add[SomeAuthHandler]("OpenIdConnect",...)?
   at Microsoft.AspNetCore.Authentication.AuthenticationService.AuthenticateAsync(HttpContext context, String scheme)
   at Microsoft.AspNetCore.Authorization.Policy.PolicyEvaluator.AuthenticateAsync(AuthorizationPolicy policy, HttpContext context)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at PowerShellUniversal.PSUMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\PowerShellMiddleware.cs:line 43
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.FeatureMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\FeatureMiddleware.cs:line 42
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.DisallowedModeMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\ModeMiddleware.cs:line 46
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.CspMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\CspMiddleware.cs:line 20
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 201
   at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
   at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
   at Universal.Server.Middleware.SwaggerAuthenticationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 35
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at AspNetCoreRateLimit.RateLimitMiddleware`1.Invoke(HttpContext context) in C:\actions-runner\_work\universal\universal\src\AspNetCoreRateLimit\Middleware\RateLimitMiddleware.cs:line 109
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|8_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
2023-07-31 10:50:22.586 +01:00 [DBG] No response compression available for HTTPS requests. See ResponseCompressionOptions.EnableForHttps.

Portion relevant to HealthCheckController:

2023-07-31 10:52:58.084 +01:00 [DBG] The request path /api/v1/health/status does not match a supported file type
2023-07-31 10:52:58.091 +01:00 [DBG] The request path  does not match the path filter
2023-07-31 10:52:58.092 +01:00 [DBG] 1 candidate(s) found for the request path '/api/v1/health/status'
2023-07-31 10:52:58.092 +01:00 [DBG] Endpoint 'PowerShellUniversal.HealthCheckController.GetStatus (Universal.Server)' with route pattern 'api/v1/health/status' is valid for the request path '/api/v1/health/status'
2023-07-31 10:52:58.092 +01:00 [DBG] Request matched endpoint 'PowerShellUniversal.HealthCheckController.GetStatus (Universal.Server)'
2023-07-31 10:52:58.103 +01:00 [DBG] Authorization was successful.
2023-07-31 10:52:58.111 +01:00 [INF] Executing endpoint 'PowerShellUniversal.HealthCheckController.GetStatus (Universal.Server)'
2023-07-31 10:52:58.111 +01:00 [INF] Route matched with {action = "GetStatus", controller = "HealthCheck"}. Executing controller action with signature Microsoft.AspNetCore.Mvc.IActionResult GetStatus() on controller PowerShellUniversal.HealthCheckController (Universal.Server).
2023-07-31 10:52:58.111 +01:00 [DBG] Execution plan of authorization filters (in the following order): ["None"]
2023-07-31 10:52:58.112 +01:00 [DBG] Execution plan of resource filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"]
2023-07-31 10:52:58.112 +01:00 [DBG] Execution plan of action filters (in the following order): ["Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter (Order: -2147483648)","Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter (Order: -3000)"]
2023-07-31 10:52:58.112 +01:00 [DBG] Execution plan of exception filters (in the following order): ["None"]
2023-07-31 10:52:58.112 +01:00 [DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"]
2023-07-31 10:52:58.133 +01:00 [VRB] Resource Filter: Before executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
2023-07-31 10:52:58.134 +01:00 [VRB] Resource Filter: After executing OnResourceExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
2023-07-31 10:52:58.134 +01:00 [DBG] Executing controller factory for controller PowerShellUniversal.HealthCheckController (Universal.Server)
2023-07-31 10:52:58.141 +01:00 [DBG] Executed controller factory for controller PowerShellUniversal.HealthCheckController (Universal.Server)
2023-07-31 10:52:58.141 +01:00 [VRB] Action Filter: Before executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter.
2023-07-31 10:52:58.141 +01:00 [VRB] Action Filter: Before executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
2023-07-31 10:52:58.142 +01:00 [VRB] Action Filter: After executing OnActionExecuting on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
2023-07-31 10:52:58.142 +01:00 [INF] Executing action method PowerShellUniversal.HealthCheckController.GetStatus (Universal.Server) - Validation state: "Valid"
2023-07-31 10:52:58.142 +01:00 [INF] Executed action method PowerShellUniversal.HealthCheckController.GetStatus (Universal.Server), returned result Microsoft.AspNetCore.Mvc.OkObjectResult in 0.3651ms.
2023-07-31 10:52:58.142 +01:00 [VRB] Action Filter: Before executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
2023-07-31 10:52:58.142 +01:00 [VRB] Action Filter: After executing OnActionExecuted on filter Microsoft.AspNetCore.Mvc.ModelBinding.UnsupportedContentTypeFilter.
2023-07-31 10:52:58.142 +01:00 [VRB] Action Filter: After executing OnActionExecutionAsync on filter Microsoft.AspNetCore.Mvc.Filters.ControllerActionFilter.
2023-07-31 10:52:58.143 +01:00 [VRB] Result Filter: Before executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
2023-07-31 10:52:58.150 +01:00 [VRB] Result Filter: After executing OnResultExecuting on filter Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter.
2023-07-31 10:52:58.150 +01:00 [VRB] Before executing action result Microsoft.AspNetCore.Mvc.OkObjectResult.
2023-07-31 10:52:58.150 +01:00 [DBG] List of registered output formatters, in the following order: ["Microsoft.AspNetCore.Mvc.Formatters.HttpNoContentOutputFormatter","Microsoft.AspNetCore.Mvc.Formatters.StringOutputFormatter","Microsoft.AspNetCore.Mvc.Formatters.StreamOutputFormatter","Microsoft.AspNetCore.Mvc.Formatters.NewtonsoftJsonOutputFormatter"]
2023-07-31 10:52:58.151 +01:00 [DBG] No information found on request to perform content negotiation.
2023-07-31 10:52:58.151 +01:00 [DBG] Attempting to select an output formatter without using a content type as no explicit content types were specified for the response.
2023-07-31 10:52:58.151 +01:00 [DBG] Attempting to select the first formatter in the output formatters list which can write the result.
2023-07-31 10:52:58.151 +01:00 [DBG] Selected output formatter 'Microsoft.AspNetCore.Mvc.Formatters.NewtonsoftJsonOutputFormatter' and content type 'application/json' to write the response.
insomniacc commented 1 year ago

After all the above, getting it working, testing a web app restart, I logged in again this morning and saw the same issue. No authentication handler is registered for the scheme 'OpenIdConnect'. The registered schemes are: Identity.External, Cookies, Bearer, Deny. Did you forget to call AddAuthentication().Add[SomeAuthHandler]("OpenIdConnect",...)? I've no idea what's causing this.

insomniacc commented 1 year ago

It seems I cant even get to the login page either. no form is shown, just this: image I'll take a look at the logs now and report back

insomniacc commented 1 year ago

Seeing this repeating in the logs:

2023-08-01 00:00:01.707 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:01.782 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:05.092 +01:00 [VRB] Recurring job 'ROCKPSU.ProcessMonitor' is being updated. RecurringJob: (Queue:rockpsu;Cron:* * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.JobProcessManager, Universal.Server","m":"MonitorProcesses"};CreatedAt:1690810163396;NextExecution:1690844400000;V:2;LastExecution:1690844345083;LastJobId:b2175de5-6aaa-4d52-8927-5b902e89e355), Changes: (LastExecution:1690844405092;NextExecution:1690844460000;LastJobId:ec44e070-ecb3-46f5-8de7-b751eff6d2f5), NextExecution: (7/31/2023 11:01:00 PM)
2023-08-01 00:00:05.093 +01:00 [VRB] Recurring job 'AppTokenRefresh.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:* * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.Common.Interfaces.IAppTokenService, PowerShellUniversal","m":"Load"};CreatedAt:1690810176047;NextExecution:1690844400000;V:2;LastExecution:1690844345083;LastJobId:407085c0-2655-4fe1-9277-75d976fd81cc), Changes: (LastExecution:1690844405092;NextExecution:1690844460000;LastJobId:17b2919c-46f8-417b-8fd4-088d7911a107), NextExecution: (7/31/2023 11:01:00 PM)
2023-08-01 00:00:05.093 +01:00 [VRB] Recurring job 'GitSync.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:*/1 * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.IGitSyncService, PowerShellUniversal","m":"Sync","p":["System.Boolean"],"a":["false"]};CreatedAt:1690810176394;NextExecution:1690844400000;V:2;LastExecution:1690844345083;LastJobId:5f1d7a51-e4e9-4155-96f7-d298f07333a5), Changes: (LastExecution:1690844405092;NextExecution:1690844460000;LastJobId:af6794c3-51a3-495a-8a2c-0f76dae5a183), NextExecution: (7/31/2023 11:01:00 PM)
2023-08-01 00:00:05.094 +01:00 [VRB] Recurring job 'Heartbeat.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:*/1 * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.HeartBeatService, Universal.Server","m":"Run"};CreatedAt:1690810176401;NextExecution:1690844400000;V:2;LastExecution:1690844345083;LastJobId:b38848a2-b967-49b4-9394-be262ad9c576), Changes: (LastExecution:1690844405092;NextExecution:1690844460000;LastJobId:b2b5fa7b-28fc-4038-8ccb-5101e729d5fe), NextExecution: (7/31/2023 11:01:00 PM)
2023-08-01 00:00:05.095 +01:00 [INF] Starting heartbeat job.
2023-08-01 00:00:05.095 +01:00 [DBG] Git sync is not enabled.
2023-08-01 00:00:05.149 +01:00 [VRB] Recurring job 'HealthCheck.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:*/59 * * * *;TimeZoneId:UTC;Job:{"t":"PowerShellUniversal.IHealthCheckService, PowerShellUniversal","m":"RunChecks"};CreatedAt:1690810176402;NextExecution:1690844400000;V:2;LastExecution:1690844345083;LastJobId:9a40c740-7978-4e98-b658-90e177d4b743), Changes: (LastExecution:1690844405092;NextExecution:1690847940000;LastJobId:ff8808e1-e593-4443-9c74-8987684670a8), NextExecution: (7/31/2023 11:59:00 PM)
2023-08-01 00:00:05.154 +01:00 [INF] Finished heartbeat job.
2023-08-01 00:00:05.154 +01:00 [INF] Running health check: Memory Utilization
2023-08-01 00:00:05.156 +01:00 [VRB] Recurring job 'IUpdateCheckService.CheckForUpdates' is being updated. RecurringJob: (Queue:default;Cron:*/59 * * * *;TimeZoneId:UTC;Job:{"t":"PowerShellUniversal.IUpdateCheckService, PowerShellUniversal","m":"CheckForUpdates"};CreatedAt:1690810176411;NextExecution:1690844400000;V:2;LastExecution:1690844345083;LastJobId:1f1961c4-8de1-4361-b51d-af07387c09cc), Changes: (LastExecution:1690844405092;NextExecution:1690847940000;LastJobId:125512bf-111d-4b21-8eed-0d2f76502148), NextExecution: (7/31/2023 11:59:00 PM)
2023-08-01 00:00:05.163 +01:00 [VRB] Recurring job 'ModuleRefresh.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:*/15 * * * *;TimeZoneId:UTC;Job:{"t":"PowerShellUniversal.IModuleService, PowerShellUniversal","m":"DiscoverModules"};CreatedAt:1690810176412;NextExecution:1690844400000;V:2;LastExecution:1690843504903;LastJobId:823a4be2-0c4a-4a71-b211-6e6f729bf4f5), Changes: (LastExecution:1690844405092;NextExecution:1690845300000;LastJobId:ff1fd346-aed0-47ef-a0fd-91ecb67fae9c), NextExecution: (7/31/2023 11:15:00 PM)
2023-08-01 00:00:05.164 +01:00 [DBG] 7 recurring job(s) processed by scheduler.
2023-08-01 00:00:05.213 +01:00 [WRN] Failed to process the job 'ff8808e1-e593-4443-9c74-8987684670a8': an exception occured. Job was automatically deleted because the retry attempt count exceeded 0.
System.IO.FileNotFoundException: Could not find file '/Data/Database-log.db'.
File name: '/Data/Database-log.db'
   at Interop.ThrowExceptionForIoErrno(ErrorInfo errorInfo, String path, Boolean isDirError)
   at Microsoft.Win32.SafeHandles.SafeFileHandle.Open(String fullPath, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, UnixFileMode openPermissions, Int64& fileLength, UnixFileMode& filePermissions, Func`4 createOpenException)
   at System.IO.Strategies.OSFileStreamStrategy..ctor(String path, FileMode mode, FileAccess access, FileShare share, FileOptions options, Int64 preallocationSize, Nullable`1 unixCreateMode)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options, Int64 preallocationSize)
   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)
   at LiteDB.Engine.FileStreamFactory.GetStream(Boolean canWrite, Boolean sequencial)
   at LiteDB.Engine.StreamPool.Rent()
   at LiteDB.Engine.DiskReader.<.ctor>b__5_1()
   at System.Lazy`1.ViaFactory(LazyThreadSafetyMode mode)
   at System.Lazy`1.ExecutionAndPublication(LazyHelper executionAndPublication, Boolean useDefaultConstructor)
   at System.Lazy`1.CreateValue()
   at LiteDB.Engine.DiskReader.ReadPage(Int64 position, Boolean writable, FileOrigin origin)
   at LiteDB.Engine.Snapshot.ReadPage[T](UInt32 pageID, FileOrigin& origin, Int64& position, Int32& walVersion)
   at LiteDB.Engine.Snapshot.GetPage[T](UInt32 pageID, FileOrigin& origin, Int64& position, Int32& walVersion)
   at LiteDB.Engine.Snapshot..ctor(LockMode mode, String collectionName, HeaderPage header, UInt32 transactionID, TransactionPages transPages, LockService locker, WalIndexService walIndex, DiskReader reader, Boolean addIfNotExists)
   at LiteDB.Engine.TransactionService.CreateSnapshot(LockMode mode, String collection, Boolean addIfNotExists)
   at LiteDB.Engine.QueryExecutor.<>c__DisplayClass10_0.<<ExecuteQuery>g__RunQuery|0>d.MoveNext()
   at LiteDB.Engine.QueryExecutor.ExecuteQuery(Boolean executionPlan)
   at LiteDB.Engine.LiteEngine.Query(String collection, Query query)
   at LiteDB.LiteQueryable`1.ToDocuments()+MoveNext()
   at System.Linq.Enumerable.SelectEnumerableIterator`2.MoveNext()
   at System.Linq.Enumerable.TryGetFirst[TSource](IEnumerable`1 source, Boolean& found)
   at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source)
   at PowerShellUniversal.HealthCheckService.RunChecks() in C:\actions-runner\_work\universal\universal\src\Universal.Server\Services\Health\HealthCheckService.cs:line 64
   at InvokeStub_IHealthCheckService.RunChecks(Object, Object, IntPtr*)
   at System.Reflection.MethodInvoker.Invoke(Object obj, IntPtr* args, BindingFlags invokeAttr)
2023-08-01 00:00:06.783 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:06.783 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:11.783 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:11.783 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:16.783 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:16.783 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:21.784 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:21.784 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:26.784 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:26.784 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:28.417 +01:00 [DBG] Server lw1mdlwk00012p:1:3b96fa0f heartbeat successfully sent
2023-08-01 00:00:28.417 +01:00 [VRB] Server lw1mdlwk00012p:1:3b96fa0f waiting for 00:00:30 delay before sending a heartbeat
2023-08-01 00:00:31.784 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:31.784 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:36.785 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:36.785 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:41.785 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:41.785 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:46.785 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:46.785 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:51.785 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:51.786 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:56.059 +01:00 [DBG] Connection id "0HMSHP8L52NTP" received FIN.
2023-08-01 00:00:56.059 +01:00 [DBG] Connection id "0HMSHP8L52NTP" disconnecting.
2023-08-01 00:00:56.059 +01:00 [DBG] Connection id "0HMSHP8L52NTP" stopped.
2023-08-01 00:00:56.059 +01:00 [DBG] Connection id "0HMSHP8L52NTP" sending FIN because: "The Socket transport's send loop completed gracefully."
2023-08-01 00:00:56.786 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:00:56.786 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:00:58.418 +01:00 [DBG] Server lw1mdlwk00012p:1:3b96fa0f heartbeat successfully sent
2023-08-01 00:00:58.418 +01:00 [VRB] Server lw1mdlwk00012p:1:3b96fa0f waiting for 00:00:30 delay before sending a heartbeat
2023-08-01 00:01:01.786 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 00:01:01.786 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 00:01:05.166 +01:00 [VRB] Recurring job 'ROCKPSU.ProcessMonitor' is being updated. RecurringJob: (Queue:rockpsu;Cron:* * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.JobProcessManager, Universal.Server","m":"MonitorProcesses"};CreatedAt:1690810163396;NextExecution:1690844460000;V:2;LastExecution:1690844405092;LastJobId:ec44e070-ecb3-46f5-8de7-b751eff6d2f5), Changes: (LastExecution:1690844465165;NextExecution:1690844520000;LastJobId:75659ba2-7a62-4a10-be1b-100f0838301e), NextExecution: (7/31/2023 11:02:00 PM)
2023-08-01 00:01:05.166 +01:00 [VRB] Recurring job 'AppTokenRefresh.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:* * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.Common.Interfaces.IAppTokenService, PowerShellUniversal","m":"Load"};CreatedAt:1690810176047;NextExecution:1690844460000;V:2;LastExecution:1690844405092;LastJobId:17b2919c-46f8-417b-8fd4-088d7911a107), Changes: (LastExecution:1690844465165;NextExecution:1690844520000;LastJobId:db5ae992-6fc0-4fbc-a009-d2181c8136cf), NextExecution: (7/31/2023 11:02:00 PM)
2023-08-01 00:01:05.167 +01:00 [VRB] Recurring job 'GitSync.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:*/1 * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.IGitSyncService, PowerShellUniversal","m":"Sync","p":["System.Boolean"],"a":["false"]};CreatedAt:1690810176394;NextExecution:1690844460000;V:2;LastExecution:1690844405092;LastJobId:af6794c3-51a3-495a-8a2c-0f76dae5a183), Changes: (LastExecution:1690844465165;NextExecution:1690844520000;LastJobId:6039f9ae-2083-431e-a887-8c0a40947035), NextExecution: (7/31/2023 11:02:00 PM)
2023-08-01 00:01:05.168 +01:00 [VRB] Recurring job 'Heartbeat.ROCKPSU' is being updated. RecurringJob: (Queue:rockpsu;Cron:*/1 * * * *;TimeZoneId:UTC;Job:{"t":"UniversalAutomation.HeartBeatService, Universal.Server","m":"Run"};CreatedAt:1690810176401;NextExecution:1690844460000;V:2;LastExecution:1690844405092;LastJobId:b2b5fa7b-28fc-4038-8ccb-5101e729d5fe), Changes: (LastExecution:1690844465165;NextExecution:1690844520000;LastJobId:411e87d0-1252-49e9-8251-947a7d2f9444), NextExecution: (7/31/2023 11:02:00 PM)

Also seeing this:

2023-08-01 10:48:48.060 +01:00 [INF] Request starting HTTP/1.1 GET http://<url>.azurewebsites.net/api/v1/identity/my - -
2023-08-01 10:48:48.060 +01:00 [VRB] All hosts are allowed.
2023-08-01 10:48:48.060 +01:00 [VRB] Performing unprotect operation to key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} with purposes ('/home/', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Cookies', 'v2').
2023-08-01 10:48:48.060 +01:00 [VRB] Key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} was not found in the key ring. Unprotect operation cannot proceed.
2023-08-01 10:48:48.060 +01:00 [INF] Cookies was not authenticated. Failure message: Unprotect ticket failed
2023-08-01 10:48:48.061 +01:00 [VRB] This request accepts compression.
2023-08-01 10:48:48.061 +01:00 [VRB] Performing unprotect operation to key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} with purposes ('/home/', 'SessionMiddleware').
2023-08-01 10:48:48.061 +01:00 [VRB] Key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} was not found in the key ring. Unprotect operation cannot proceed.
2023-08-01 10:48:48.061 +01:00 [WRN] Error unprotecting the session cookie.
System.Security.Cryptography.CryptographicException: The key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} was not found in the key ring. For more information go to http://aka.ms/dataprotectionwarning
   at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status)
   at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData)
   at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger)
2023-08-01 10:48:48.061 +01:00 [VRB] Performing protect operation to key {d373bbd1-20d1-4aea-86ab-2838b3d1775f} with purposes ('/home/', 'SessionMiddleware').
2023-08-01 10:48:48.062 +01:00 [DBG] The request path /api/v1/identity/my does not match a supported file type
2023-08-01 10:48:48.062 +01:00 [DBG] The request path  does not match the path filter
2023-08-01 10:48:48.062 +01:00 [DBG] 2 candidate(s) found for the request path '/api/v1/identity/my'
2023-08-01 10:48:48.062 +01:00 [DBG] Endpoint 'UniversalAutomation.IdentityController.My (Universal.Server)' with route pattern 'api/v1/identity/my' is valid for the request path '/api/v1/identity/my'
2023-08-01 10:48:48.062 +01:00 [DBG] Endpoint 'UniversalAutomation.IdentityController.Get (Universal.Server)' with route pattern 'api/v1/identity/{name}' is valid for the request path '/api/v1/identity/my'
2023-08-01 10:48:48.062 +01:00 [DBG] Request matched endpoint 'UniversalAutomation.IdentityController.My (Universal.Server)'
2023-08-01 10:48:48.090 +01:00 [INF] Cookies was not authenticated. Failure message: Unprotect ticket failed
2023-08-01 10:48:48.090 +01:00 [DBG] AuthenticationScheme: Bearer was not authenticated.
2023-08-01 10:48:48.091 +01:00 [ERR] An unhandled exception has occurred while executing the request.
System.InvalidOperationException: No authentication handler is registered for the scheme 'OpenIdConnect'. The registered schemes are: Identity.External, Cookies, Bearer, Deny. Did you forget to call AddAuthentication().Add[SomeAuthHandler]("OpenIdConnect",...)?
   at Microsoft.AspNetCore.Authentication.AuthenticationService.AuthenticateAsync(HttpContext context, String scheme)
   at Microsoft.AspNetCore.Authorization.Policy.PolicyEvaluator.AuthenticateAsync(AuthorizationPolicy policy, HttpContext context)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at PowerShellUniversal.PSUMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\PowerShellMiddleware.cs:line 44
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.FeatureMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\FeatureMiddleware.cs:line 43
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.DisallowedModeMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\ModeMiddleware.cs:line 47
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.CspMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\CspMiddleware.cs:line 21
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 202
   at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
   at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
   at Universal.Server.Middleware.SwaggerAuthenticationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 37
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at AspNetCoreRateLimit.RateLimitMiddleware`1.Invoke(HttpContext context) in C:\actions-runner\_work\universal\universal\src\AspNetCoreRateLimit\Middleware\RateLimitMiddleware.cs:line 110
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|8_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
2023-08-01 10:48:48.099 +01:00 [DBG] No response compression available for HTTPS requests. See ResponseCompressionOptions.EnableForHttps.
2023-08-01 10:48:48.099 +01:00 [DBG] Connection id "0HMSHP8L52O23" completed keep alive response.
2023-08-01 10:48:48.099 +01:00 [INF] Request finished HTTP/1.1 GET http://<url>.azurewebsites.net/api/v1/identity/my - - - 500 - text/plain 39.5811ms
2023-08-01 10:48:48.393 +01:00 [VRB] Checking for aborted jobs...
2023-08-01 10:48:48.393 +01:00 [VRB] No newly aborted jobs found.
2023-08-01 10:48:49.132 +01:00 [INF] Request starting HTTP/1.1 GET http://<url>.azurewebsites.net/api/v1/identity/my - -
2023-08-01 10:48:49.132 +01:00 [VRB] All hosts are allowed.
2023-08-01 10:48:49.132 +01:00 [VRB] Performing unprotect operation to key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} with purposes ('/home/', 'Microsoft.AspNetCore.Authentication.Cookies.CookieAuthenticationMiddleware', 'Cookies', 'v2').
2023-08-01 10:48:49.132 +01:00 [VRB] Key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} was not found in the key ring. Unprotect operation cannot proceed.
2023-08-01 10:48:49.133 +01:00 [INF] Cookies was not authenticated. Failure message: Unprotect ticket failed
2023-08-01 10:48:49.133 +01:00 [VRB] This request accepts compression.
2023-08-01 10:48:49.133 +01:00 [VRB] Performing unprotect operation to key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} with purposes ('/home/', 'SessionMiddleware').
2023-08-01 10:48:49.133 +01:00 [VRB] Key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} was not found in the key ring. Unprotect operation cannot proceed.
2023-08-01 10:48:49.133 +01:00 [WRN] Error unprotecting the session cookie.
System.Security.Cryptography.CryptographicException: The key {4e8fd50b-63f3-4a14-9c42-7b5f234988d6} was not found in the key ring. For more information go to http://aka.ms/dataprotectionwarning
   at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.UnprotectCore(Byte[] protectedData, Boolean allowOperationsOnRevokedKeys, UnprotectStatus& status)
   at Microsoft.AspNetCore.DataProtection.KeyManagement.KeyRingBasedDataProtector.Unprotect(Byte[] protectedData)
   at Microsoft.AspNetCore.Session.CookieProtection.Unprotect(IDataProtector protector, String protectedText, ILogger logger)
2023-08-01 10:48:49.133 +01:00 [VRB] Performing protect operation to key {d373bbd1-20d1-4aea-86ab-2838b3d1775f} with purposes ('/home/', 'SessionMiddleware').
2023-08-01 10:48:49.133 +01:00 [DBG] The request path /api/v1/identity/my does not match a supported file type
2023-08-01 10:48:49.133 +01:00 [DBG] The request path  does not match the path filter
2023-08-01 10:48:49.133 +01:00 [DBG] 2 candidate(s) found for the request path '/api/v1/identity/my'
2023-08-01 10:48:49.133 +01:00 [DBG] Endpoint 'UniversalAutomation.IdentityController.My (Universal.Server)' with route pattern 'api/v1/identity/my' is valid for the request path '/api/v1/identity/my'
2023-08-01 10:48:49.133 +01:00 [DBG] Endpoint 'UniversalAutomation.IdentityController.Get (Universal.Server)' with route pattern 'api/v1/identity/{name}' is valid for the request path '/api/v1/identity/my'
2023-08-01 10:48:49.134 +01:00 [DBG] Request matched endpoint 'UniversalAutomation.IdentityController.My (Universal.Server)'
2023-08-01 10:48:49.140 +01:00 [INF] Cookies was not authenticated. Failure message: Unprotect ticket failed
2023-08-01 10:48:49.146 +01:00 [DBG] AuthenticationScheme: Bearer was not authenticated.
2023-08-01 10:48:49.147 +01:00 [ERR] An unhandled exception has occurred while executing the request.
System.InvalidOperationException: No authentication handler is registered for the scheme 'OpenIdConnect'. The registered schemes are: Identity.External, Cookies, Bearer, Deny. Did you forget to call AddAuthentication().Add[SomeAuthHandler]("OpenIdConnect",...)?
   at Microsoft.AspNetCore.Authentication.AuthenticationService.AuthenticateAsync(HttpContext context, String scheme)
   at Microsoft.AspNetCore.Authorization.Policy.PolicyEvaluator.AuthenticateAsync(AuthorizationPolicy policy, HttpContext context)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at PowerShellUniversal.PSUMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\PowerShellMiddleware.cs:line 44
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.FeatureMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\FeatureMiddleware.cs:line 43
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.DisallowedModeMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\ModeMiddleware.cs:line 47
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at PowerShellUniversal.CspMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\CspMiddleware.cs:line 21
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 202
   at Swashbuckle.AspNetCore.SwaggerUI.SwaggerUIMiddleware.Invoke(HttpContext httpContext)
   at Swashbuckle.AspNetCore.Swagger.SwaggerMiddleware.Invoke(HttpContext httpContext, ISwaggerProvider swaggerProvider)
   at Universal.Server.Middleware.SwaggerAuthenticationMiddleware.InvokeAsync(HttpContext context, RequestDelegate next) in C:\actions-runner\_work\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 37
   at Microsoft.AspNetCore.Builder.UseMiddlewareExtensions.<>c__DisplayClass6_1.<<UseMiddlewareInterface>b__1>d.MoveNext()
--- End of stack trace from previous location ---
   at AspNetCoreRateLimit.RateLimitMiddleware`1.Invoke(HttpContext context) in C:\actions-runner\_work\universal\universal\src\AspNetCoreRateLimit\Middleware\RateLimitMiddleware.cs:line 110
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Session.SessionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddlewareImpl.<Invoke>g__Awaited|8_0(ExceptionHandlerMiddlewareImpl middleware, HttpContext context, Task task)
2023-08-01 10:48:49.148 +01:00 [DBG] No response compression available for HTTPS requests. See ResponseCompressionOptions.EnableForHttps.
2023-08-01 10:48:49.148 +01:00 [DBG] Connection id "0HMSHP8L52O23" completed keep alive response.
2023-08-01 10:48:49.148 +01:00 [INF] Request finished HTTP/1.1 GET http://<url>.azurewebsites.net/api/v1/identity/my - - - 500 - text/plain 15.7574ms
insomniacc commented 1 year ago

Just rebooted the web app and it looks like in this case it's resolved the issue. I do have a nightly reboot of the web app scheduled so it seems it broke at that point, but another reboot cleared whatever was causing the problem.

insomniacc commented 1 year ago

Sorry, I sort of hijacked this thread with a separate issue, I'm pretty confident the initial issue I raised has been resolved in the last update though, I've had no problem with it since.

adamdriscoll commented 1 year ago

@insomniacc I'll close this one but can you just open a support case for the other stuff? I'm not sure what's going on but it certainly seems like something really fundamental is broken and cascading into a bunch of errors.