GRPC issues between servers

rbleattler · February 28, 2022, 6:22pm

@adam Do you have any idea whats going on here?

I’m running into issues with an API where from some segments of our network, requests are only getting through some of the time. This particular software loops through a number of calls (using an async handler, so it should not be just ending the call). We’re seeing these GRPC errors.

2022-02-28 09:42:45.893 -06:00 [DBG] Starting C:\Program Files\PowerShell\7\pwsh.exe with command line  -NoProfile -Command "& { [System.Reflection.Assembly]::LoadFrom('D:\PowerShellUniversal\Installation\Host\host.dll') | Out-Null; [UniversalHost.AgentService]::StartDashboard(63646, 2956, 63622) }"
2022-02-28 09:42:45.893 -06:00 [INF] Starting job using CreateProcessAsUser.
2022-02-28 09:42:59.034 -06:00 [DBG] Connection ID "18374686485577204722" disconnecting.
2022-02-28 09:42:59.042 -06:00 [ERR] An unhandled exception has occurred while executing the request.
Grpc.Core.RpcException: Status(StatusCode="Cancelled", Detail="Cancelled", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646062979.035000000","description":"Error received from peer ipv6:[::1]:63624","file":"..\..\..\src\core\lib\surface\call.cc","file_line":1067,"grpc_message":"Cancelled","grpc_status":1}")
   at Universal.Server.Services.ApiGrpc.ExecuteAsync(apiRequest request, CancellationToken cancellationToken) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiGrpc.cs:line 149
   at Universal.Server.Services.ApiService.ExecuteAsync(HttpContext httpContext) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiService.cs:line 323
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 79
   at Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.<Invoke>g__AwaitMatcher|8_0(EndpointRoutingMiddleware middleware, HttpContext httpContext, Task`1 matcherTask)
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 40
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
2022-02-28 09:42:59.086 -06:00 [DBG] POST requests are not supported
2022-02-28 09:42:59.087 -06:00 [DBG] POST requests are not supported
2022-02-28 09:42:59.087 -06:00 [DBG] No candidates found for the request path '/Error'
2022-02-28 09:42:59.087 -06:00 [DBG] Request did not match any endpoints
2022-02-28 09:42:59.088 -06:00 [WRN] No exception handler was found, rethrowing original exception.
2022-02-28 09:42:59.089 -06:00 [ERR] Connection ID "18374686485577204722", Request ID "800003f3-0001-ff00-b63f-84710c7967bb": An unhandled exception was thrown by the application.
Grpc.Core.RpcException: Status(StatusCode="Cancelled", Detail="Cancelled", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646062979.035000000","description":"Error received from peer ipv6:[::1]:63624","file":"..\..\..\src\core\lib\surface\call.cc","file_line":1067,"grpc_message":"Cancelled","grpc_status":1}")
   at Universal.Server.Services.ApiGrpc.ExecuteAsync(apiRequest request, CancellationToken cancellationToken) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiGrpc.cs:line 149
   at Universal.Server.Services.ApiService.ExecuteAsync(HttpContext httpContext) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiService.cs:line 323
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 79
   at Microsoft.AspNetCore.Routing.EndpointRoutingMiddleware.<Invoke>g__AwaitMatcher|8_0(EndpointRoutingMiddleware middleware, HttpContext httpContext, Task`1 matcherTask)
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 40
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.HandleException(HttpContext context, ExceptionDispatchInfo edi)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Builder.Extensions.MapMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync()

I’m assuming we have something blocked in our corporate network that is causing this. In all my testing from my laptop I never had this problem, but from our server VLANs we do. If not that, I’m at a loss. I can share the source code that is calling this if needed, its an open source project I’m working on.

rbleattler · February 28, 2022, 7:34pm

Looks like this is also happening with a dashboard now as well. The previously mentioned issue was occurring on 2.7 and 2.8.3. I’m not sure about the dashboard. But I’m also seeing a bunch of these with the dashboard. This also immediately stops the dashboard.

2022-02-28 13:32:43.485 -06:00 [DBG] POST requests are not supported
2022-02-28 13:32:43.487 -06:00 [DBG] POST requests are not supported
2022-02-28 13:32:43.491 -06:00 [DBG] POST requests are not supported
2022-02-28 13:32:43.491 -06:00 [DBG] POST requests are not supported
2022-02-28 13:32:43.491 -06:00 [DBG] No candidates found for the request path '/Error'
2022-02-28 13:32:43.491 -06:00 [DBG] No candidates found for the request path '/Error'
2022-02-28 13:32:43.491 -06:00 [DBG] POST requests are not supported
2022-02-28 13:32:43.491 -06:00 [DBG] Request did not match any endpoints
2022-02-28 13:32:43.491 -06:00 [DBG] Request did not match any endpoints
2022-02-28 13:32:43.492 -06:00 [DBG] No candidates found for the request path '/Error'
2022-02-28 13:32:43.487 -06:00 [DBG] POST requests are not supported
2022-02-28 13:32:43.492 -06:00 [DBG] POST requests are not supported
2022-02-28 13:32:43.492 -06:00 [DBG] No candidates found for the request path '/Error'
2022-02-28 13:32:43.492 -06:00 [DBG] Request did not match any endpoints
2022-02-28 13:32:43.492 -06:00 [DBG] Request did not match any endpoints

adam · February 28, 2022, 9:39pm

We allocate a gRPC dynamic port when opening communication between external processes (like pwsh\powershell) and the PSU service. A cancelled status typically means some sort of time out.

I’m wondering if something is blocking this type of thing. The ports only listen on the loop back adapter.

rbleattler · February 28, 2022, 11:03pm

Hmm, that’s pretty interesting. I made a handful of changes to the way things are processing inside PSU and the API side of things seems to be resolved. Unfortunately the dashboard which worked fine prior to my upgrade from 2.7 → 2.8.3 is still completely borked and shows “Session Timed Out” after just a few seconds, and the dashboard shuts down.

Looks like there were a lot of changes between 2.7.x and 2.8.3. I’ll include a snippet of the log in another reply to show what I’m seeing there (this is already a long reply).

I have two dashboards this is happening on, the one I can actually share is my ‘playground’. I’d been experimenting with pulling in external ‘components’ (just chunks of code) to try to keep the file a bit more terse… This was working before without issue (at least in some places). I tried disabling that part of the code and it didn’t matter.

The base is :

# Import Supporting Components #
$ComponentDirectory = Join-Path -Path $PSScriptRoot -ChildPath 'DashboardComponents'
$Components = Get-ChildItem $ComponentDirectory -File
$Components.ForEach{
    $ComponentRaw = Get-Content $($Components.Where{ $PSItem.BaseName -eq 'WarningModal' }) -Raw
    $ComponentName = $PSItem.BaseName
    $ScriptBlockVarName = '{0}ScriptBlock' -f $ComponentName
    New-Variable -Name $ScriptBlockVarName -Value $([scriptblock]::Create($ComponentRaw))
}
# #

