Logins fail until service is restarted

davmurfy · July 6, 2021, 9:31pm

We have been having an issue where authentication starts failing at some point until the service is restarted on the server. Then it will continue to work for several hours or all day. I have been unable to identify what exactly is causing the interruption, but restarting the service always resolves it.

I haven’t found anything in the logs to indicate when it starts, but I do have some from when the logins succeed after service restart, and when it fails before the restart.

When it succeeds I see the following:
2021-07-06T16:02:04.7468186-05:00 0HMA0MMBKF1UK:00000007 [INF] Executing endpoint ‘“UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)”’ (500cc934)
2021-07-06T16:02:04.7470125-05:00 0HMA0MMBKF1UK:00000007 [INF] Route matched with “{action = “SignIn”, controller = “Authentication”}”. Executing controller action with signature “System.Threading.Tasks.Task1[Microsoft.AspNetCore.Mvc.IActionResult] SignIn(UniversalDashboard.Controllers.Credential)" on controller "UniversalDashboard.Controllers.AuthenticationController" ("Universal.Server"). (122b2fdf) 2021-07-06T16:02:05.6797867-05:00 0HMA0MMBKF1UK:00000007 [INF] Evaluting claims for Admin (c41c449e) 2021-07-06T16:02:05.6808367-05:00 0HMA0MMBKF1UK:00000007 [INF] AuthenticationScheme: "Cookies" signed in. (c66dd7e7) 2021-07-06T16:02:05.6811718-05:00 0HMA0MMBKF1UK:00000007 [INF] Executing JsonResult, writing value of type '"<>f__AnonymousType11[[Microsoft.Extensions.Primitives.StringValues, Microsoft.Extensions.Primitives, Version=3.1.8.0, Culture=neutral, PublicKeyToken=adb9793829ddae60]]”’. (2f513669)
2021-07-06T16:02:05.6843863-05:00 0HMA0MMBKF1UK:00000007 [INF] Executed action “UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)” in 937.3336ms (afa2e885)
2021-07-06T16:02:05.6844191-05:00 0HMA0MMBKF1UK:00000007 [INF] Executed endpoint ‘“UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)”’ (99874f2b)
2021-07-06T16:02:05.6845571-05:00 0HMA0MMBKF1UK:00000007 [INF] Request finished in 939.502ms 200 application/json; charset=utf-8 (791a596a)
2021-07-06T16:02:05.7294411-05:00 0HMA0MMBKF1UK:00000008 [INF] Request starting HTTP/1.1 GET http://server:5000/admin (ca22a1cb)
2021-07-06T16:02:05.7308255-05:00 0HMA0MMBKF1UK:00000008 [INF] /admin (00e9b4ee)

When it fails I see this:
2021-07-06T14:35:16.8795411-05:00 0HMA0FL3KLMD8:00000003 [INF] Executing endpoint ‘“UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)”’ (500cc934)
2021-07-06T14:35:16.8796291-05:00 0HMA0FL3KLMD8:00000003 [INF] Route matched with “{action = “SignIn”, controller = “Authentication”}”. Executing controller action with signature “System.Threading.Tasks.Task1[Microsoft.AspNetCore.Mvc.IActionResult] SignIn(UniversalDashboard.Controllers.Credential)" on controller "UniversalDashboard.Controllers.AuthenticationController" ("Universal.Server"). (122b2fdf) 2021-07-06T14:35:17.0486023-05:00 0HMA0FL3KLMD8:00000003 [INF] Executing JsonResult, writing value of type '"<>f__AnonymousType01[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]”’. (2f513669)
2021-07-06T14:35:17.0488378-05:00 0HMA0FL3KLMD8:00000003 [INF] Executed action “UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)” in 169.1818ms (afa2e885)
2021-07-06T14:35:17.0488613-05:00 0HMA0FL3KLMD8:00000003 [INF] Executed endpoint ‘“UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)”’ (99874f2b)
2021-07-06T14:35:17.0489149-05:00 0HMA0FL3KLMD8:00000003 [INF] Request finished in 170.7855ms 200 application/json; charset=utf-8 (791a596a)

So it seems to work differently when it gets to this line, but I don’t know what may cause it.
2021-07-06T14:35:17.0486023-05:00 0HMA0FL3KLMD8:00000003 [INF] Executing JsonResult, writing value of type ‘"<>f__AnonymousType0`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]"’. (2f513669)

Any help getting pointed in the right direction would be appreciated.

Product: PowerShell Universal
Version: 1.5.17

adam · July 6, 2021, 9:44pm

Can you check the memory and CPU usage around this time? I’m just wondering if that’s a factor.

It looks like it looks like it’s evaluating claims in the successful execution and not in the unsuccessful one.

2021-07-06T16:02:05.6797867-05:00 0HMA0MMBKF1UK:00000007 [INF] Evaluting claims for Admin (c41c449e)

davmurfy · July 7, 2021, 1:32pm