New-UDDashboard -Title "Testing Dashboard" -Stylesheets @('/SharedAssets/custom.css') -Content {
    $Session:TestStringList = @('TestString1', 'TestString2', 'TestString3')
    $Session:IUJ = @"
var elem; 
elem = document.getElementById('ReportDownload'); 
elem.toggleAttribute('download');
//elem.toggleAttribute('hidden');
var disable = elem.getAttribute('class');
disable = disable.replace(' Mui-disabled','')
elem.setAttribute('class',disable)
"@

    New-UDDynamic -Id 'ButtonD' -Content {
        
        # $ButtonTester
        # New-UDButton -Id 'TestButton' -text 'TestButton' -Size medium -OnClick {
        #     if ($session:FormSubmitted){
        #         Invoke-UDJavaScript -Javascript $Session:IUJ
        #     }
        # }

    }
    New-UDRow -Id 'Row0' -Columns {
        New-UDColumn -Id 'Col0' -Endpoint {
            New-UDCard -Title 'Web Logs and Reporting' -Content {
                New-UDStyle -Style ".MuiButton-root { visibility: hidden !important }" -Content {
                    New-UDForm -Id 'QueryBuilder' -SubmitText 'Get Logs' -ButtonVariant outlined -CancelText 'Cancel Request' -Content {
                        New-UDSelect -Id 'SiteSelector' -Label 'Website Name(s)' -DefaultValue $($Session:TestStringList | Sort-Object)[0] -Option { 
                        ($Session:TestStringList | Sort-Object).Foreach{
                                New-UDSelectOption -Name $PSItem -Value $PSItem
                            }
                        } -OnChange {
                            $Session:FormSubmitted = $false
                        }
                        New-UDDatePicker -Id 'StartDatePicker' -Label 'Start Date' -Variant inline -Locale en -Value $([datetime]::now.AddYears(-1)) -OnChange { $Body }
                        New-UDTimePicker -Id 'StartTimePicker' -Label 'Start Time' -Locale en -Value $([datetime]::now) -OnChange { 
                            $Session:FormSubmitted = $false
                            $Body 
                        }
                        New-UDDatePicker -Id 'EndDatePicker' -Label 'End Date' -Variant inline -Locale en -Value $([datetime]::now) -OnChange { 
                            $Session:FormSubmitted = $false
                            $Body 
                        }
                        New-UDTimePicker -Id 'EndTimePicker' -Label 'End Time' -Locale en -Value $([datetime]::now) -OnChange { 
                            $Session:FormSubmitted = $false
                            $Body 
                        }
                        New-UDCheckBox -Id 'GenerateCsv' -Label 'GenerateCsv' -Checked $false -OnChange {
                            $Session:FormSubmitted = $false
                        }
                        New-UDCheckBox -Id 'GenerateReport' -Label 'Generate Site Report' -Checked $false -OnChange { 
                            $Session:FormSubmitted = $false
                            if ($EventData) {
                                Set-UDElement -Id 'TSV' -Attributes @{disabled = $false }
                                Set-UDElement -Id 'TUSV' -Attributes @{disabled = $false }
                                Set-UDElement -Id 'TPH' -Attributes @{disabled = $false }
                                Set-UDElement -Id 'TD' -Attributes @{disabled = $false }
                            } else {
                                Set-UDElement -Id 'TSV' -Attributes @{
                                    disabled = $true
                                    checked  = $false
                                }
                                Set-UDElement -Id 'TUSV' -Attributes @{
                                    disabled = $true
                                    checked  = $false
                                }
                                Set-UDElement -Id 'TPH' -Attributes @{
                                    disabled = $true
                                    checked  = $false
                                }
                                Set-UDElement -Id 'TD' -Attributes @{
                                    disabled = $true
                                    checked  = $false
                                }
                            }
                        }
                        New-UDCheckBox -Id 'TSV' -Label 'Total Site Visits' -Disabled -OnChange { 
                            $Session:FormSubmitted = $false
                        }
                        New-UDCheckBox -Id 'TUSV' -Label 'Total Unique Visitors' -Disabled -OnChange { 
                            $Session:FormSubmitted = $false
                        }
                        New-UDCheckBox -Id 'TPH' -Label 'Total Page Hits' -Disabled -OnChange { 
                            $Session:FormSubmitted = $false
                        }
                        New-UDCheckBox -Id 'TD' -Label 'Total Downloads' -Disabled -OnChange { 
                            $Session:FormSubmitted = $false
                        }
                        # New-UDCheckBox -Id 'GetResultTable' -Label 'Return Results Table'
                    } -OnSubmit {
                        if ($null -ne $EventData) {
                            $Session:FormSubmitted = $true
                        } else {
                            $Session:FormSubmitted = $false
                        }
                        Sync-UDElement -Id 'ButtonDynamic'
                    }
                }
            }
        } -LargeSize 4

        New-UDColumn -Id 'Col2' -Content {
            New-UDCard -Title 'How to Use This Page' -Content {
                New-UDHtml -Markup @"
Some Instructions here...
"@
            }
            New-UDCard -Id 'ExportLinks' -Content {
                New-UDDynamic -Id 'ButtonDynamic' -Content {
                    New-UDGrid -Id 'ButtonGrid' -Container -Spacing 5 -Content {
                        New-UDGrid -Id 'SubmitButtonGridItem' -Item -Content {
                            New-UDButton -ClassName 'MuiButtonBase-root MuiButton-root MuiButton-contained MuiButton-containedSizeSmall ud-mu-button' -Id 'SubmitForm' -Text 'Get Logs' -OnClick {
                                Invoke-UDForm -Id 'QueryBuilder'
                                Sync-UDElement -Id 'ButtonD'
                                #Invoke-UDJavaScript -Javascript $Session:IUJ
                            }
                        }
                        if ($Session:FormSubmitted) {
                            New-UDGrid -Id 'ReportButtonGridItem' -Item -Content {
                                New-UDButton -Text 'Get Report' -Variant contained -Href 'https://lxa-devops-ua.ubcmain.com/tempdownloads/SiteReport-2022-01-13_03-13.pdf' -Id 'ReportDownload'
                            }
                        }
                    }
                    Sync-UDElement -Id CsvDynamic
                    Sync-UDElement -Id ReportDynamic
                }
            }
        } -LargeSize 5
    }
    New-UDHeading -Text 'My List!' -Size 1
    New-UDList -Id 'DataPreviewList' -SubHeader 'MyList' -Content {
        New-UDListItem -Icon (New-UDIcon -Icon globe -Size xs) -Id 'SiteNameListItem' -Label 'Site Url' -SubTitle "SiteUrl"
        New-UDListItem -Icon (New-UDIcon -Icon door_open -Size sm) -Id 'TUSVListItem' -Label 'Total Unique Site Visits' -SubTitle "TUSV"
        New-UDListItem -Icon (New-UDIcon -Icon eye -Size lg) -Id 'TPHListItem' -Label 'Total Page Hits' -SubTitle "TPH"
        New-UDListItem -Icon (New-UDIcon -Icon user_friends -Size 2x) -Id 'TSVListItem' -Label 'Total Site Visits' -SubTitle "TSV"
        New-UDListItem -Icon (New-UDIcon -Icon download -Size 3x) -Id 'TDListItem' -Label 'Total Downloads' -SubTitle "TD"
    }
    #region Warning Modal
    $WarningModalScriptBlock.Invoke()
    #endregion Warning Modal
}

The component being imported is a warning modal that blocks out the screen until the user agrees to a message (its glitchy, it will just leave you with an empty page if you accidentally click outside the box… but it works for now)

$CenterAlignStyle = "text-align: center;"
Show-UDModal -Content {
    Switch-UDElementAttribute -Id 'app' -AttributeName 'hidden'
    New-UDRow -Columns {
        New-UDColumn -Id 'Modal0' -Content {
            New-UDStyle -Id 'CenterAlign0' -Style $CenterAlignStyle -Content {
                New-UDTypography -Id 'ModalWarning' -Text 'This page is to be used by Authorized UBC Personnel only. All other persons found to be using this page are subject to legal action.'
            }
        }
    }
    New-UDRow -Columns {
        New-UDColumn -Id 'Modal1' -Content {
            New-UDStyle -Id 'CenterAlign0' -Style $CenterAlignStyle -Content {
                New-UDButton -Text 'I Understand' -OnClick {
                    Switch-UDElementAttribute -Id 'CsvDownload' -AttributeName 'hidden'
                    Switch-UDElementAttribute -Id 'ReportDownload' -AttributeName 'hidden'
                    Hide-UDModal
                    Set-UDElementAttribute -Id 'ReportDownload' -AttributeName 'Target' -Value '_blank'
                    $IsHidden = Get-UDElementAttribute -Id 'app' -AttributeName 'hidden'
                    if ($IsHidden) {
                        Switch-UDElementAttribute -Id 'app' -AttributeName 'hidden'
                    }
                    Switch-UDElementAttribute -Id 'app' -AttributeName 'hidden'
                } 
            }
        }
    }
}

rbleattler · February 28, 2022, 11:03pm

Log Snippet