It was happening again this morning. It was at around 4% cpu and 45% memory, which this machine is usually at.

Between when it was working yesterday and this morning I only see one part in the logs other than starting and finishing groom jobs.

2021-07-07T00:03:15.6666478-05:00 0HMA0MMBKF1UT:00000001 [INF] Request starting HTTP/1.0 GET http:///   (ca22a1cb)
2021-07-07T00:03:15.6708266-05:00 0HMA0MMBKF1UT:00000001 [INF] Executing ChallengeResult with authentication schemes ([]). (f3dca807)
2021-07-07T00:03:15.6710484-05:00 0HMA0MMBKF1UT:00000001 [INF] AuthenticationScheme: "Cookies" was challenged. (d45f1f38)
2021-07-07T00:03:15.6711237-05:00 0HMA0MMBKF1UT:00000001 [INF] Request finished in 4.5061ms 302  (791a596a)
2021-07-07T00:03:30.6891323-05:00 0HMA0MMBKF1V2:00000001 [INF] Request starting HTTP/1.0 OPTIONS http:///   (ca22a1cb)
2021-07-07T00:03:30.6910021-05:00 0HMA0MMBKF1V2:00000001 [INF] Executing ChallengeResult with authentication schemes ([]). (f3dca807)
2021-07-07T00:03:30.6911459-05:00 0HMA0MMBKF1V2:00000001 [INF] AuthenticationScheme: "Cookies" was challenged. (d45f1f38)
2021-07-07T00:03:30.6912000-05:00 0HMA0MMBKF1V2:00000001 [INF] Request finished in 2.0888ms 302  (791a596a)
2021-07-07T00:03:45.7155874-05:00 0HMA0MMBKF1VA:00000001 [INF] Request starting HTTP/1.0 GET http:///nice ports,/Trinity.txt.bak   (ca22a1cb)
2021-07-07T00:03:45.7185077-05:00 0HMA0MMBKF1VA:00000001 [INF] Request finished in 2.9287ms 404  (791a596a)

Then when the login page is loaded:

2021-07-07T07:59:42.1761958-05:00 0HMA0MMBKF1VT:00000001 [INF] Request starting HTTP/1.1 GET http://server:5000/login   (ca22a1cb)
2021-07-07T07:59:42.1776717-05:00 0HMA0MMBKF1VT:00000001 [INF] /login (68a5683a)
2021-07-07T07:59:42.2084315-05:00 0HMA0MMBKF1VT:00000001 [INF] Request finished in 32.2496ms 200 text/html (791a596a)
2021-07-07T07:59:42.3735434-05:00 0HMA0MMBKF1VT:00000002 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/loginPage   (ca22a1cb)
2021-07-07T07:59:42.3749802-05:00 0HMA0MMBKF1VT:00000002 [INF] Executing endpoint '"UniversalAutomation.LoginPageController.Get (UniversalAutomation)"' (500cc934)
2021-07-07T07:59:42.3750945-05:00 0HMA0MMBKF1VT:00000002 [INF] Route matched with "{action = \"Get\", controller = \"LoginPage\"}". Executing controller action with signature "UniversalAutomation.LoginPage Get()" on controller "UniversalAutomation.LoginPageController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T07:59:42.4829581-05:00 0HMA0MMBKF1VT:00000002 [INF] Executing ObjectResult, writing value of type '"null"'. (8a1b66c8)
2021-07-07T07:59:42.4830496-05:00 0HMA0MMBKF1VT:00000002 [INF] Executed action "UniversalAutomation.LoginPageController.Get (UniversalAutomation)" in 107.9276ms (afa2e885)
2021-07-07T07:59:42.4830649-05:00 0HMA0MMBKF1VT:00000002 [INF] Executed endpoint '"UniversalAutomation.LoginPageController.Get (UniversalAutomation)"' (99874f2b)
2021-07-07T07:59:42.4831284-05:00 0HMA0MMBKF1VT:00000002 [INF] Request finished in 109.6092ms 204  (791a596a)

Then when the login is attempted and fails:

2021-07-07T08:02:08.9143833-05:00 0HMA0MMBKF1VV:00000001 [INF] Request starting HTTP/1.1 POST http://server:5000/api/v1/signin application/json 71 (ca22a1cb)
2021-07-07T08:02:08.9145835-05:00 0HMA0MMBKF1VV:00000001 [INF] CORS policy execution failed. (09b6f179)
2021-07-07T08:02:08.9146075-05:00 0HMA0MMBKF1VV:00000001 [INF] Request origin "http://server:5000" does not have permission to access the resource. (a03d560b)
2021-07-07T08:02:08.9161164-05:00 0HMA0MMBKF1VV:00000001 [INF] Executing endpoint '"UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)"' (500cc934)
2021-07-07T08:02:08.9162264-05:00 0HMA0MMBKF1VV:00000001 [INF] Route matched with "{action = \"SignIn\", controller = \"Authentication\"}". Executing controller action with signature "System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] SignIn(UniversalDashboard.Controllers.Credential)" on controller "UniversalDashboard.Controllers.AuthenticationController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:02:09.5062985-05:00 0HMA0MMBKF1VV:00000001 [INF] Executing JsonResult, writing value of type '"<>f__AnonymousType0`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]"'. (2f513669)
2021-07-07T08:02:09.5076380-05:00 0HMA0MMBKF1VV:00000001 [INF] Executed action "UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)" in 591.378ms (afa2e885)
2021-07-07T08:02:09.5076679-05:00 0HMA0MMBKF1VV:00000001 [INF] Executed endpoint '"UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)"' (99874f2b)
2021-07-07T08:02:09.5077377-05:00 0HMA0MMBKF1VV:00000001 [INF] Request finished in 593.3897ms 200 application/json; charset=utf-8 (791a596a)

I restarted the service:

2021-07-07T08:05:12.0984870-05:00  [INF] Application is shutting down... (90f52c38)
2021-07-07T08:05:12.4528517-05:00  [INF] Exception during stop. (69827b32)
System.NullReferenceException: Object reference not set to an instance of an object.
   at Universal.Server.Services.SecurityProxy.StopAsync() in D:\a\universal\universal\src\Universal.Server\Services\SecurityProxy.cs:line 83
2021-07-07T08:05:12.4543676-05:00  [INF] Dashboard 1 not running. (5aad6de1)
2021-07-07T08:05:12.4543846-05:00  [INF] Dashboard 2 not running. (4f4cec78)
2021-07-07T08:05:12.4543888-05:00  [INF] Dashboard 3 not running. (6e330047)
2021-07-07T08:05:12.4543921-05:00  [INF] Dashboard 4 not running. (ee589ae3)
2021-07-07T08:05:12.4543952-05:00  [INF] Dashboard 5 not running. (74e34091)
2021-07-07T08:05:12.4543997-05:00  [INF] Dashboard 6 not running. (4edf6944)
2021-07-07T08:05:12.4544028-05:00  [INF] Dashboard 7 not running. (3fbe1f5a)
2021-07-07T08:05:12.4544058-05:00  [INF] Dashboard 8 not running. (c37dff7b)
2021-07-07T08:05:15.0274638-05:00  [INF] User profile is available. Using '"C:\Users\UD_AD_Automation\AppData\Local\ASP.NET\DataProtection-Keys"' as key repository and Windows DPAPI to encrypt keys at rest. (7ac5e29c)
2021-07-07T08:05:19.5770592-05:00  [INF] Now listening on: "http://[::]:5000" (d826f4b8)
2021-07-07T08:05:19.5786056-05:00  [INF] Application started. Hosting environment: "Production"; Content root path: "C:\Program Files (x86)\Universal\" (9029d6f8)

Then the login works:

2021-07-07T08:05:40.3148076-05:00 0HMA18VLRIIP1:00000001 [INF] Request starting HTTP/1.1 POST http://server:5000/api/v1/signin application/json 71 (ca22a1cb)
2021-07-07T08:05:40.3349052-05:00 0HMA18VLRIIP1:00000001 [INF] CORS policy execution failed. (09b6f179)
2021-07-07T08:05:40.3350237-05:00 0HMA18VLRIIP1:00000001 [INF] Request origin "http://server:5000" does not have permission to access the resource. (a03d560b)
2021-07-07T08:05:40.4983737-05:00 0HMA18VLRIIP1:00000001 [INF] Executing endpoint '"UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)"' (500cc934)
2021-07-07T08:05:40.5249848-05:00 0HMA18VLRIIP1:00000001 [INF] Route matched with "{action = \"SignIn\", controller = \"Authentication\"}". Executing controller action with signature "System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] SignIn(UniversalDashboard.Controllers.Credential)" on controller "UniversalDashboard.Controllers.AuthenticationController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:42.2393501-05:00 0HMA18VLRIIP1:00000001 [INF] Evaluting claims for Admin (c41c449e)
2021-07-07T08:05:42.2443710-05:00 0HMA18VLRIIP1:00000001 [INF] AuthenticationScheme: "Cookies" signed in. (c66dd7e7)
2021-07-07T08:05:42.2476467-05:00 0HMA18VLRIIP1:00000001 [INF] Executing JsonResult, writing value of type '"<>f__AnonymousType1`1[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]"'. (2f513669)
2021-07-07T08:05:42.2637222-05:00 0HMA18VLRIIP1:00000001 [INF] Executed action "UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)" in 1734.5604ms (afa2e885)
2021-07-07T08:05:42.2645168-05:00 0HMA18VLRIIP1:00000001 [INF] Executed endpoint '"UniversalDashboard.Controllers.AuthenticationController.SignIn (Universal.Server)"' (99874f2b)
2021-07-07T08:05:42.2676165-05:00 0HMA18VLRIIP1:00000001 [INF] Request finished in 1956.1735ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:42.2905702-05:00 0HMA18VLRIIP1:00000002 [INF] Request starting HTTP/1.1 GET http://server:5000/admin   (ca22a1cb)
2021-07-07T08:05:42.2954332-05:00 0HMA18VLRIIP1:00000002 [INF] /admin (00e9b4ee)
2021-07-07T08:05:42.2956101-05:00 0HMA18VLRIIP1:00000002 [INF] C:\Program Files (x86)\Universal\UniversalAutomation\admin (c6078a92)
2021-07-07T08:05:42.3144755-05:00 0HMA18VLRIIP1:00000002 [INF] Request finished in 23.9139ms 200 text/html (791a596a)
2021-07-07T08:05:43.3175616-05:00 0HMA18VLRIIP1:00000003 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/license/feature?t=1625663143302   (ca22a1cb)
2021-07-07T08:05:43.3221609-05:00 0HMA18VLRIIP2:00000001 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/accessible?t=1625663143304   (ca22a1cb)
2021-07-07T08:05:43.3233669-05:00 0HMA18VLRIIP4:00000001 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/stats?t=1625663143304   (ca22a1cb)
2021-07-07T08:05:43.3237209-05:00 0HMA18VLRIIP3:00000001 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/version?t=1625663143304   (ca22a1cb)
2021-07-07T08:05:43.3294486-05:00 0HMA18VLRIIP3:00000001 [INF] Executing endpoint '"Universal.Server.Services.VersionController.Get (Universal.Server)"' (500cc934)
2021-07-07T08:05:43.3308020-05:00 0HMA18VLRIIP3:00000001 [INF] Route matched with "{action = \"Get\", controller = \"Version\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Get()" on controller "Universal.Server.Services.VersionController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:43.3342007-05:00 0HMA18VLRIIP3:00000001 [INF] Executing ObjectResult, writing value of type '"System.String"'. (8a1b66c8)
2021-07-07T08:05:43.3349375-05:00 0HMA18VLRIIP3:00000001 [INF] Executed action "Universal.Server.Services.VersionController.Get (Universal.Server)" in 4.0522ms (afa2e885)
2021-07-07T08:05:43.3349794-05:00 0HMA18VLRIIP3:00000001 [INF] Executed endpoint '"Universal.Server.Services.VersionController.Get (Universal.Server)"' (99874f2b)
2021-07-07T08:05:43.3351799-05:00 0HMA18VLRIIP3:00000001 [INF] Request finished in 11.4209ms 200 text/plain; charset=utf-8 (791a596a)
2021-07-07T08:05:43.3473169-05:00 0HMA18VLRIIP4:00000001 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.3473209-05:00 0HMA18VLRIIP2:00000001 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.3474525-05:00 0HMA18VLRIIP4:00000001 [INF] Executing endpoint '"UniversalAutomation.StatsController.Get (UniversalAutomation)"' (500cc934)
2021-07-07T08:05:43.3474537-05:00 0HMA18VLRIIP2:00000001 [INF] Executing endpoint '"UniversalAutomation.AliveController.Accessible (UniversalAutomation)"' (500cc934)
2021-07-07T08:05:43.3486273-05:00 0HMA18VLRIIP4:00000001 [INF] Route matched with "{action = \"Get\", controller = \"Stats\"}". Executing controller action with signature "UniversalAutomation.Stats Get()" on controller "UniversalAutomation.StatsController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T08:05:43.3486794-05:00 0HMA18VLRIIP2:00000001 [INF] Route matched with "{action = \"Accessible\", controller = \"Alive\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult Accessible()" on controller "UniversalAutomation.AliveController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T08:05:43.3496033-05:00 0HMA18VLRIIP2:00000001 [INF] Returning user information (f14d189f)
2021-07-07T08:05:43.3504339-05:00 0HMA18VLRIIP2:00000001 [INF] Executing JsonResult, writing value of type '"<>f__AnonymousType0`2[[System.String, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[System.String[], System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e]]"'. (2f513669)
2021-07-07T08:05:43.3530764-05:00 0HMA18VLRIIP2:00000001 [INF] Executed action "UniversalAutomation.AliveController.Accessible (UniversalAutomation)" in 4.343ms (afa2e885)
2021-07-07T08:05:43.3531165-05:00 0HMA18VLRIIP2:00000001 [INF] Executed endpoint '"UniversalAutomation.AliveController.Accessible (UniversalAutomation)"' (99874f2b)
2021-07-07T08:05:43.3532088-05:00 0HMA18VLRIIP2:00000001 [INF] Request finished in 31.0955ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:43.3532994-05:00 0HMA18VLRIIP1:00000003 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.3533513-05:00 0HMA18VLRIIP1:00000003 [INF] Executing endpoint '"Universal.Server.Controllers.LicenseController.GetLicensedFeatures (Universal.Server)"' (500cc934)
2021-07-07T08:05:43.3545635-05:00 0HMA18VLRIIP4:00000001 [INF] Executing ObjectResult, writing value of type '"UniversalAutomation.Stats"'. (8a1b66c8)
2021-07-07T08:05:43.3546873-05:00 0HMA18VLRIIP1:00000003 [INF] Route matched with "{action = \"GetLicensedFeatures\", controller = \"License\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Common.Interfaces.Feature] GetLicensedFeatures()" on controller "Universal.Server.Controllers.LicenseController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:43.3555454-05:00 0HMA18VLRIIP1:00000003 [INF] Executing ObjectResult, writing value of type '"System.Collections.Generic.List`1[[UniversalAutomation.Common.Interfaces.Feature, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (8a1b66c8)
2021-07-07T08:05:43.3584293-05:00 0HMA18VLRIIP1:00000003 [INF] Executed action "Universal.Server.Controllers.LicenseController.GetLicensedFeatures (Universal.Server)" in 3.6922ms (afa2e885)
2021-07-07T08:05:43.3584778-05:00 0HMA18VLRIIP1:00000003 [INF] Executed endpoint '"Universal.Server.Controllers.LicenseController.GetLicensedFeatures (Universal.Server)"' (99874f2b)
2021-07-07T08:05:43.3585717-05:00 0HMA18VLRIIP1:00000003 [INF] Request finished in 41.4974ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:43.3641920-05:00 0HMA18VLRIIP4:00000001 [INF] Executed action "UniversalAutomation.StatsController.Get (UniversalAutomation)" in 15.5066ms (afa2e885)
2021-07-07T08:05:43.3642349-05:00 0HMA18VLRIIP4:00000001 [INF] Executed endpoint '"UniversalAutomation.StatsController.Get (UniversalAutomation)"' (99874f2b)
2021-07-07T08:05:43.3643568-05:00 0HMA18VLRIIP4:00000001 [INF] Request finished in 40.9953ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:43.3755914-05:00 0HMA18VLRIIP4:00000002 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/settings?t=1625663143364   (ca22a1cb)
2021-07-07T08:05:43.3775632-05:00 0HMA18VLRIIP4:00000002 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.3776211-05:00 0HMA18VLRIIP4:00000002 [INF] Executing endpoint '"UniversalAutomation.SettingsController.Get (UniversalAutomation)"' (500cc934)
2021-07-07T08:05:43.3790333-05:00 0HMA18VLRIIP4:00000002 [INF] Route matched with "{action = \"Get\", controller = \"Settings\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Settings] Get()" on controller "UniversalAutomation.SettingsController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T08:05:43.3798362-05:00 0HMA18VLRIIP4:00000002 [INF] Executing ObjectResult, writing value of type '"UniversalAutomation.Settings[]"'. (8a1b66c8)
2021-07-07T08:05:43.3855501-05:00 0HMA18VLRIIP4:00000002 [INF] Executed action "UniversalAutomation.SettingsController.Get (UniversalAutomation)" in 6.4533ms (afa2e885)
2021-07-07T08:05:43.3855988-05:00 0HMA18VLRIIP4:00000002 [INF] Executed endpoint '"UniversalAutomation.SettingsController.Get (UniversalAutomation)"' (99874f2b)
2021-07-07T08:05:43.3857145-05:00 0HMA18VLRIIP4:00000002 [INF] Request finished in 10.1548ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:43.4937290-05:00 0HMA18VLRIIP4:00000003 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/authmethod   (ca22a1cb)
2021-07-07T08:05:43.4939420-05:00 0HMA18VLRIIP3:00000002 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/version/update?t=1625663143480   (ca22a1cb)
2021-07-07T08:05:43.4956090-05:00 0HMA18VLRIIP3:00000002 [INF] Executing endpoint '"Universal.Server.Services.VersionController.GetUpdate (Universal.Server)"' (500cc934)
2021-07-07T08:05:43.4958518-05:00 0HMA18VLRIIP4:00000003 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.4958932-05:00 0HMA18VLRIIP4:00000003 [INF] Executing endpoint '"UniversalDashboard.Controllers.AuthenticationController.GetAuthenticationMethod (Universal.Server)"' (500cc934)
2021-07-07T08:05:43.4965145-05:00 0HMA18VLRIIP3:00000002 [INF] Route matched with "{action = \"GetUpdate\", controller = \"Version\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult GetUpdate()" on controller "Universal.Server.Services.VersionController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:43.4968774-05:00 0HMA18VLRIIP3:00000002 [INF] Executing JsonResult, writing value of type '"UniversalAutomation.Common.Update"'. (2f513669)
2021-07-07T08:05:43.4974180-05:00 0HMA18VLRIIP4:00000003 [INF] Route matched with "{action = \"GetAuthenticationMethod\", controller = \"Authentication\"}". Executing controller action with signature "System.String GetAuthenticationMethod()" on controller "UniversalDashboard.Controllers.AuthenticationController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:43.4983128-05:00 0HMA18VLRIIP4:00000003 [INF] Executing ObjectResult, writing value of type '"System.String"'. (8a1b66c8)
2021-07-07T08:05:43.4985434-05:00 0HMA18VLRIIP4:00000003 [INF] Executed action "UniversalDashboard.Controllers.AuthenticationController.GetAuthenticationMethod (Universal.Server)" in 1.0821ms (afa2e885)
2021-07-07T08:05:43.4985679-05:00 0HMA18VLRIIP4:00000003 [INF] Executed endpoint '"UniversalDashboard.Controllers.AuthenticationController.GetAuthenticationMethod (Universal.Server)"' (99874f2b)
2021-07-07T08:05:43.4986414-05:00 0HMA18VLRIIP4:00000003 [INF] Request finished in 4.9496ms 200 text/plain; charset=utf-8 (791a596a)
2021-07-07T08:05:43.4988435-05:00 0HMA18VLRIIP1:00000004 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/gitStatus/setting?t=1625663143484   (ca22a1cb)
2021-07-07T08:05:43.4993602-05:00 0HMA18VLRIIP3:00000002 [INF] Executed action "Universal.Server.Services.VersionController.GetUpdate (Universal.Server)" in 2.8067ms (afa2e885)
2021-07-07T08:05:43.4993945-05:00 0HMA18VLRIIP3:00000002 [INF] Executed endpoint '"Universal.Server.Services.VersionController.GetUpdate (Universal.Server)"' (99874f2b)
2021-07-07T08:05:43.4994639-05:00 0HMA18VLRIIP3:00000002 [INF] Request finished in 5.5413ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:43.5009845-05:00 0HMA18VLRIIP1:00000004 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.5010409-05:00 0HMA18VLRIIP1:00000004 [INF] Executing endpoint '"UniversalAutomation.GitStatusController.GetSettings (UniversalAutomation)"' (500cc934)
2021-07-07T08:05:43.5013971-05:00 0HMA18VLRIIP4:00000004 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/authmethod   (ca22a1cb)
2021-07-07T08:05:43.5020363-05:00 0HMA18VLRIIP1:00000004 [INF] Route matched with "{action = \"GetSettings\", controller = \"GitStatus\"}". Executing controller action with signature "Microsoft.AspNetCore.Mvc.IActionResult GetSettings()" on controller "UniversalAutomation.GitStatusController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T08:05:43.5024612-05:00 0HMA18VLRIIP1:00000004 [INF] Executing JsonResult, writing value of type '"<>f__AnonymousType1`2[[System.Boolean, System.Private.CoreLib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=7cec85d7bea7798e],[UniversalAutomation.Common.GitSyncBehavior, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (2f513669)
2021-07-07T08:05:43.5027994-05:00 0HMA18VLRIIP4:00000004 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.5028329-05:00 0HMA18VLRIIP4:00000004 [INF] Executing endpoint '"UniversalDashboard.Controllers.AuthenticationController.GetAuthenticationMethod (Universal.Server)"' (500cc934)
2021-07-07T08:05:43.5029780-05:00 0HMA18VLRIIP4:00000004 [INF] Route matched with "{action = \"GetAuthenticationMethod\", controller = \"Authentication\"}". Executing controller action with signature "System.String GetAuthenticationMethod()" on controller "UniversalDashboard.Controllers.AuthenticationController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:43.5032060-05:00 0HMA18VLRIIP4:00000004 [INF] Executing ObjectResult, writing value of type '"System.String"'. (8a1b66c8)
2021-07-07T08:05:43.5033378-05:00 0HMA18VLRIIP4:00000004 [INF] Executed action "UniversalDashboard.Controllers.AuthenticationController.GetAuthenticationMethod (Universal.Server)" in 0.3345ms (afa2e885)
2021-07-07T08:05:43.5033576-05:00 0HMA18VLRIIP4:00000004 [INF] Executed endpoint '"UniversalDashboard.Controllers.AuthenticationController.GetAuthenticationMethod (Universal.Server)"' (99874f2b)
2021-07-07T08:05:43.5034182-05:00 0HMA18VLRIIP4:00000004 [INF] Request finished in 2.0326ms 200 text/plain; charset=utf-8 (791a596a)
2021-07-07T08:05:43.5041898-05:00 0HMA18VLRIIP1:00000004 [INF] Executed action "UniversalAutomation.GitStatusController.GetSettings (UniversalAutomation)" in 2.1051ms (afa2e885)
2021-07-07T08:05:43.5042243-05:00 0HMA18VLRIIP1:00000004 [INF] Executed endpoint '"UniversalAutomation.GitStatusController.GetSettings (UniversalAutomation)"' (99874f2b)
2021-07-07T08:05:43.5042927-05:00 0HMA18VLRIIP1:00000004 [INF] Request finished in 5.4533ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:43.7088401-05:00 0HMA18VLRIIP1:00000005 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/endpoint   (ca22a1cb)
2021-07-07T08:05:43.7105808-05:00 0HMA18VLRIIP1:00000005 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.7106363-05:00 0HMA18VLRIIP1:00000005 [INF] Executing endpoint '"UniversalAutomation.EndpointController.Get (Universal.Server)"' (500cc934)
2021-07-07T08:05:43.7116720-05:00 0HMA18VLRIIP1:00000005 [INF] Route matched with "{action = \"Get\", controller = \"Endpoint\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Endpoint] Get()" on controller "UniversalAutomation.EndpointController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:43.7121383-05:00 0HMA18VLRIIP1:00000005 [INF] Executing ObjectResult, writing value of type '"System.Collections.ObjectModel.ReadOnlyCollection`1[[UniversalAutomation.Endpoint, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (8a1b66c8)
2021-07-07T08:05:43.7132887-05:00 0HMA18VLRIIP1:00000005 [INF] Executed action "UniversalAutomation.EndpointController.Get (Universal.Server)" in 1.5647ms (afa2e885)
2021-07-07T08:05:43.7133603-05:00 0HMA18VLRIIP1:00000005 [INF] Executed endpoint '"UniversalAutomation.EndpointController.Get (Universal.Server)"' (99874f2b)
2021-07-07T08:05:43.7134593-05:00 0HMA18VLRIIP1:00000005 [INF] Request finished in 4.6464ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:43.7304109-05:00 0HMA18VLRIIP1:00000006 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/role?t=1625663143720   (ca22a1cb)
2021-07-07T08:05:43.7318579-05:00 0HMA18VLRIIP1:00000006 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:43.7319040-05:00 0HMA18VLRIIP1:00000006 [INF] Executing endpoint '"UniversalAutomation.RoleController.Get (UniversalAutomation)"' (500cc934)
2021-07-07T08:05:43.7328549-05:00 0HMA18VLRIIP1:00000006 [INF] Route matched with "{action = \"Get\", controller = \"Role\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Role] Get()" on controller "UniversalAutomation.RoleController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T08:05:43.7330278-05:00 0HMA18VLRIIP1:00000006 [INF] Executing ObjectResult, writing value of type '"System.Collections.ObjectModel.ReadOnlyCollection`1[[UniversalAutomation.Role, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (8a1b66c8)
2021-07-07T08:05:43.7344670-05:00 0HMA18VLRIIP1:00000006 [INF] Executed action "UniversalAutomation.RoleController.Get (UniversalAutomation)" in 1.5622ms (afa2e885)
2021-07-07T08:05:43.7345018-05:00 0HMA18VLRIIP1:00000006 [INF] Executed endpoint '"UniversalAutomation.RoleController.Get (UniversalAutomation)"' (99874f2b)
2021-07-07T08:05:43.7345889-05:00 0HMA18VLRIIP1:00000006 [INF] Request finished in 4.197ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:56.7336260-05:00 0HMA18VLRIIP1:00000007 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/license/feature?t=1625663156719   (ca22a1cb)
2021-07-07T08:05:56.7360059-05:00 0HMA18VLRIIP4:00000005 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/endpoint   (ca22a1cb)
2021-07-07T08:05:56.7399828-05:00 0HMA18VLRIIP4:00000005 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:56.7401487-05:00 0HMA18VLRIIP4:00000005 [INF] Executing endpoint '"UniversalAutomation.EndpointController.Get (Universal.Server)"' (500cc934)
2021-07-07T08:05:56.7404758-05:00 0HMA18VLRIIP4:00000005 [INF] Route matched with "{action = \"Get\", controller = \"Endpoint\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Endpoint] Get()" on controller "UniversalAutomation.EndpointController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:56.7409299-05:00 0HMA18VLRIIP4:00000005 [INF] Executing ObjectResult, writing value of type '"System.Collections.ObjectModel.ReadOnlyCollection`1[[UniversalAutomation.Endpoint, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (8a1b66c8)
2021-07-07T08:05:56.7416828-05:00 0HMA18VLRIIP4:00000005 [INF] Executed action "UniversalAutomation.EndpointController.Get (Universal.Server)" in 1.0751ms (afa2e885)
2021-07-07T08:05:56.7418032-05:00 0HMA18VLRIIP4:00000005 [INF] Executed endpoint '"UniversalAutomation.EndpointController.Get (Universal.Server)"' (99874f2b)
2021-07-07T08:05:56.7421236-05:00 0HMA18VLRIIP4:00000005 [INF] Request finished in 6.1544ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:56.7425159-05:00 0HMA18VLRIIP3:00000003 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/role?t=1625663156721   (ca22a1cb)
2021-07-07T08:05:56.7455767-05:00 0HMA18VLRIIP3:00000003 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:56.7456662-05:00 0HMA18VLRIIP3:00000003 [INF] Executing endpoint '"UniversalAutomation.RoleController.Get (UniversalAutomation)"' (500cc934)
2021-07-07T08:05:56.7458934-05:00 0HMA18VLRIIP3:00000003 [INF] Route matched with "{action = \"Get\", controller = \"Role\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Role] Get()" on controller "UniversalAutomation.RoleController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T08:05:56.7462186-05:00 0HMA18VLRIIP3:00000003 [INF] Executing ObjectResult, writing value of type '"System.Collections.ObjectModel.ReadOnlyCollection`1[[UniversalAutomation.Role, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (8a1b66c8)
2021-07-07T08:05:56.7472249-05:00 0HMA18VLRIIP3:00000003 [INF] Executed action "UniversalAutomation.RoleController.Get (UniversalAutomation)" in 1.2363ms (afa2e885)
2021-07-07T08:05:56.7473089-05:00 0HMA18VLRIIP3:00000003 [INF] Executed endpoint '"UniversalAutomation.RoleController.Get (UniversalAutomation)"' (99874f2b)
2021-07-07T08:05:56.7475565-05:00 0HMA18VLRIIP3:00000003 [INF] Request finished in 5.0615ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:56.7508709-05:00 0HMA18VLRIIP1:00000007 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:56.7509583-05:00 0HMA18VLRIIP1:00000007 [INF] Executing endpoint '"Universal.Server.Controllers.LicenseController.GetLicensedFeatures (Universal.Server)"' (500cc934)
2021-07-07T08:05:56.7511427-05:00 0HMA18VLRIIP1:00000007 [INF] Route matched with "{action = \"GetLicensedFeatures\", controller = \"License\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Common.Interfaces.Feature] GetLicensedFeatures()" on controller "Universal.Server.Controllers.LicenseController" ("Universal.Server"). (122b2fdf)
2021-07-07T08:05:56.7514922-05:00 0HMA18VLRIIP1:00000007 [INF] Executing ObjectResult, writing value of type '"System.Collections.Generic.List`1[[UniversalAutomation.Common.Interfaces.Feature, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (8a1b66c8)
2021-07-07T08:05:56.7520339-05:00 0HMA18VLRIIP1:00000007 [INF] Executed action "Universal.Server.Controllers.LicenseController.GetLicensedFeatures (Universal.Server)" in 0.8258ms (afa2e885)
2021-07-07T08:05:56.7520878-05:00 0HMA18VLRIIP1:00000007 [INF] Executed endpoint '"Universal.Server.Controllers.LicenseController.GetLicensedFeatures (Universal.Server)"' (99874f2b)
2021-07-07T08:05:56.7523182-05:00 0HMA18VLRIIP1:00000007 [INF] Request finished in 18.9372ms 200 application/json; charset=utf-8 (791a596a)
2021-07-07T08:05:56.8013793-05:00 0HMA18VLRIIP1:00000008 [INF] Request starting HTTP/1.1 GET http://server:5000/api/v1/role?t=1625663156790   (ca22a1cb)
2021-07-07T08:05:56.8046460-05:00 0HMA18VLRIIP1:00000008 [INF] Authorization was successful. (0d575a54)
2021-07-07T08:05:56.8047077-05:00 0HMA18VLRIIP1:00000008 [INF] Executing endpoint '"UniversalAutomation.RoleController.Get (UniversalAutomation)"' (500cc934)
2021-07-07T08:05:56.8049329-05:00 0HMA18VLRIIP1:00000008 [INF] Route matched with "{action = \"Get\", controller = \"Role\"}". Executing controller action with signature "System.Collections.Generic.IEnumerable`1[UniversalAutomation.Role] Get()" on controller "UniversalAutomation.RoleController" ("UniversalAutomation"). (122b2fdf)
2021-07-07T08:05:56.8052156-05:00 0HMA18VLRIIP1:00000008 [INF] Executing ObjectResult, writing value of type '"System.Collections.ObjectModel.ReadOnlyCollection`1[[UniversalAutomation.Role, UniversalAutomation.Common, Version=1.0.0.0, Culture=neutral, PublicKeyToken=null]]"'. (8a1b66c8)
2021-07-07T08:05:56.8060545-05:00 0HMA18VLRIIP1:00000008 [INF] Executed action "UniversalAutomation.RoleController.Get (UniversalAutomation)" in 1.0574ms (afa2e885)
2021-07-07T08:05:56.8061275-05:00 0HMA18VLRIIP1:00000008 [INF] Executed endpoint '"UniversalAutomation.RoleController.Get (UniversalAutomation)"' (99874f2b)
2021-07-07T08:05:56.8063334-05:00 0HMA18VLRIIP1:00000008 [INF] Request finished in 5.0429ms 200 application/json; charset=utf-8 (791a596a)

adam · July 7, 2021, 1:57pm

Ok. Thanks for all the info. It doesn’t look like it has anything to do with resources.

What I am noticing is that it isn’t running the claims evaluation again. For Windows authentication we cache claims because otherwise it runs super frequently. For forms (cookies) authentication, we don’t do this but based on the log and behavior, it kind of seems like that’s what is happening.

I’m adding some more logging to the claims evaluater in 2.1.2 to see if we can get some more information out of PSU when this is happening.

EDIT: 2.1.2 has the additonal logging. If you have a chance to upgrade and then switch the logging to the Debug level, that would be helpful.