2022-02-28 16:44:23.747 -06:00 [ERR] An unhandled exception has occurred while executing the request.
Grpc.Core.RpcException: Status(StatusCode="Unknown", Detail="Stream removed", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646088263.741000000","description":"Error received from peer ipv6:[::1]:61684","file":"..\..\..\src\core\lib\surface\call.cc","file_line":1067,"grpc_message":"Stream removed","grpc_status":2}")
   at Universal.Server.Services.DashboardProxy.ExecuteAsync(ExecutionContext context) in D:\a\universal\universal\src\Universal.Server\Services\Dashboard\DashboardProxy.cs:line 567
   at UniversalDashboard.Controllers.UDComponentController.RunScript(String endpointId, Dictionary`2 parameters, Boolean form) in D:\a\universal\universal\src\Universal.Server\Controllers\UDComponentController.cs:line 187
   at UniversalDashboard.Controllers.UDComponentController.ElementPost(String id, Boolean form) in D:\a\universal\universal\src\Universal.Server\Controllers\UDComponentController.cs:line 376
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 134
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 42
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
2022-02-28 16:44:23.754 -06:00 [DBG] POST requests are not supported
2022-02-28 16:44:23.754 -06:00 [DBG] POST requests are not supported
2022-02-28 16:44:23.755 -06:00 [DBG] No candidates found for the request path '/Error'
2022-02-28 16:44:23.755 -06:00 [DBG] Request did not match any endpoints
2022-02-28 16:44:23.758 -06:00 [WRN] No exception handler was found, rethrowing original exception.
2022-02-28 16:44:23.760 -06:00 [ERR] Connection ID "18014398528272466008", Request ID "80000067-0004-fa00-b63f-84710c7967bb": An unhandled exception was thrown by the application.
Grpc.Core.RpcException: Status(StatusCode="Unknown", Detail="Stream removed", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646088263.741000000","description":"Error received from peer ipv6:[::1]:61684","file":"..\..\..\src\core\lib\surface\call.cc","file_line":1067,"grpc_message":"Stream removed","grpc_status":2}")
   at Universal.Server.Services.DashboardProxy.ExecuteAsync(ExecutionContext context) in D:\a\universal\universal\src\Universal.Server\Services\Dashboard\DashboardProxy.cs:line 567
   at UniversalDashboard.Controllers.UDComponentController.RunScript(String endpointId, Dictionary`2 parameters, Boolean form) in D:\a\universal\universal\src\Universal.Server\Controllers\UDComponentController.cs:line 187
   at UniversalDashboard.Controllers.UDComponentController.ElementPost(String id, Boolean form) in D:\a\universal\universal\src\Universal.Server\Controllers\UDComponentController.cs:line 376
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 134
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 42
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.HandleException(HttpContext context, ExceptionDispatchInfo edi)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Builder.Extensions.MapMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync()
2022-02-28 16:44:23.767 -06:00 [INF] Request finished HTTP/1.1 POST https://MyServerUrl.com/api/internal/component/element/8ef53d64-9c66-43d8-a3b5-4967e9ddb0c0 application/json 2 - 500 - - 10294.3543ms
2022-02-28 16:44:23.784 -06:00 [INF] Request starting HTTP/1.1 GET https://MyServerUrl.com/api/internal/session/211f8845-a2cd-4598-a3f2-b6c6dca3fe6d - -
2022-02-28 16:44:23.787 -06:00 [INF] Evaluting claims for ubcmain\robert.bleattler, Cache: True
2022-02-28 16:44:23.788 -06:00 [DBG] The request path /api/internal/session/211f8845-a2cd-4598-a3f2-b6c6dca3fe6d does not match a supported file type
2022-02-28 16:44:23.788 -06:00 [DBG] The request path  does not match the path filter
2022-02-28 16:44:23.788 -06:00 [DBG] 1 candidate(s) found for the request path '/api/internal/session/211f8845-a2cd-4598-a3f2-b6c6dca3fe6d'
2022-02-28 16:44:23.788 -06:00 [DBG] Endpoint 'UniversalDashboard.Controllers.SessionController.Index (Universal.Server)' with route pattern 'api/internal/session/{sessionId}' is valid for the request path '/api/internal/session/211f8845-a2cd-4598-a3f2-b6c6dca3fe6d'
2022-02-28 16:44:23.788 -06:00 [DBG] Request matched endpoint 'UniversalDashboard.Controllers.SessionController.Index (Universal.Server)'
2022-02-28 16:44:23.792 -06:00 [INF] Executing endpoint 'UniversalDashboard.Controllers.SessionController.Index (Universal.Server)'
2022-02-28 16:44:23.792 -06:00 [INF] Route matched with {action = "Index", controller = "Session"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Index(System.String) on controller UniversalDashboard.Controllers.SessionController (Universal.Server).
2022-02-28 16:44:23.792 -06:00 [DBG] Execution plan of authorization filters (in the following order): ["None"]
2022-02-28 16:44:23.792 -06:00 [DBG] Execution plan of resource filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"]
2022-02-28 16:44:23.792 -06: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)"]
2022-02-28 16:44:23.792 -06:00 [DBG] Execution plan of exception filters (in the following order): ["None"]
2022-02-28 16:44:23.793 -06:00 [DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"]
2022-02-28 16:44:23.793 -06:00 [DBG] Executing controller factory for controller UniversalDashboard.Controllers.SessionController (Universal.Server)
2022-02-28 16:44:23.793 -06:00 [DBG] Executed controller factory for controller UniversalDashboard.Controllers.SessionController (Universal.Server)
2022-02-28 16:44:23.793 -06:00 [DBG] Attempting to bind parameter 'sessionId' of type 'System.String' ...
2022-02-28 16:44:23.793 -06:00 [DBG] Attempting to bind parameter 'sessionId' of type 'System.String' using the name 'sessionId' in request data ...
2022-02-28 16:44:23.793 -06:00 [DBG] Done attempting to bind parameter 'sessionId' of type 'System.String'.
2022-02-28 16:44:23.793 -06:00 [DBG] Done attempting to bind parameter 'sessionId' of type 'System.String'.
2022-02-28 16:44:23.793 -06:00 [DBG] Attempting to validate the bound parameter 'sessionId' of type 'System.String' ...
2022-02-28 16:44:23.793 -06:00 [DBG] Done attempting to validate the bound parameter 'sessionId' of type 'System.String'.
2022-02-28 16:44:25.040 -06:00 [INF] Request starting HTTP/1.1 GET https://MyServerUrl.com/api/internal/dashboard - -
2022-02-28 16:44:25.042 -06:00 [INF] Evaluting claims for ubcmain\robert.bleattler, Cache: True
2022-02-28 16:44:25.043 -06:00 [DBG] The request path /api/internal/dashboard does not match a supported file type
2022-02-28 16:44:25.043 -06:00 [DBG] The request path  does not match the path filter
2022-02-28 16:44:25.043 -06:00 [DBG] 1 candidate(s) found for the request path '/api/internal/dashboard'
2022-02-28 16:44:25.043 -06:00 [DBG] Endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)' with route pattern 'api/internal/dashboard' is valid for the request path '/api/internal/dashboard'
2022-02-28 16:44:25.043 -06:00 [DBG] Request matched endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)'
2022-02-28 16:44:25.046 -06:00 [INF] Executing endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)'
2022-02-28 16:44:25.046 -06:00 [INF] Route matched with {action = "Index", controller = "UDDashboard"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Index() on controller UniversalDashboard.Controllers.UDDashboardController (Universal.Server).
2022-02-28 16:44:25.046 -06:00 [DBG] Execution plan of authorization filters (in the following order): ["None"]
2022-02-28 16:44:25.046 -06:00 [DBG] Execution plan of resource filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"]
2022-02-28 16:44:25.046 -06: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)","Microsoft.AspNetCore.Mvc.Filters.ResponseCacheFilter"]
2022-02-28 16:44:25.046 -06:00 [DBG] Execution plan of exception filters (in the following order): ["None"]
2022-02-28 16:44:25.046 -06:00 [DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter","PowerShellUniversal.GenerateAntiforgeryTokenCookieAttribute (Order: 0)"]
2022-02-28 16:44:25.046 -06:00 [DBG] Executing controller factory for controller UniversalDashboard.Controllers.UDDashboardController (Universal.Server)
2022-02-28 16:44:25.046 -06:00 [DBG] Executed controller factory for controller UniversalDashboard.Controllers.UDDashboardController (Universal.Server)
2022-02-28 16:44:25.046 -06:00 [DBG] Session loaded; Key:1e8412e9-4656-9143-79a3-bd807ee8f70d, Id:af54e455-dca4-5d2e-4db0-da37d1737c77, Count:1
2022-02-28 16:44:25.047 -06:00 [DBG] An antiforgery cookie token was reused.
2022-02-28 16:44:25.047 -06:00 [INF] Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
2022-02-28 16:44:25.047 -06:00 [DBG] No response compression available for HTTPS requests. See ResponseCompressionOptions.EnableForHttps.
2022-02-28 16:44:25.047 -06:00 [INF] Executed action UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server) in 1.2072ms
2022-02-28 16:44:25.048 -06:00 [INF] Executed endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)'
2022-02-28 16:44:25.048 -06:00 [INF] Request finished HTTP/1.1 GET https://MyServerUrl.com/api/internal/dashboard - - - 200 10 text/plain;+charset=utf-8 8.1640ms
2022-02-28 16:44:25.103 -06:00 [INF] Request starting HTTP/1.1 GET https://MyServerUrl.com/api/internal/dashboard - -
2022-02-28 16:44:25.107 -06:00 [INF] Evaluting claims for ubcmain\robert.bleattler, Cache: True
2022-02-28 16:44:25.108 -06:00 [DBG] The request path /api/internal/dashboard does not match a supported file type
2022-02-28 16:44:25.108 -06:00 [DBG] The request path  does not match the path filter
2022-02-28 16:44:25.108 -06:00 [DBG] 1 candidate(s) found for the request path '/api/internal/dashboard'
2022-02-28 16:44:25.108 -06:00 [DBG] Endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)' with route pattern 'api/internal/dashboard' is valid for the request path '/api/internal/dashboard'
2022-02-28 16:44:25.108 -06:00 [DBG] Request matched endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)'
2022-02-28 16:44:25.110 -06:00 [INF] Executing endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)'
2022-02-28 16:44:25.111 -06:00 [INF] Route matched with {action = "Index", controller = "UDDashboard"}. Executing controller action with signature System.Threading.Tasks.Task`1[Microsoft.AspNetCore.Mvc.IActionResult] Index() on controller UniversalDashboard.Controllers.UDDashboardController (Universal.Server).
2022-02-28 16:44:25.111 -06:00 [DBG] Execution plan of authorization filters (in the following order): ["None"]
2022-02-28 16:44:25.111 -06:00 [DBG] Execution plan of resource filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter"]
2022-02-28 16:44:25.111 -06: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)","Microsoft.AspNetCore.Mvc.Filters.ResponseCacheFilter"]
2022-02-28 16:44:25.111 -06:00 [DBG] Execution plan of exception filters (in the following order): ["None"]
2022-02-28 16:44:25.111 -06:00 [DBG] Execution plan of result filters (in the following order): ["Microsoft.AspNetCore.Mvc.ViewFeatures.Filters.SaveTempDataFilter","PowerShellUniversal.GenerateAntiforgeryTokenCookieAttribute (Order: 0)"]
2022-02-28 16:44:25.111 -06:00 [DBG] Executing controller factory for controller UniversalDashboard.Controllers.UDDashboardController (Universal.Server)
2022-02-28 16:44:25.111 -06:00 [DBG] Executed controller factory for controller UniversalDashboard.Controllers.UDDashboardController (Universal.Server)
2022-02-28 16:44:25.111 -06:00 [DBG] Session loaded; Key:1e8412e9-4656-9143-79a3-bd807ee8f70d, Id:af54e455-dca4-5d2e-4db0-da37d1737c77, Count:1
2022-02-28 16:44:25.112 -06:00 [DBG] An antiforgery cookie token was reused.
2022-02-28 16:44:25.112 -06:00 [INF] Executing ContentResult with HTTP Response ContentType of text/plain; charset=utf-8
2022-02-28 16:44:25.112 -06:00 [DBG] No response compression available for HTTPS requests. See ResponseCompressionOptions.EnableForHttps.
2022-02-28 16:44:25.112 -06:00 [INF] Executed action UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server) in 1.3482ms
2022-02-28 16:44:25.112 -06:00 [INF] Executed endpoint 'UniversalDashboard.Controllers.UDDashboardController.Index (Universal.Server)'
2022-02-28 16:44:25.113 -06:00 [INF] Request finished HTTP/1.1 GET https://MyServerUrl.com/api/internal/dashboard - - - 200 10 text/plain;+charset=utf-8 9.3551ms
2022-02-28 16:44:25.824 -06:00 [INF] Executed action UniversalDashboard.Controllers.SessionController.Index (Universal.Server) in 2031.7037ms
2022-02-28 16:44:25.825 -06:00 [INF] Executed endpoint 'UniversalDashboard.Controllers.SessionController.Index (Universal.Server)'
2022-02-28 16:44:25.825 -06:00 [ERR] An unhandled exception has occurred while executing the request.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="failed to connect to all addresses", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646088265.823000000","description":"Failed to pick subchannel","file":"..\..\..\src\core\ext\filters\client_channel\client_channel.cc","file_line":3009,"referenced_errors":[{"created":"@1646088265.823000000","description":"failed to connect to all addresses","file":"..\..\..\src\core\ext\filters\client_channel\lb_policy\pick_first\pick_first.cc","file_line":398,"grpc_status":14}]}")
   at Universal.Server.Services.DashboardProxy.SessionExists(String sessionId) in D:\a\universal\universal\src\Universal.Server\Services\Dashboard\DashboardProxy.cs:line 333
   at UniversalDashboard.Controllers.SessionController.Index(String sessionId) in D:\a\universal\universal\src\Universal.Server\Controllers\SessionController.cs:line 59
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 134
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 42
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
2022-02-28 16:44:25.828 -06:00 [DBG] The request path /Error does not match a supported file type
2022-02-28 16:44:25.828 -06:00 [DBG] The request path  does not match the path filter
2022-02-28 16:44:25.828 -06:00 [DBG] No candidates found for the request path '/Error'
2022-02-28 16:44:25.828 -06:00 [DBG] Request did not match any endpoints
2022-02-28 16:44:25.830 -06:00 [WRN] No exception handler was found, rethrowing original exception.
2022-02-28 16:44:25.830 -06:00 [ERR] Connection ID "17942340929939570744", Request ID "8000003c-0003-f900-b63f-84710c7967bb": An unhandled exception was thrown by the application.
Grpc.Core.RpcException: Status(StatusCode="Unavailable", Detail="failed to connect to all addresses", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646088265.823000000","description":"Failed to pick subchannel","file":"..\..\..\src\core\ext\filters\client_channel\client_channel.cc","file_line":3009,"referenced_errors":[{"created":"@1646088265.823000000","description":"failed to connect to all addresses","file":"..\..\..\src\core\ext\filters\client_channel\lb_policy\pick_first\pick_first.cc","file_line":398,"grpc_status":14}]}")
   at Universal.Server.Services.DashboardProxy.SessionExists(String sessionId) in D:\a\universal\universal\src\Universal.Server\Services\Dashboard\DashboardProxy.cs:line 333
   at UniversalDashboard.Controllers.SessionController.Index(String sessionId) in D:\a\universal\universal\src\Universal.Server\Controllers\SessionController.cs:line 59
   at Microsoft.AspNetCore.Mvc.Infrastructure.ActionMethodExecutor.TaskOfIActionResultExecutor.Execute(IActionResultTypeMapper mapper, ObjectMethodExecutor executor, Object controller, Object[] arguments)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeActionMethodAsync>g__Awaited|12_0(ControllerActionInvoker invoker, ValueTask`1 actionResultValueTask)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeNextActionFilterAsync>g__Awaited|10_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Rethrow(ActionExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker.<InvokeInnerFilterAsync>g__Awaited|13_0(ControllerActionInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeNextResourceFilter>g__Awaited|24_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Rethrow(ResourceExecutedContextSealed context)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.Next(State& next, Scope& scope, Object& state, Boolean& isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeFilterPipelineAsync>g__Awaited|19_0(ResourceInvoker invoker, Task lastTask, State next, Scope scope, Object state, Boolean isCompleted)
   at Microsoft.AspNetCore.Mvc.Infrastructure.ResourceInvoker.<InvokeAsync>g__Logged|17_1(ResourceInvoker invoker)
   at Microsoft.AspNetCore.Routing.EndpointMiddleware.<Invoke>g__AwaitRequestTask|6_0(Endpoint endpoint, Task requestTask, ILogger logger)
   at Microsoft.AspNetCore.Authorization.AuthorizationMiddleware.Invoke(HttpContext context)
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 134
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 42
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.HandleException(HttpContext context, ExceptionDispatchInfo edi)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Builder.Extensions.MapMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync()
2022-02-28 16:44:25.833 -06:00 [INF] Request finished HTTP/1.1 GET https://MyServerUrl.com/api/internal/session/211f8845-a2cd-4598-a3f2-b6c6dca3fe6d - - - 500 - - 2049.8564ms
2022-02-28 16:44:31.042 -06:00 [INF] Request starting HTTP/1.1 GET https://MyServerUrl.com/api/internal/dashboard - -
2022-02-28 16:44:31.044 -06:00 [INF] Evaluting claims for ubcmain\robert.bleattler, Cache: True
2022-02-28 16:44:31.045 -06:00 [DBG] The request path /api/internal/dashboard does not match a supported file type
2022-02-28 16:44:31.045 -06:00 [DBG] The request path  does not match the path filter
2022-02-28 16:44:31.045 -06:00 [DBG] 1 candidate(s) found for the request path '/api/internal/dashboard'

adam · February 28, 2022, 11:23pm

Stream Removed typically means the external process crashed. Can you check event log to see if you have any .NET Application crashes related to PowerShell?

rbleattler · February 28, 2022, 11:31pm

Yep a whole bunch. But I think I found at least part of the problem. I had New-UDColumn called with the -EndPoint block, switching that to a -Content block got the dashboard at least loading. Still some issues but one step closer!

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name="Windows Error Reporting" /> 
  <EventID Qualifiers="0">1001</EventID> 
  <Level>4</Level> 
  <Task>0</Task> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2022-02-28T23:08:29.559584400Z" /> 
  <EventRecordID>42176</EventRecordID> 
  <Channel>Application</Channel> 
  <Computer>LXA-DEVOPS-UA.UBCMAIN.com</Computer> 
  <Security /> 
  </System>
- <EventData>
  <Data>1502029414158184776</Data> 
  <Data>4</Data> 
  <Data>APPCRASH</Data> 
  <Data>Not available</Data> 
  <Data>0</Data> 
  <Data>pwsh.exe</Data> 
  <Data>7.2.1.500</Data> 
  <Data>61735063</Data> 
  <Data>StackHash_2264</Data> 
  <Data>0.0.0.0</Data> 
  <Data>00000000</Data> 
  <Data>c00000fd</Data> 
  <Data>PCH_49</Data> 
  <Data /> 
  <Data /> 
  <Data>\\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER35D7.tmp.dmp \\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER5806.tmp.WERInternalMetadata.xml \\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER5827.tmp.xml \\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER5825.tmp.csv \\?\C:\ProgramData\Microsoft\Windows\WER\Temp\WER5845.tmp.txt</Data> 
  <Data>\\?\C:\ProgramData\Microsoft\Windows\WER\ReportArchive\AppCrash_pwsh.exe_78bb21d098cf3638c51fb028d6169687823dc98c_9329b50a_04545b90</Data> 
  <Data /> 
  <Data>0</Data> 
  <Data>83f12d0c-5d62-4fef-8d9d-c3d1a3f9e39e</Data> 
  <Data>268435456</Data> 
  <Data>0da39bb92239cfdac4d847cb49163148</Data> 
  <Data>0</Data> 
  </EventData>
  </Event>

adam · March 1, 2022, 12:22am

Are there any events around that one that provide a .NET stack at all?

The only crash I’ve noticed recently was happening when using Select-Object and it was causing a Stack Overflow exception that would bring down the PS process. I didn’t manage to record the repro steps and I haven’t been able to reproduce it since. I do know that it was happening by some infinite loop in the serialization code.

rbleattler · March 1, 2022, 4:59pm

Of all the various errors popping up, I don’t see very many that have stack traces. There are a couple that are definitely related to Universal, as they refer to w3wp and there is no other web app or site deployed on this server:

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name=".NET Runtime" /> 
  <EventID Qualifiers="0">1026</EventID> 
  <Level>2</Level> 
  <Task>0</Task> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2022-02-28T20:13:06.980093300Z" /> 
  <EventRecordID>42153</EventRecordID> 
  <Channel>Application</Channel> 
  <Computer>MyServer.com</Computer> 
  <Security /> 
  </System>
- <EventData>
  <Data>Application: w3wp.exe CoreCLR Version: 5.0.921.35908 .NET Version: 5.0.9 Description: The process was terminated due to an unhandled exception. Exception Info: System.AggregateException: One or more hosted services failed to stop. (One or more errors occurred. (The handle is invalid.)) ---> System.AggregateException: One or more errors occurred. (The handle is invalid.) ---> System.IO.IOException: The handle is invalid. at System.ConsolePal.WindowsConsoleStream.Write(Byte[] buffer, Int32 offset, Int32 count) at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder) at System.IO.StreamWriter.WriteLine(String value) at System.IO.TextWriter.SyncTextWriter.WriteLine(String value) at Hangfire.Logging.LogProviders.ColouredConsoleLogProvider.ColouredConsoleLogger.Write(LogLevel logLevel, String message, Exception e) at Hangfire.Logging.LogProviders.ColouredConsoleLogProvider.ColouredConsoleLogger.Log(LogLevel logLevel, Func`1 messageFunc, Exception exception) at Hangfire.Logging.LogExtensions.Info(ILog logger, String message) at Hangfire.Server.BackgroundServerProcess.<>c__DisplayClass6_0.<Execute>g__HandleStoppingSignal|1() at System.Threading.CancellationToken.<>c.<.cctor>b__26_0(Object obj) at System.Threading.CancellationTokenSource.CallbackNode.<>c.<ExecuteCallback>b__9_0(Object s) at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state) --- End of stack trace from previous location --- at System.Threading.CancellationTokenSource.CallbackNode.ExecuteCallback() at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException) --- End of inner exception stack trace --- at System.Threading.CancellationTokenSource.ExecuteCallbackHandlers(Boolean throwOnFirstException) at System.Threading.CancellationTokenSource.NotifyCancellation(Boolean throwOnFirstException) at System.Threading.CancellationTokenSource.Cancel() at Hangfire.Server.BackgroundProcessingServer.SendStop() at Hangfire.BackgroundJobServer.SendStop() at Hangfire.BackgroundJobServerHostedService.StopAsync(CancellationToken cancellationToken) at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken) --- End of inner exception stack trace --- at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.WaitForShutdownAsync(IHost host, CancellationToken token) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.Run(IHost host) at Universal.Server.Program.<>c__DisplayClass3_0.<Main>b__0(Options o) in D:\a\universal\universal\src\Universal.Server\Program.cs:line 63 at CommandLine.ParserResultExtensions.WithParsed[T](ParserResult`1 result, Action`1 action) at Universal.Server.Program.Main(String[] args) in D:\a\universal\universal\src\Universal.Server\Program.cs:line 45</Data> 
  </EventData>
  </Event>

<Event xmlns="http://schemas.microsoft.com/win/2004/08/events/event">
- <System>
  <Provider Name=".NET Runtime" /> 
  <EventID Qualifiers="0">1026</EventID> 
  <Level>2</Level> 
  <Task>0</Task> 
  <Keywords>0x80000000000000</Keywords> 
  <TimeCreated SystemTime="2022-02-28T21:45:04.525397000Z" /> 
  <EventRecordID>42161</EventRecordID> 
  <Channel>Application</Channel> 
  <Computer>MyServer.com</Computer> 
  <Security /> 
  </System>
- <EventData>
  <Data>Application: w3wp.exe CoreCLR Version: 5.0.921.35908 .NET Version: 5.0.9 Description: The process was terminated due to an unhandled exception. Exception Info: System.AggregateException: One or more hosted services failed to stop. (The operation was canceled.) ---> System.OperationCanceledException: The operation was canceled. at System.Threading.CancellationToken.ThrowOperationCanceledException() at Hangfire.Processing.TaskExtensions.WaitOneAsync(WaitHandle waitHandle, TimeSpan timeout, CancellationToken token) at Hangfire.Processing.BackgroundDispatcher.WaitAsync(TimeSpan timeout, CancellationToken cancellationToken) at Hangfire.Server.BackgroundProcessingServer.WaitForShutdownAsync(CancellationToken cancellationToken) at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken) --- End of inner exception stack trace --- at Microsoft.Extensions.Hosting.Internal.Host.StopAsync(CancellationToken cancellationToken) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.WaitForShutdownAsync(IHost host, CancellationToken token) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.RunAsync(IHost host, CancellationToken token) at Microsoft.Extensions.Hosting.HostingAbstractionsHostExtensions.Run(IHost host) at Universal.Server.Program.<>c__DisplayClass3_0.<Main>b__0(Options o) in D:\a\universal\universal\src\Universal.Server\Program.cs:line 63 at CommandLine.ParserResultExtensions.WithParsed[T](ParserResult`1 result, Action`1 action) at Universal.Server.Program.Main(String[] args) in D:\a\universal\universal\src\Universal.Server\Program.cs:line 45</Data> 
  </EventData>
  </Event>```

rbleattler · March 1, 2022, 6:38pm

I will note that something I’m seeing is runaway RAM usage in an API PowerShell process. I’m not really sure why but it is definitely pretty serious. I’m not really sure what it is, only that its after a lot of or very large API requests. This is receiving large chunks of JSON, converting to objects, then dumping into a SQLite DB to later sync to a SQL DB (wanted to avoid the overhead of directly connecting to the SQL server which lives on a different server than PSU).

NOTE: Today I added some manual garbage collection calls, which seems to be helping. I’ll let you know if it spirals out of control again though.

rbleattler · March 2, 2022, 12:47pm

NOTE: Today I added some manual garbage collection calls, which seems to be helping. I’ll let you know if it spirals out of control again though.

It looks like this is not the case, as the process still goes crazy. I’m trying to identify where the problem is but as of right now I can’t identify it.

It looks like the API re-uses the same process for API calls within a timeframe. Does it spawn jobs or child run-spaces to do so? If so, is it supposed to dispose of those jobs or run-spaces? It seems like it may not be doing it. After a while the process is using a ton of memory (from ProcExp64 below)

Process     CPU     Private Bytes   Working Set     PID 
pwsh.exe	5.45	22,434,168 K	13,182,928 K	3716

The output in the PSU Logs:

2022-03-02 06:32:23.525 -06:00 [INF] Request starting HTTP/1.1 POST https://MyServerUrl/iis/logs/clibulkadd text/plain;+charset=utf-8 1327471
2022-03-02 06:32:23.526 -06:00 [DBG] No response compression available, the Accept-Encoding header is missing or invalid.
2022-03-02 06:32:23.526 -06:00 [DBG] POST requests are not supported
2022-03-02 06:32:23.526 -06:00 [DBG] POST requests are not supported
2022-03-02 06:32:23.526 -06:00 [DBG] No candidates found for the request path '/iis/logs/clibulkadd'
2022-03-02 06:32:23.526 -06:00 [DBG] Request did not match any endpoints
2022-03-02 06:32:23.530 -06:00 [DBG] Authenticating with JWT
2022-03-02 06:32:23.530 -06:00 [INF] Successfully validated the token.
2022-03-02 06:32:23.530 -06:00 [DBG] AuthenticationScheme: Bearer was successfully authenticated.
2022-03-02 06:32:23.531 -06:00 [INF] Evaluting claims for USER, Cache: True
2022-03-02 06:32:23.531 -06:00 [DBG] Successful authentication.
2022-03-02 06:32:53.447 -06:00 [DBG] Connection ID "18158513707758389037" disconnecting.
2022-03-02 06:32:53.449 -06:00 [ERR] An unhandled exception has occurred while executing the request.
Grpc.Core.RpcException: Status(StatusCode="Cancelled", Detail="Cancelled", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646224373.448000000","description":"Error received from peer ipv6:[::1]:51196","file":"..\..\..\src\core\lib\surface\call.cc","file_line":1067,"grpc_message":"Cancelled","grpc_status":1}")
   at Universal.Server.Services.ApiGrpc.ExecuteAsync(apiRequest request, CancellationToken cancellationToken) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiGrpc.cs:line 150
   at Universal.Server.Services.ApiService.ExecuteAsync(HttpContext httpContext) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiService.cs:line 323
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 79
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 42
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
2022-03-02 06:32:53.451 -06:00 [DBG] POST requests are not supported
2022-03-02 06:32:53.451 -06:00 [DBG] POST requests are not supported
2022-03-02 06:32:53.451 -06:00 [DBG] No candidates found for the request path '/Error'
2022-03-02 06:32:53.451 -06:00 [DBG] Request did not match any endpoints
2022-03-02 06:32:53.452 -06:00 [WRN] No exception handler was found, rethrowing original exception.
2022-03-02 06:32:53.453 -06:00 [ERR] Connection ID "18158513707758389037", Request ID "8000072e-0002-fc00-b63f-84710c7967bb": An unhandled exception was thrown by the application.
Grpc.Core.RpcException: Status(StatusCode="Cancelled", Detail="Cancelled", DebugException="Grpc.Core.Internal.CoreErrorDetailException: {"created":"@1646224373.448000000","description":"Error received from peer ipv6:[::1]:51196","file":"..\..\..\src\core\lib\surface\call.cc","file_line":1067,"grpc_message":"Cancelled","grpc_status":1}")
   at Universal.Server.Services.ApiGrpc.ExecuteAsync(apiRequest request, CancellationToken cancellationToken) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiGrpc.cs:line 150
   at Universal.Server.Services.ApiService.ExecuteAsync(HttpContext httpContext) in D:\a\universal\universal\src\Universal.Server\Services\API\ApiService.cs:line 323
   at Universal.Server.Middleware.RoutingMiddleware.Invoke(HttpContext httpContext, IPolicyEvaluator policyEvaluator) in D:\a\universal\universal\src\Universal.Server\Middleware\RoutingMiddleware.cs:line 79
   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 D:\a\universal\universal\src\Universal.Server\Middleware\SwaggerAuthMiddleware.cs:line 42
   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 D:\a\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.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.HandleException(HttpContext context, ExceptionDispatchInfo edi)
   at Microsoft.AspNetCore.Diagnostics.ExceptionHandlerMiddleware.<Invoke>g__Awaited|6_0(ExceptionHandlerMiddleware middleware, HttpContext context, Task task)
   at Microsoft.AspNetCore.Diagnostics.StatusCodePagesMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.ResponseCompression.ResponseCompressionMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Builder.Extensions.MapMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Authentication.AuthenticationMiddleware.Invoke(HttpContext context)
   at Microsoft.AspNetCore.Server.IIS.Core.IISHttpContextOfT`1.ProcessRequestAsync()
2022-03-02 06:32:53.455 -06:00 [INF] Request finished HTTP/1.1 POST https://MyServerUrl/iis/logs/clibulkadd text/plain;+charset=utf-8 1327471 - 0 - - 29929.2765ms

rbleattler · March 2, 2022, 1:00pm

@adam

Digging around the (still active) process to try to find what the issue is… I can’t seem to pinpoint what the big issue is, but I did just discover that when I try to access https://MyServer.com/hangfire, I get a 500 error. I wonder if the hangfire process is dying and never coming back up at some point…

adam · March 2, 2022, 4:03pm

Can you collect some stuff for me? I need a log to see what the 500 hangfire error is. Hangfire is the scheduling component and I’ve never seen it throw an exception when trying to view the dashboard for it.

I’ll also like a memory dump of the runaway pwsh process to see what’s consuming so much memory. That will help us narrow it down. Are you using dbatools for SQL access? We were working with that team a bit because they had a memory leak that was popping up due to how PSU retains runspaces.

You can upload the memory dump here: Dropbox - Submit files

Another thing we added in 2.8 was the ability to turn on runspace recycling. This can help with memory issues as it will dispose of runspaces after a certain amount of uses or time to try to free up resources. This isn’t a golden ticket because sometimes modules won’t clean up managed resources properly so they are still allocated even after the runspace is disposed (as was the problem with dbatools).

rbleattler · March 2, 2022, 6:13pm

I restarted IIS, and was watching the log. I am seeing :

2022-03-02 07:13:52.279 -06:00 [DBG] Considering key <GUID> with expiration date 2022-04-02 00:12:58Z as default key.
2022-03-02 07:13:52.291 -06:00 [DBG] Forwarded activator type request from Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor, Microsoft.AspNetCore.DataProtection, Version=5.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.XmlEncryption.DpapiXmlDecryptor, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
2022-03-02 07:13:52.293 -06:00 [DBG] Decrypting secret element using Windows DPAPI.
2022-03-02 07:13:52.294 -06:00 [DBG] Forwarded activator type request from Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Version=5.0.0.0, Culture=neutral, PublicKeyToken=adb9793829ddae60 to Microsoft.AspNetCore.DataProtection.AuthenticatedEncryption.ConfigurationModel.AuthenticatedEncryptorDescriptorDeserializer, Microsoft.AspNetCore.DataProtection, Culture=neutral, PublicKeyToken=adb9793829ddae60
2022-03-02 07:13:52.298 -06:00 [DBG] Opening CNG algorithm 'AES' from provider 'null' with chaining mode CBC.
2022-03-02 07:13:52.301 -06:00 [DBG] Opening CNG algorithm 'SHA256' from provider 'null' with HMAC.
2022-03-02 07:13:52.304 -06:00 [DBG] Using key {4045c147-3b11-408c-880f-eb070ca0522a} as the default key.
2022-03-02 07:13:52.305 -06:00 [DBG] Key ring with default key <GUID> was loaded during application startup.
2022-03-02 07:13:53.014 -06:00 [ERR] Error registering vault PSUSecretStore
2022-03-02 07:13:53.014 -06:00 [ERR] Exception:
System.Management.Automation.ParentContainsErrorRecordException: Cannot bind parameter 'PasswordTimeout'. Cannot convert the "System.Security.SecureString" value of type "System.Security.SecureString" to type "System.Int32".

I noticed I’d never set up the PSUSecretStore password in appsettings.json (though I also don’t recall doing this before). Upon checking the password does align with a Secret Store previously created. I changed the setting in appsettings, and still see that error on startup. I haven’t seen any issues related to it that I’m aware of… but I’m not entirely sure.

RE: Uploading a memory dump, I can try to run this on a lower environment to replicate the issue. I tried to get one for you this morning, but the dump was going to be absolutely massive – and I needed to get back to building this thing.

I’ll definitely be taking your advice on implementing runspace recycling. I thought Garbage Collection was going to be the Golden Ticket… but alas here we are.

@adam if at any point it makes sense, I’m happy to get in a teams/discord/slack call to dig in and screen share as well.

rbleattler · March 3, 2022, 1:25pm

@adam, I created a memory dump last night when the process was running wild. Unfortunately, without compression it’s far too large to submit using Dropbox File Request. Its uploading now, compressed with 7zip (LZMA 2 Compression) down to ~900MB.

As a reference, I have a scheduled job that is meant to run at 5am to process all the data from my temporary (sqlite) db and add it to our production db. I noticed the job failed, and shows this in the admin dash.

If you need anything else, I have logging set to debug at all levels, and can grab a log bundle for you as well.

adam · March 3, 2022, 2:53pm

It looks like there are 10k PSVariables in your process that are accounting for a lot of the memory.

Looking at the top memory users, there is a UCJL variable that is repeated and uses about 30MB every time. I can’t view the data but it’s a string.

There aren’t too many runspaces.

There are almost 1 million ArrayLists allocated. Here’s a sample of what’s in them.

Digging around a bit more I noticed this endpoint for example is currently running:

${UA.RepositoryRoot.ExternalEndPoints}\iis\logs\clibulkadd.ps1

What does that script do? I’m also open to a call to chat about this more. Let me know if you have any time tomorrow or next week.

rbleattler · March 3, 2022, 3:22pm

@Adam I can make time tomorrow. My only blocking hour right now is ~11am-12pm EST, then ~3:50-4:15 EST.

That endpoint is receiving and deserializing data to be parsed and added to the db. What’s odd is those variables are supposed to be getting cleaned up explicitly, because I know how heavy strings are in memory.

adam · March 3, 2022, 4:02pm

Works for me. Feel free to email me at adam@ironmansoftware.com to put something on my calendar. I’m free anytime except 9-10 AM MST.

Topic		Replies	Views
Multiple Grpc.Core errors PowerShell Universal	0	32	October 23, 2024
Grpc.Core.Server errors in my job output PowerShell Universal	4	237	April 19, 2024
Endpoints sometimes fails with 500 Servererror PowerShell Universal	2	222	January 4, 2023
Invalid configuration: dashboards.ps1 PowerShell Universal	2	467	September 24, 2021
Loads of errors with Endpoints in 5.0.12 (and 5.0.13) PowerShell Universal	13	126	October 25, 2024

GRPC issues between servers

Related topics