Unexpected timeout from process

[maciejsobocinski]

Hi,

We have dotnetmonitor set up on ECS Fargate. Running in listen mode collecting metrics every X. Our set up is a single dotnetmonitor side car inside each launched task with many tasks being launched. It stops working for us on some tasks after a few hours with the following error:

{
    "Timestamp": "2022-04-15T06:50:03.0758604Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 6. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 6. Process will no longer be monitored.",
        "processId": "6",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

Then all subsequent requests get this error:

{
    "Timestamp": "2022-04-15T06:55:01.6363199Z",
    "EventId": 1,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController",
    "Message": "Request failed.",
    "Exception": "System.ArgumentException: Unable to discover a target process.    at Microsoft.Diagnostics.Monitoring.WebApi.DiagnosticServices.GetProcessAsync(DiagProcessFilter processFilterConfig, CancellationToken token) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/DiagnosticServices.cs:line 100    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.<>c__DisplayClass33_0`1.<<InvokeForProcess>b__0>d.MoveNext() in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagController.cs:line 713 --- End of stack trace from previous location ---    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagControllerExtensions.InvokeService[T](ControllerBase controller, Func`1 serviceCall, ILogger logger) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagControllerExtensions.cs:line 91",
    "State": {
        "Message": "Request failed.",
        "{OriginalFormat}": "Request failed."
    },
    "Scopes": [
        {
            "Message": "SpanId:5f73f4ec6a4c2a06, TraceId:6e3bec22534dca3eed9ae13c8150dc0c, ParentId:0d6726492bd0e999",
            "SpanId": "5f73f4ec6a4c2a06",
            "TraceId": "6e3bec22534dca3eed9ae13c8150dc0c",
            "ParentId": "0d6726492bd0e999"
        },
        {
            "Message": "ConnectionId:0HMGU731FOFDF",
            "ConnectionId": "0HMGU731FOFDF"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMGU731FOFDF:00000002",
            "RequestId": "0HMGU731FOFDF:00000002",
            "RequestPath": "/livemetrics"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "cc79e4d4-794e-481f-8083-fb3f3c7b5ca5",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:livemetrics",
            "ArtifactType": "livemetrics"
        }
    ]
}

Note the main container itself keeps on working just fine and is processing requests without any issues. Per metrics captured before the error I do not see any abnormal memory/cpu/etc usage compared to the other tasks where dotnet-monitor keeps on working.

Here is our ecs task definition (the dotnetmonitor config values are under 'Environment'):

  TaskDefinition:
    Type: AWS::ECS::TaskDefinition
    Properties:
      Cpu: !Ref TaskCpu
      Memory: !Ref TaskMemory
      NetworkMode: awsvpc
      ExecutionRoleArn: !Sub "arn:aws:iam::${AWS::AccountId}:role/ecsTaskExecutionRole"
      TaskRoleArn: !ImportValue AppServicesEcsTaskRoleArn
      RequiresCompatibilities:
        - FARGATE
      Volumes:
        - Name: tmp
      ContainerDefinitions:
        - Essential: true
          Name: appservices
          Image:
            !Sub
              - "${repository}:${image}"
              - repository: !ImportValue AppServicesEcrRepository
                image: !Ref TaskEcrImageTag
          Ulimits:
            - Name: nofile
              HardLimit: 65535
              SoftLimit: 65535
          PortMappings:
            - ContainerPort: 44392
              Protocol: tcp
          LogConfiguration:
            LogDriver: awslogs
            Options:
              awslogs-group: !ImportValue AppServicesEcsLogGroup
              awslogs-region: !Ref AWS::Region
              awslogs-stream-prefix: !Ref EnvironmentName
          LinuxParameters:
            InitProcessEnabled: true
            Capabilities:
              Add:
                - SYS_PTRACE
          StopTimeout: 120
          MountPoints:
            - ContainerPath: /tmp
              SourceVolume: tmp
          Environment:
            - Name: DOTNET_DiagnosticPorts
              Value: /tmp/port
          DependsOn:
            - ContainerName: dotnet-monitor
              Condition: START
        - Essential: true
          Name: dotnet-monitor
          Image:
            !Sub
            - "${repository}:${image}-dotnetmonitor"
            - repository: !ImportValue AppServicesEcrRepository
              image: !Ref TaskEcrImageTag
          MountPoints:
            - ContainerPath: /tmp
              SourceVolume: tmp
          Environment:
            - Name: Kestrel__Certificates__Default__Path
              Value: /tmp/cert.pfx
            - Name: DotnetMonitor_S3Bucket
              Value: !Sub '{{resolve:ssm:/appservices/${EnvironmentName}/integration.bulk.s3.bucket:1}}'
            - Name: DotnetMonitor_DefaultProcess__Filters__0__Key
              Value: ProcessName
            - Name: DotnetMonitor_DefaultProcess__Filters__0__Value
              Value: dotnet
            - Name: DotnetMonitor_DiagnosticPort__ConnectionMode
              Value: Listen
            - Name: DotnetMonitor_DiagnosticPort__EndpointName
              Value: /tmp/port
            - Name: DotnetMonitor_Storage__DumpTempFolder
              Value: /tmp
            - Name: DotnetMonitor_Egress__FileSystem__file__directoryPath
              Value: /tmp/gcdump
            - Name: DotnetMonitor_Egress__FileSystem__file__intermediateDirectoryPath
              Value: /tmp/gcdumptmp
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Trigger__Type
              Value: EventCounter
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Trigger__Settings__ProviderName
              Value: System.Runtime
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Trigger__Settings__CounterName
              Value: working-set
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Trigger__Settings__GreaterThan
              Value: !Ref TaskMemoryAutoGCDump
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Trigger__Settings__SlidingWindowDuration
              Value: 00:00:05
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Actions__0__Type
              Value: CollectGCDump
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Actions__0__Name
              Value: GCDump
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Actions__0__Settings__Egress
              Value: file
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Actions__1__Type
              Value: Execute
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Actions__1__Settings__Path
              Value: /bin/sh
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Actions__1__Settings__Arguments
              Value: /app/gcdump.sh $(Actions.GCDump.EgressPath)
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Limits__ActionCount
              Value: 1
            - Name: DotnetMonitor_CollectionRules__HighMemoryRule__Limits__ActionCountSlidingWindowDuration
              Value: 03:00:00
          Secrets:
            - Name: DotnetMonitor_Authentication__MonitorApiKey__Subject
              ValueFrom: !Sub "arn:aws:ssm:${AWS::Region}:${AWS::AccountId}:parameter/appservices/${EnvironmentName}/dotnetmonitor.subject"
            - Name: DotnetMonitor_Authentication__MonitorApiKey__PublicKey
              ValueFrom: !Sub "arn:aws:ssm:${AWS::Region}:${AWS::AccountId}:parameter/appservices/${EnvironmentName}/dotnetmonitor.publickey"
          LogConfiguration:
            LogDriver: awslogs
            Options:
              awslogs-group: !ImportValue AppServicesEcsLogGroup
              awslogs-region: !Ref AWS::Region
              awslogs-stream-prefix: !Ref EnvironmentName

And dockerfile to customize the default dotnet monitor container:

FROM mcr.microsoft.com/dotnet/monitor:6

RUN apk add curl && \
    apk add jq && \
    apk add aws-cli && \
    apk add dos2unix

RUN adduser -s /bin/true -u 1000 -D -h /app app \
  && chown -R "app" "/app"

COPY --chown=app:app --chmod=500 gcdump.sh /app/gcdump.sh
RUN dos2unix /app/gcdump.sh

USER app

[maciejsobocinski]

Another update on this. We are also having trouble with the rule above to collect a gc dump when working-set goes above 70%. GC dump work fine for us under low memory usage but under high it "seems like" it takes so long pausing the dotnet process in main container that our load balancer kills the task - health checks are set to 45 seconds of failures to relaunch. Looking at our perf logs during that time memory usage is 6678/8192mb (186mb of that is dotnet monitor) and cpu usage is 1004/2048 (only 1 of that is used by dotnet monitor). The weird thing is per the dotnet-monitor logs below gcdump times out after 3 seconds but it looks like it is still running inside the main container causing time outs/container restart.

Any tips/ideas/guidance on how to capture a gc dump in prod (we are trying to diagnose memory spikes)?

Here are dotnet-monitor logs of the gc dump rule being triggered, timing out in like 3 seconds then for the next minute or so main container requests are timing out/failing (presumably because a gc dump is still running?) and eventually the container(s) get killed by our load balancer:

{
    "Timestamp": "2022-04-19T03:04:46.3862671Z",
    "EventId": 36,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' trigger 'EventCounter' completed.",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' trigger 'EventCounter' completed.",
        "ruleName": "HighMemoryRule",
        "triggerType": "EventCounter",
        "{OriginalFormat}": "Collection rule '{ruleName}' trigger '{triggerType}' completed."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:04:46.5268863Z",
    "EventId": 33,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' action 'CollectGCDump' started.",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' action 'CollectGCDump' started.",
        "ruleName": "HighMemoryRule",
        "actionType": "CollectGCDump",
        "{OriginalFormat}": "Collection rule '{ruleName}' action '{actionType}' started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        },
        {
            "Message": "CollectionRuleActionType:CollectGCDump CollectionRuleActionIndex:0",
            "CollectionRuleActionType": "CollectGCDump",
            "CollectionRuleActionIndex": 0
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:04:46.5665901Z",
    "EventId": 33,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' action 'Execute' started.",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' action 'Execute' started.",
        "ruleName": "HighMemoryRule",
        "actionType": "Execute",
        "{OriginalFormat}": "Collection rule '{ruleName}' action '{actionType}' started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        },
        {
            "Message": "CollectionRuleActionType:Execute CollectionRuleActionIndex:1",
            "CollectionRuleActionType": "Execute",
            "CollectionRuleActionIndex": 1
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:04:49.5671423Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 10. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 10. Process will no longer be monitored.",
        "processId": "10",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}
{
    "Timestamp": "2022-04-19T03:04:49.5714281Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:04:49.5779787Z",
    "EventId": 38,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' action 'CollectGCDump' failed.",
    "Exception": "System.Threading.Tasks.TaskCanceledException: A task was canceled.    at Microsoft.Diagnostics.Tools.Monitor.TaskExtensions.WithCancellation(Task task, CancellationToken token) in /_/src/Tools/dotnet-monitor/TaskExtensions.cs:line 37    at Microsoft.Diagnostics.Tools.Monitor.TaskExtensions.WithCancellation[T](Task`1 task, CancellationToken token) in /_/src/Tools/dotnet-monitor/TaskExtensions.cs:line 48    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.CollectionRuleActionBase`1.WaitForCompletionAsync(CancellationToken token) in /_/src/Tools/dotnet-monitor/CollectionRules/Actions/CollectionRuleActionBase.cs:line 64    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.ActionListExecutor.WaitForCompletion(CollectionRuleContext context, Action startCallback, IDictionary`2 allResults, ICollectionRuleAction action, CollectionRuleActionOptions actionOption, CancellationToken cancellationToken) in /_/src/Tools/dotnet-monitor/CollectionRules/ActionListExecutor.cs:line 160    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.ActionListExecutor.WaitForCompletion(CollectionRuleContext context, Action startCallback, IDictionary`2 allResults, ActionCompletionEntry entry, CancellationToken cancellationToken) in /_/src/Tools/dotnet-monitor/CollectionRules/ActionListExecutor.cs:line 177",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' action 'CollectGCDump' failed.",
        "ruleName": "HighMemoryRule",
        "actionType": "CollectGCDump",
        "{OriginalFormat}": "Collection rule '{ruleName}' action '{actionType}' failed."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        },
        {
            "Message": "CollectionRuleActionType:Execute CollectionRuleActionIndex:1",
            "CollectionRuleActionType": "Execute",
            "CollectionRuleActionIndex": 1
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:04:49.5977629Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Request canceled.",
    "State": {
        "Message": "Request canceled.",
        "{OriginalFormat}": "Request canceled."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        },
        {
            "Message": "CollectionRuleActionType:CollectGCDump CollectionRuleActionIndex:0",
            "CollectionRuleActionType": "CollectGCDump",
            "CollectionRuleActionIndex": 0
        },
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:10 ArtifactSource_RuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "10",
            "ArtifactSource_RuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:04:49.6023431Z",
    "EventId": 38,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' action 'Execute' failed.",
    "Exception": "System.Threading.Tasks.TaskCanceledException: A task was canceled.    at Microsoft.Diagnostics.Tools.Monitor.TaskExtensions.WithCancellation(Task task, CancellationToken token) in /_/src/Tools/dotnet-monitor/TaskExtensions.cs:line 37    at Microsoft.Diagnostics.Tools.Monitor.TaskExtensions.WithCancellation[T](Task`1 task, CancellationToken token) in /_/src/Tools/dotnet-monitor/TaskExtensions.cs:line 48    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.CollectionRuleActionBase`1.WaitForCompletionAsync(CancellationToken token) in /_/src/Tools/dotnet-monitor/CollectionRules/Actions/CollectionRuleActionBase.cs:line 64    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.ActionListExecutor.WaitForCompletion(CollectionRuleContext context, Action startCallback, IDictionary`2 allResults, ICollectionRuleAction action, CollectionRuleActionOptions actionOption, CancellationToken cancellationToken) in /_/src/Tools/dotnet-monitor/CollectionRules/ActionListExecutor.cs:line 160    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.ActionListExecutor.WaitForCompletion(CollectionRuleContext context, Action startCallback, IDictionary`2 allResults, ActionCompletionEntry entry, CancellationToken cancellationToken) in /_/src/Tools/dotnet-monitor/CollectionRules/ActionListExecutor.cs:line 177    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.ActionListExecutor.WaitForCompletion(CollectionRuleContext context, Action startCallback, IDictionary`2 allResults, ActionCompletionEntry entry, CancellationToken cancellationToken) in /_/src/Tools/dotnet-monitor/CollectionRules/ActionListExecutor.cs:line 185    at Microsoft.Diagnostics.Tools.Monitor.CollectionRules.Actions.ActionListExecutor.ExecuteActions(CollectionRuleContext context, Action startCallback, CancellationToken cancellationToken) in /_/src/Tools/dotnet-monitor/CollectionRules/ActionListExecutor.cs:line 77",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' action 'Execute' failed.",
        "ruleName": "HighMemoryRule",
        "actionType": "Execute",
        "{OriginalFormat}": "Collection rule '{ruleName}' action '{actionType}' failed."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        },
        {
            "Message": "CollectionRuleActionType:Execute CollectionRuleActionIndex:1",
            "CollectionRuleActionType": "Execute",
            "CollectionRuleActionIndex": 1
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:04:49.6056195Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:05:34.4132777Z",
    "EventId": 40,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Starting collection rules.",
    "State": {
        "Message": "Starting collection rules.",
        "{OriginalFormat}": "Starting collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:05:34.4137868Z",
    "EventId": 29,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' started.",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' started.",
        "ruleName": "HighMemoryRule",
        "{OriginalFormat}": "Collection rule '{ruleName}' started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:05:34.4142123Z",
    "EventId": 35,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' trigger 'EventCounter' started.",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' trigger 'EventCounter' started.",
        "ruleName": "HighMemoryRule",
        "triggerType": "EventCounter",
        "{OriginalFormat}": "Collection rule '{ruleName}' trigger '{triggerType}' started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1 CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:05:34.4164694Z",
    "EventId": 32,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules started.",
    "State": {
        "Message": "All collection rules started.",
        "{OriginalFormat}": "All collection rules started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:05:58.8419003Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 10. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 10. Process will no longer be monitored.",
        "processId": "10",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}
{
    "Timestamp": "2022-04-19T03:05:58.8422906Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:05:58.8516468Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:10 TargetRuntimeInstanceCookie:1af38edab5774d948ed55b3310dc80d1",
            "TargetProcessId": "10",
            "TargetRuntimeInstanceCookie": "1af38edab5774d948ed55b3310dc80d1"
        }
    ]
}
{
    "Timestamp": "2022-04-19T03:06:09.9610855Z",
    "EventId": 0,
    "LogLevel": "Information",
    "Category": "Microsoft.Hosting.Lifetime",
    "Message": "Application is shutting down...",
    "State": {
        "Message": "Application is shutting down...",
        "{OriginalFormat}": "Application is shutting down..."
    },
    "Scopes": []
}

[maciejsobocinski]

Glancing at the dotnet monitor code if feels like "CheckEndpointAsync" below ends up cancelling the gc dump and rule collection if the process is unresponsive for more than 2.5 seconds (because a gc dump is taking place) then rules are restarted and the same gc dump rule is invoked again (further pausing the runtime)? The first check against operationTrackerService only returns true if a trace or a dump are running...but not a gcdump:

 private async Task<bool> CheckEndpointAsync(EndpointInfo info, CancellationToken token)
        {
            // If a dump operation is in progress, the runtime is likely to not respond to
            // diagnostic requests. Do not check for responsiveness while the dump operation
            // is in progress.
            if (_operationTrackerService?.IsExecutingOperation(info) == true)
            {
                return true;
            }

            using var timeoutSource = new CancellationTokenSource();
            using var linkedSource = CancellationTokenSource.CreateLinkedTokenSource(token, timeoutSource.Token);

            try
            {
                timeoutSource.CancelAfter(PruneWaitForConnectionTimeout);

                await info.Endpoint.WaitForConnectionAsync(linkedSource.Token).ConfigureAwait(false);
            }
            catch (OperationCanceledException) when (timeoutSource.IsCancellationRequested)
            {
                _logger?.EndpointTimeout(info.ProcessId.ToString(System.Globalization.CultureInfo.InvariantCulture));
                return false;
            }
            catch (Exception ex) when (ex is not OperationCanceledException)
            {
                return false;
            }

            return true;
        }

[jander-msft]

@maciejsobocinski, thanks for reporting this and digging into it. Have a few questions for you:

Our set up is a single dotnetmonitor side car inside each launched task with many tasks being launched. It stops working for us on some tasks after a few hours with the following error:

Is this occurring randomly, or only after an impactful operation happens such as capturing a gcdump?

The first check against operationTrackerService only returns true if a trace or a dump are running...but not a gcdump

My understanding is that the diagnostic communication channel should still be viable while a gcdump is being collected. @josalem, do you know if there is some kind of lock that is held while GC data is collected that would prevent the diagnostic communication channel from responding? If this is expected, we can add gcdump operations to the tracking service in dotnet monitor to prevent pruning of the diagnostic connection. However, even with the pruning (which disposes the stream), I would still expect the runtime instance to try to reestablish the diagnostic connection again, which it does not seem to do (or maybe we don't see that because it is still collecting GC data).

[maciejsobocinski]

@jander-msft both I believe. My initial ticket we had 4 tasks (each with it's own dotnet monitor) started up. Every 5 minutes hitting the /livemetrics endpoint . About 12 hrs in dotnet-monitor started failing inside one of them. There was no gc dump ran at the time per the logs (have it set to auto gc dump at 70%) memory usage was around 17% with cpu basically idle. This is the log entry:

{
    "Timestamp": "2022-04-15T06:50:02.0842638Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:be2da2ba85a57e19, TraceId:8bd2f78ca29aec12951eabd01e36a7ef, ParentId:f2394daea1f71aab",
            "SpanId": "be2da2ba85a57e19",
            "TraceId": "8bd2f78ca29aec12951eabd01e36a7ef",
            "ParentId": "f2394daea1f71aab"
        },
        {
            "Message": "ConnectionId:0HMGU731FOFDE",
            "ConnectionId": "0HMGU731FOFDE"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMGU731FOFDE:00000002",
            "RequestId": "0HMGU731FOFDE:00000002",
            "RequestPath": "/livemetrics"
        }
    ]
}

{
    "Timestamp": "2022-04-15T06:50:03.0758604Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 6. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 6. Process will no longer be monitored.",
        "processId": "6",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

subsequent requests to /livemetrics:

{
    "Timestamp": "2022-04-15T06:55:01.6363199Z",
    "EventId": 1,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController",
    "Message": "Request failed.",
    "Exception": "System.ArgumentException: Unable to discover a target process.    at Microsoft.Diagnostics.Monitoring.WebApi.DiagnosticServices.GetProcessAsync(DiagProcessFilter processFilterConfig, CancellationToken token) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/DiagnosticServices.cs:line 100    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.<>c__DisplayClass33_0`1.<<InvokeForProcess>b__0>d.MoveNext() in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagController.cs:line 713 --- End of stack trace from previous location ---    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagControllerExtensions.InvokeService[T](ControllerBase controller, Func`1 serviceCall, ILogger logger) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagControllerExtensions.cs:line 91",
    "State": {
        "Message": "Request failed.",
        "{OriginalFormat}": "Request failed."
    },
    "Scopes": [
        {
            "Message": "SpanId:5f73f4ec6a4c2a06, TraceId:6e3bec22534dca3eed9ae13c8150dc0c, ParentId:0d6726492bd0e999",
            "SpanId": "5f73f4ec6a4c2a06",
            "TraceId": "6e3bec22534dca3eed9ae13c8150dc0c",
            "ParentId": "0d6726492bd0e999"
        },
        {
            "Message": "ConnectionId:0HMGU731FOFDF",
            "ConnectionId": "0HMGU731FOFDF"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMGU731FOFDF:00000002",
            "RequestId": "0HMGU731FOFDF:00000002",
            "RequestPath": "/livemetrics"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "cc79e4d4-794e-481f-8083-fb3f3c7b5ca5",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:livemetrics",
            "ArtifactType": "livemetrics"
        }
    ]
}

At that point I disabled the /livemetrics polling but left the gc dump on 70% working-set in place. 4 days later the rule hit and failed with the 'CollectGCDump' failed/unexpected time out. It happened 3 times across different containers (the ones that failed were killed by our load balancer and restarted) within a few hrs.

[maciejsobocinski]

I was able to somewhat repro this in our dev environment. I manually triggered a gc dump when memory usage was low on the task (660/4096mb). gc dump was successful (unlike in our prod environment where it failed completely trying to do a gc dump with memory at 6678/8192mb) but also got the "Unexpected timeout" and further requests stopped working:

{
    "Timestamp": "2022-04-19T17:29:02.1838974Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:5d0a7651ef64ae52, TraceId:9087c513b99f163bfc5d9ad466a24d1c, ParentId:236c1fd495300808",
            "SpanId": "5d0a7651ef64ae52",
            "TraceId": "9087c513b99f163bfc5d9ad466a24d1c",
            "ParentId": "236c1fd495300808"
        },
        {
            "Message": "ConnectionId:0HMH22ID4PGJD",
            "ConnectionId": "0HMH22ID4PGJD"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH22ID4PGJD:00000002",
            "RequestId": "0HMH22ID4PGJD:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-19T17:29:02.4566427Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
        "processId": "7",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

{
    "Timestamp": "2022-04-19T17:29:02.4612395Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:c1de3bbadd104c679b6258ba69f40d69",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "c1de3bbadd104c679b6258ba69f40d69"
        }
    ]
}

{
    "Timestamp": "2022-04-19T17:29:02.7642136Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:c1de3bbadd104c679b6258ba69f40d69",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "c1de3bbadd104c679b6258ba69f40d69"
        }
    ]
}

{
    "Timestamp": "2022-04-19T17:29:04.1995862Z",
    "EventId": 5,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.OutputStreamResult",
    "Message": "Written to HTTP stream.",
    "State": {
        "Message": "Written to HTTP stream.",
        "{OriginalFormat}": "Written to HTTP stream."
    },
    "Scopes": [
        {
            "Message": "SpanId:5d0a7651ef64ae52, TraceId:9087c513b99f163bfc5d9ad466a24d1c, ParentId:236c1fd495300808",
            "SpanId": "5d0a7651ef64ae52",
            "TraceId": "9087c513b99f163bfc5d9ad466a24d1c",
            "ParentId": "236c1fd495300808"
        },
        {
            "Message": "ConnectionId:0HMH22ID4PGJD",
            "ConnectionId": "0HMH22ID4PGJD"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH22ID4PGJD:00000002",
            "RequestId": "0HMH22ID4PGJD:00000002",
            "RequestPath": "/gcdump"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureGcDump (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "b011b956-5606-4899-a3e0-3b07d50140b9",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureGcDump (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:7 ArtifactSource_RuntimeInstanceCookie:c1de3bbadd104c679b6258ba69f40d69",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "7",
            "ArtifactSource_RuntimeInstanceCookie": "c1de3bbadd104c679b6258ba69f40d69"
        }
    ]
}

{
    "Timestamp": "2022-04-19T17:30:04.0298055Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:8f51c0ee93ee397a, TraceId:0e45b3f64604b64e4836c8e12e0a6c29, ParentId:54634c8d96e978c7",
            "SpanId": "8f51c0ee93ee397a",
            "TraceId": "0e45b3f64604b64e4836c8e12e0a6c29",
            "ParentId": "54634c8d96e978c7"
        },
        {
            "Message": "ConnectionId:0HMH22ID4PGJD",
            "ConnectionId": "0HMH22ID4PGJD"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMH22ID4PGJD:00000003",
            "RequestId": "0HMH22ID4PGJD:00000003",
            "RequestPath": "/livemetrics"
        }
    ]
}

{
    "Timestamp": "2022-04-19T17:30:04.0309405Z",
    "EventId": 1,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController",
    "Message": "Request failed.",
    "Exception": "System.ArgumentException: Unable to discover a target process.    at Microsoft.Diagnostics.Monitoring.WebApi.DiagnosticServices.GetProcessAsync(DiagProcessFilter processFilterConfig, CancellationToken token) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/DiagnosticServices.cs:line 100    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.<>c__DisplayClass33_0`1.<<InvokeForProcess>b__0>d.MoveNext() in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagController.cs:line 713 --- End of stack trace from previous location ---    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagControllerExtensions.InvokeService[T](ControllerBase controller, Func`1 serviceCall, ILogger logger) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagControllerExtensions.cs:line 91",
    "State": {
        "Message": "Request failed.",
        "{OriginalFormat}": "Request failed."
    },
    "Scopes": [
        {
            "Message": "SpanId:8f51c0ee93ee397a, TraceId:0e45b3f64604b64e4836c8e12e0a6c29, ParentId:54634c8d96e978c7",
            "SpanId": "8f51c0ee93ee397a",
            "TraceId": "0e45b3f64604b64e4836c8e12e0a6c29",
            "ParentId": "54634c8d96e978c7"
        },
        {
            "Message": "ConnectionId:0HMH22ID4PGJD",
            "ConnectionId": "0HMH22ID4PGJD"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMH22ID4PGJD:00000003",
            "RequestId": "0HMH22ID4PGJD:00000003",
            "RequestPath": "/livemetrics"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "79857f94-77a3-4950-9596-99bb1e874bff",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:livemetrics",
            "ArtifactType": "livemetrics"
        }
    ]
}

[jander-msft]

When want to eliminate (or possibly blame) the possibility that the socket file has been deleted by something, which would cause the subsequent reconnection of the runtime to the dotnet monitor tool to not occur.

• When the unexpected timeout occurs, could you check that the /tmp/port socket file still exists?
• Could you try moving all of the DotnetMonitor_* settings from the /tmp directory to another shared mounted directory? Our examples typically use /diag as the directory.

[maciejsobocinski]

Hi,

Thank you for looking into this! I can confirm that /tmp/port still exists after timeout. I did get a slightly different behavior today though. GCDump worked just fine several times on a container that was launched only 2hrs ago with next to no traffic going to it (in our dev environment). Eventually I did get the time out in the logs but gcdump succeeded and further requests kept on working (where as yesterday 'unable to discover target process') - I did remove the collection rule that was the one difference I'm going to add it back and see if it changes anything (I'm testing through hitting the http endpoint though so not sure that it matters). I will update the settings to /diag as well and report back.

{
    "Timestamp": "2022-04-20T14:53:07.4891490Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:653424d1c4071427, TraceId:337acd08f914a23c757f608b79ab2b21, ParentId:0000000000000000",
            "SpanId": "653424d1c4071427",
            "TraceId": "337acd08f914a23c757f608b79ab2b21",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2P607OT3P",
            "ConnectionId": "0HMH2P607OT3P"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2P607OT3P:00000002",
            "RequestId": "0HMH2P607OT3P:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T14:53:08.0951240Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
        "processId": "7",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

{
    "Timestamp": "2022-04-20T14:53:08.0998805Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:8e064fa4979846d497866ec3cad84db3",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "8e064fa4979846d497866ec3cad84db3"
        }
    ]
}

{
    "Timestamp": "2022-04-20T14:53:08.1010130Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:8e064fa4979846d497866ec3cad84db3",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "8e064fa4979846d497866ec3cad84db3"
        }
    ]
}

{
    "Timestamp": "2022-04-20T14:53:13.4598955Z",
    "EventId": 4,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Egressed artifact to /tmp/gcdump/20220420_145307_493_7.gcdump",
    "State": {
        "Message": "Egressed artifact to /tmp/gcdump/20220420_145307_493_7.gcdump",
        "location": "/tmp/gcdump/20220420_145307_493_7.gcdump",
        "{OriginalFormat}": "Egressed artifact to {location}"
    },
    "Scopes": [
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:7 ArtifactSource_RuntimeInstanceCookie:8e064fa4979846d497866ec3cad84db3",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "7",
            "ArtifactSource_RuntimeInstanceCookie": "8e064fa4979846d497866ec3cad84db3"
        }
    ]
}

{
    "Timestamp": "2022-04-20T14:54:18.5851347Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:417bbd375cbd0870, TraceId:157005f4185c24249dea2f87133b890f, ParentId:0000000000000000",
            "SpanId": "417bbd375cbd0870",
            "TraceId": "157005f4185c24249dea2f87133b890f",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2P607OT3Q",
            "ConnectionId": "0HMH2P607OT3Q"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2P607OT3Q:00000002",
            "RequestId": "0HMH2P607OT3Q:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T14:54:20.2243724Z",
    "EventId": 4,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Egressed artifact to /tmp/gcdump/20220420_145418_585_7.gcdump",
    "State": {
        "Message": "Egressed artifact to /tmp/gcdump/20220420_145418_585_7.gcdump",
        "location": "/tmp/gcdump/20220420_145418_585_7.gcdump",
        "{OriginalFormat}": "Egressed artifact to {location}"
    },
    "Scopes": [
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:7 ArtifactSource_RuntimeInstanceCookie:8e064fa4979846d497866ec3cad84db3",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "7",
            "ArtifactSource_RuntimeInstanceCookie": "8e064fa4979846d497866ec3cad84db3"
        }
    ]
}

[maciejsobocinski]

I re-enabled the collection rule on high memory. Then started making calls to /gcdump endpoint (rule never triggered). Freshly launched container the first 10 or so gcdumps were successful then it failed again with timeout. This time around further requests are failing again. /tmp/port is still there. Not sure if it's random luck or because I re-enabled the rule (my prior comment was testing without rule got it to timeout but further requests kept on working):

{
    "Timestamp": "2022-04-20T16:19:11.1758418Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:d08610fd79f115b9, TraceId:0333d198dc6ad02684724b0425818337, ParentId:0000000000000000",
            "SpanId": "d08610fd79f115b9",
            "TraceId": "0333d198dc6ad02684724b0425818337",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2T3ELTG56",
            "ConnectionId": "0HMH2T3ELTG56"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2T3ELTG56:00000002",
            "RequestId": "0HMH2T3ELTG56:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T16:19:13.8908825Z",
    "EventId": 4,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Egressed artifact to /tmp/gcdump/20220420_161911_176_9.gcdump",
    "State": {
        "Message": "Egressed artifact to /tmp/gcdump/20220420_161911_176_9.gcdump",
        "location": "/tmp/gcdump/20220420_161911_176_9.gcdump",
        "{OriginalFormat}": "Egressed artifact to {location}"
    },
    "Scopes": [
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:9 ArtifactSource_RuntimeInstanceCookie:672855941e7f4fc2a9f5497110c9a870",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "9",
            "ArtifactSource_RuntimeInstanceCookie": "672855941e7f4fc2a9f5497110c9a870"
        }
    ]
}

{
    "Timestamp": "2022-04-20T16:19:17.4243122Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:a7d39e4d1c10fd33, TraceId:b3dec8791469c2c5776ef9026c041fac, ParentId:0000000000000000",
            "SpanId": "a7d39e4d1c10fd33",
            "TraceId": "b3dec8791469c2c5776ef9026c041fac",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2T3ELTG57",
            "ConnectionId": "0HMH2T3ELTG57"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2T3ELTG57:00000002",
            "RequestId": "0HMH2T3ELTG57:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T16:19:17.9434247Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 9. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 9. Process will no longer be monitored.",
        "processId": "9",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

{
    "Timestamp": "2022-04-20T16:19:17.9476126Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:9 TargetRuntimeInstanceCookie:672855941e7f4fc2a9f5497110c9a870",
            "TargetProcessId": "9",
            "TargetRuntimeInstanceCookie": "672855941e7f4fc2a9f5497110c9a870"
        }
    ]
}

{
    "Timestamp": "2022-04-20T16:19:18.1395307Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:9 TargetRuntimeInstanceCookie:672855941e7f4fc2a9f5497110c9a870",
            "TargetProcessId": "9",
            "TargetRuntimeInstanceCookie": "672855941e7f4fc2a9f5497110c9a870"
        }
    ]
}

{
    "Timestamp": "2022-04-20T16:19:20.7208460Z",
    "EventId": 4,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Egressed artifact to /tmp/gcdump/20220420_161917_425_9.gcdump",
    "State": {
        "Message": "Egressed artifact to /tmp/gcdump/20220420_161917_425_9.gcdump",
        "location": "/tmp/gcdump/20220420_161917_425_9.gcdump",
        "{OriginalFormat}": "Egressed artifact to {location}"
    },
    "Scopes": [
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:9 ArtifactSource_RuntimeInstanceCookie:672855941e7f4fc2a9f5497110c9a870",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "9",
            "ArtifactSource_RuntimeInstanceCookie": "672855941e7f4fc2a9f5497110c9a870"
        }
    ]
}

{
    "Timestamp": "2022-04-20T16:19:38.0013028Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:33460be09a652da9, TraceId:a8fa906d28d743cbba5ba7fa142d9bce, ParentId:0000000000000000",
            "SpanId": "33460be09a652da9",
            "TraceId": "a8fa906d28d743cbba5ba7fa142d9bce",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2T3ELTG58",
            "ConnectionId": "0HMH2T3ELTG58"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2T3ELTG58:00000002",
            "RequestId": "0HMH2T3ELTG58:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T16:19:38.0032943Z",
    "EventId": 1,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController",
    "Message": "Request failed.",
    "Exception": "System.ArgumentException: Unable to discover a target process.    at Microsoft.Diagnostics.Monitoring.WebApi.DiagnosticServices.GetProcessAsync(DiagProcessFilter processFilterConfig, CancellationToken token) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/DiagnosticServices.cs:line 100    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.<>c__DisplayClass33_0`1.<<InvokeForProcess>b__0>d.MoveNext() in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagController.cs:line 704 --- End of stack trace from previous location ---    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagControllerExtensions.InvokeService[T](ControllerBase controller, Func`1 serviceCall, ILogger logger) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagControllerExtensions.cs:line 57",
    "State": {
        "Message": "Request failed.",
        "{OriginalFormat}": "Request failed."
    },
    "Scopes": [
        {
            "Message": "SpanId:33460be09a652da9, TraceId:a8fa906d28d743cbba5ba7fa142d9bce, ParentId:0000000000000000",
            "SpanId": "33460be09a652da9",
            "TraceId": "a8fa906d28d743cbba5ba7fa142d9bce",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2T3ELTG58",
            "ConnectionId": "0HMH2T3ELTG58"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2T3ELTG58:00000002",
            "RequestId": "0HMH2T3ELTG58:00000002",
            "RequestPath": "/gcdump"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureGcDump (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "fc42e51f-5d23-4dff-bef0-3a2f0d017235",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureGcDump (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:gcdump",
            "ArtifactType": "gcdump"
        }
    ]
}

[maciejsobocinski]

So I moved the port to /diag/port and DumpsTempFolder to /dumps like the docs recommended. Same problem :-( Newly spun up container first couple gc dumps work, then get "unexpected timeout" but gc dump works and I can make subsequent requests BUT then it happens again with "unexpected timeout" and then goes to "unable to discover a target process" (/diag/port still exists):

{
    "Timestamp": "2022-04-20T18:50:07.4083755Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:8d03d15bc184093c, TraceId:f0e5b86b4163b69ac1a9173ac243f82f, ParentId:0000000000000000",
            "SpanId": "8d03d15bc184093c",
            "TraceId": "f0e5b86b4163b69ac1a9173ac243f82f",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2V9I11MVO",
            "ConnectionId": "0HMH2V9I11MVO"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2V9I11MVO:00000002",
            "RequestId": "0HMH2V9I11MVO:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:09.1526928Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
        "processId": "7",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

{
    "Timestamp": "2022-04-20T18:50:09.1659161Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:09.2524267Z",
    "EventId": 40,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Starting collection rules.",
    "State": {
        "Message": "Starting collection rules.",
        "{OriginalFormat}": "Starting collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:09.2525991Z",
    "EventId": 29,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' started.",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' started.",
        "ruleName": "HighMemoryRule",
        "{OriginalFormat}": "Collection rule '{ruleName}' started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f",
            "CollectionRuleName": "HighMemoryRule"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:09.2527364Z",
    "EventId": 35,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Collection rule 'HighMemoryRule' trigger 'EventCounter' started.",
    "State": {
        "Message": "Collection rule 'HighMemoryRule' trigger 'EventCounter' started.",
        "ruleName": "HighMemoryRule",
        "triggerType": "EventCounter",
        "{OriginalFormat}": "Collection rule '{ruleName}' trigger '{triggerType}' started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f CollectionRuleName:HighMemoryRule",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f",
            "CollectionRuleName": "HighMemoryRule"
        },
        {
            "Message": "CollectionRuleTriggerType:EventCounter",
            "CollectionRuleTriggerType": "EventCounter"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:09.2793160Z",
    "EventId": 32,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules started.",
    "State": {
        "Message": "All collection rules started.",
        "{OriginalFormat}": "All collection rules started."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:09.3916058Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:11.0080567Z",
    "EventId": 4,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Egressed artifact to /tmp/gcdump/20220420_185007_410_7.gcdump",
    "State": {
        "Message": "Egressed artifact to /tmp/gcdump/20220420_185007_410_7.gcdump",
        "location": "/tmp/gcdump/20220420_185007_410_7.gcdump",
        "{OriginalFormat}": "Egressed artifact to {location}"
    },
    "Scopes": [
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:7 ArtifactSource_RuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "7",
            "ArtifactSource_RuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:11.0699909Z",
    "EventId": 5,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.OutputStreamResult",
    "Message": "Written to HTTP stream.",
    "State": {
        "Message": "Written to HTTP stream.",
        "{OriginalFormat}": "Written to HTTP stream."
    },
    "Scopes": [
        {
            "Message": "SpanId:ec6999cc44d5cd93, TraceId:b3ad826b2977b98b0d239fdd94164cba, ParentId:8eefce7af93b1945",
            "SpanId": "ec6999cc44d5cd93",
            "TraceId": "b3ad826b2977b98b0d239fdd94164cba",
            "ParentId": "8eefce7af93b1945"
        },
        {
            "Message": "ConnectionId:0HMH2V9I11MVN",
            "ConnectionId": "0HMH2V9I11MVN"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMH2V9I11MVN:00000002",
            "RequestId": "0HMH2V9I11MVN:00000002",
            "RequestPath": "/livemetrics"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "7285c1f5-03cd-4516-a55c-b35a48ba044a",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:livemetrics ArtifactSource_ProcessId:7 ArtifactSource_RuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "ArtifactType": "livemetrics",
            "ArtifactSource_ProcessId": "7",
            "ArtifactSource_RuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:30.6010840Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:7ca19d809cb0a1dc, TraceId:58a4a0511e3aaf467a748a19d2646acb, ParentId:0000000000000000",
            "SpanId": "7ca19d809cb0a1dc",
            "TraceId": "58a4a0511e3aaf467a748a19d2646acb",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2V9I11MVP",
            "ConnectionId": "0HMH2V9I11MVP"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2V9I11MVP:00000002",
            "RequestId": "0HMH2V9I11MVP:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:50:34.3168668Z",
    "EventId": 4,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Egressed artifact to /tmp/gcdump/20220420_185030_606_7.gcdump",
    "State": {
        "Message": "Egressed artifact to /tmp/gcdump/20220420_185030_606_7.gcdump",
        "location": "/tmp/gcdump/20220420_185030_606_7.gcdump",
        "{OriginalFormat}": "Egressed artifact to {location}"
    },
    "Scopes": [
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:7 ArtifactSource_RuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "7",
            "ArtifactSource_RuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:51:12.3892161Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:ad90d96e4a48dafe, TraceId:18da0341234ecb0cce826273da5385a6, ParentId:0000000000000000",
            "SpanId": "ad90d96e4a48dafe",
            "TraceId": "18da0341234ecb0cce826273da5385a6",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2V9I11MVR",
            "ConnectionId": "0HMH2V9I11MVR"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2V9I11MVR:00000002",
            "RequestId": "0HMH2V9I11MVR:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:51:12.8116760Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 7. Process will no longer be monitored.",
        "processId": "7",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

{
    "Timestamp": "2022-04-20T18:51:12.8119827Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:51:13.0701847Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:7 TargetRuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "TargetProcessId": "7",
            "TargetRuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:51:15.8297924Z",
    "EventId": 4,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.EgressOperation",
    "Message": "Egressed artifact to /tmp/gcdump/20220420_185112_394_7.gcdump",
    "State": {
        "Message": "Egressed artifact to /tmp/gcdump/20220420_185112_394_7.gcdump",
        "location": "/tmp/gcdump/20220420_185112_394_7.gcdump",
        "{OriginalFormat}": "Egressed artifact to {location}"
    },
    "Scopes": [
        {
            "Message": "ArtifactType:gcdump ArtifactSource_ProcessId:7 ArtifactSource_RuntimeInstanceCookie:b53e1d6ac48e4dcb8dcf59857e24a17f",
            "ArtifactType": "gcdump",
            "ArtifactSource_ProcessId": "7",
            "ArtifactSource_RuntimeInstanceCookie": "b53e1d6ac48e4dcb8dcf59857e24a17f"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:51:28.7445777Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:882994a4060b7795, TraceId:3c8ad5e70d400f8acc73f15c6e5e3af9, ParentId:0000000000000000",
            "SpanId": "882994a4060b7795",
            "TraceId": "3c8ad5e70d400f8acc73f15c6e5e3af9",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2V9I11MVS",
            "ConnectionId": "0HMH2V9I11MVS"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2V9I11MVS:00000002",
            "RequestId": "0HMH2V9I11MVS:00000002",
            "RequestPath": "/gcdump"
        }
    ]
}

{
    "Timestamp": "2022-04-20T18:51:28.7681109Z",
    "EventId": 1,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController",
    "Message": "Request failed.",
    "Exception": "System.ArgumentException: Unable to discover a target process.    at Microsoft.Diagnostics.Monitoring.WebApi.DiagnosticServices.GetProcessAsync(DiagProcessFilter processFilterConfig, CancellationToken token) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/DiagnosticServices.cs:line 100    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.<>c__DisplayClass33_0`1.<<InvokeForProcess>b__0>d.MoveNext() in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagController.cs:line 713 --- End of stack trace from previous location ---    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagControllerExtensions.InvokeService[T](ControllerBase controller, Func`1 serviceCall, ILogger logger) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagControllerExtensions.cs:line 91",
    "State": {
        "Message": "Request failed.",
        "{OriginalFormat}": "Request failed."
    },
    "Scopes": [
        {
            "Message": "SpanId:882994a4060b7795, TraceId:3c8ad5e70d400f8acc73f15c6e5e3af9, ParentId:0000000000000000",
            "SpanId": "882994a4060b7795",
            "TraceId": "3c8ad5e70d400f8acc73f15c6e5e3af9",
            "ParentId": "0000000000000000"
        },
        {
            "Message": "ConnectionId:0HMH2V9I11MVS",
            "ConnectionId": "0HMH2V9I11MVS"
        },
        {
            "Message": "RequestPath:/gcdump RequestId:0HMH2V9I11MVS:00000002",
            "RequestId": "0HMH2V9I11MVS:00000002",
            "RequestPath": "/gcdump"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureGcDump (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "ae104f35-1f39-4b8f-84f3-014747a5c8b0",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureGcDump (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:gcdump",
            "ArtifactType": "gcdump"
        }
    ]
}

[SebastianStehle]

I have the same problem. I installed dotnet-monitor on 2 deployments. One of them works fine, but the other looses connection after some time.

I start the deployment make a few gcdumps over the endpoint, then come back 30 minutes later and it does not work anymore.

EDIT: When I restart the monitor container (not the pod) it works again.
EDIT 2: The restart has worked three times now.

[maciejsobocinski]

I just saw a new version came out that had code changes to address this. I re-enabled the container in our development environment. It is looking good so far - as in I took 30+ gc dumps continuously to test with no issues where as previously I could trigger the scenario above to occur fairly quickly. Will deploy the change to production later this week to run against real-world usage hopefully looks good there as well. Thank you!

edit: Closing this ticket as well so I don't forget since I believe this to be working now. I'll re-open if I see different results in our prod environment.

[maciejsobocinski]

So we just deployed the latest dotnet monitor to prod. I re-enabled hitting /livemetrics every 5 minutes ... within 30 minutes or so 1 out of 4 containers started getting the same error message from dotnet monitor :-( . There was no GC dumps taken and the container never stopped processing user requests successfully.

{
    "Timestamp": "2022-07-01T14:00:01.0111921Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:9fa40d2041202592, TraceId:ae38f7c3e4d83e8559019aee39ea50d9, ParentId:dbe31cb4d270f899",
            "SpanId": "9fa40d2041202592",
            "TraceId": "ae38f7c3e4d83e8559019aee39ea50d9",
            "ParentId": "dbe31cb4d270f899"
        },
        {
            "Message": "ConnectionId:0HMIRCMP5M5GF",
            "ConnectionId": "0HMIRCMP5M5GF"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMIRCMP5M5GF:00000002",
            "RequestId": "0HMIRCMP5M5GF:00000002",
            "RequestPath": "/livemetrics"
        }
    ]
}
{
    "Timestamp": "2022-07-01T14:00:08.1066647Z",
    "EventId": 5,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.OutputStreamResult",
    "Message": "Written to HTTP stream.",
    "State": {
        "Message": "Written to HTTP stream.",
        "{OriginalFormat}": "Written to HTTP stream."
    },
    "Scopes": [
        {
            "Message": "SpanId:9fa40d2041202592, TraceId:ae38f7c3e4d83e8559019aee39ea50d9, ParentId:dbe31cb4d270f899",
            "SpanId": "9fa40d2041202592",
            "TraceId": "ae38f7c3e4d83e8559019aee39ea50d9",
            "ParentId": "dbe31cb4d270f899"
        },
        {
            "Message": "ConnectionId:0HMIRCMP5M5GF",
            "ConnectionId": "0HMIRCMP5M5GF"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMIRCMP5M5GF:00000002",
            "RequestId": "0HMIRCMP5M5GF:00000002",
            "RequestPath": "/livemetrics"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "8accbb03-0591-4ce4-8407-5a631e02c09d",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:livemetrics ArtifactSource_ProcessId:8 ArtifactSource_RuntimeInstanceCookie:08449004064f4286bffdf0f33935d4b3",
            "ArtifactType": "livemetrics",
            "ArtifactSource_ProcessId": "8",
            "ArtifactSource_RuntimeInstanceCookie": "08449004064f4286bffdf0f33935d4b3"
        }
    ]
}

{
    "Timestamp": "2022-07-01T14:05:02.0873006Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:30687ae247c20cfb, TraceId:ef5426eeaf912d015c59f0eebf0bf9e5, ParentId:2d02014ed370a9e5",
            "SpanId": "30687ae247c20cfb",
            "TraceId": "ef5426eeaf912d015c59f0eebf0bf9e5",
            "ParentId": "2d02014ed370a9e5"
        },
        {
            "Message": "ConnectionId:0HMIRCMP5M5GG",
            "ConnectionId": "0HMIRCMP5M5GG"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMIRCMP5M5GG:00000002",
            "RequestId": "0HMIRCMP5M5GG:00000002",
            "RequestPath": "/livemetrics"
        }
    ]
}

{
    "Timestamp": "2022-07-01T14:05:08.0963972Z",
    "EventId": 52,
    "LogLevel": "Warning",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.ServerEndpointInfoSource",
    "Message": "Unexpected timeout from process 8. Process will no longer be monitored.",
    "State": {
        "Message": "Unexpected timeout from process 8. Process will no longer be monitored.",
        "processId": "8",
        "{OriginalFormat}": "Unexpected timeout from process {processId}. Process will no longer be monitored."
    },
    "Scopes": []
}

{
    "Timestamp": "2022-07-01T14:05:08.0970551Z",
    "EventId": 5,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.OutputStreamResult",
    "Message": "Written to HTTP stream.",
    "State": {
        "Message": "Written to HTTP stream.",
        "{OriginalFormat}": "Written to HTTP stream."
    },
    "Scopes": [
        {
            "Message": "SpanId:30687ae247c20cfb, TraceId:ef5426eeaf912d015c59f0eebf0bf9e5, ParentId:2d02014ed370a9e5",
            "SpanId": "30687ae247c20cfb",
            "TraceId": "ef5426eeaf912d015c59f0eebf0bf9e5",
            "ParentId": "2d02014ed370a9e5"
        },
        {
            "Message": "ConnectionId:0HMIRCMP5M5GG",
            "ConnectionId": "0HMIRCMP5M5GG"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMIRCMP5M5GG:00000002",
            "RequestId": "0HMIRCMP5M5GG:00000002",
            "RequestPath": "/livemetrics"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "8accbb03-0591-4ce4-8407-5a631e02c09d",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:livemetrics ArtifactSource_ProcessId:8 ArtifactSource_RuntimeInstanceCookie:08449004064f4286bffdf0f33935d4b3",
            "ArtifactType": "livemetrics",
            "ArtifactSource_ProcessId": "8",
            "ArtifactSource_RuntimeInstanceCookie": "08449004064f4286bffdf0f33935d4b3"
        }
    ]
}

{
    "Timestamp": "2022-07-01T14:05:08.1019287Z",
    "EventId": 44,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "Stopping collection rules.",
    "State": {
        "Message": "Stopping collection rules.",
        "{OriginalFormat}": "Stopping collection rules."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:8 TargetRuntimeInstanceCookie:08449004064f4286bffdf0f33935d4b3",
            "TargetProcessId": "8",
            "TargetRuntimeInstanceCookie": "08449004064f4286bffdf0f33935d4b3"
        }
    ]
}

{
    "Timestamp": "2022-07-01T14:05:08.2234506Z",
    "EventId": 45,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService",
    "Message": "All collection rules have stopped.",
    "State": {
        "Message": "All collection rules have stopped.",
        "{OriginalFormat}": "All collection rules have stopped."
    },
    "Scopes": [
        {
            "Message": "TargetProcessId:8 TargetRuntimeInstanceCookie:08449004064f4286bffdf0f33935d4b3",
            "TargetProcessId": "8",
            "TargetRuntimeInstanceCookie": "08449004064f4286bffdf0f33935d4b3"
        }
    ]
}

{
    "Timestamp": "2022-07-01T14:10:03.5723478Z",
    "EventId": 2,
    "LogLevel": "Information",
    "Category": "Microsoft.Diagnostics.Tools.Monitor.LiveJwtBearerHandler",
    "Message": "Successfully validated the token.",
    "State": {
        "Message": "Successfully validated the token.",
        "{OriginalFormat}": "Successfully validated the token."
    },
    "Scopes": [
        {
            "Message": "SpanId:cab9dde8f67d58fb, TraceId:f466c3e8ebb202208a5ec6d42f013591, ParentId:263c08c90ec8929c",
            "SpanId": "cab9dde8f67d58fb",
            "TraceId": "f466c3e8ebb202208a5ec6d42f013591",
            "ParentId": "263c08c90ec8929c"
        },
        {
            "Message": "ConnectionId:0HMIRCMP5M5GH",
            "ConnectionId": "0HMIRCMP5M5GH"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMIRCMP5M5GH:00000002",
            "RequestId": "0HMIRCMP5M5GH:00000002",
            "RequestPath": "/livemetrics"
        }
    ]
}

{
    "Timestamp": "2022-07-01T14:10:03.5739343Z",
    "EventId": 1,
    "LogLevel": "Error",
    "Category": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController",
    "Message": "Request failed.",
    "Exception": "System.ArgumentException: Unable to discover a target process.    at Microsoft.Diagnostics.Monitoring.WebApi.DiagnosticServices.GetProcessAsync(DiagProcessFilter processFilterConfig, CancellationToken token) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/DiagnosticServices.cs:line 94    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.<>c__DisplayClass33_0`1.<<InvokeForProcess>b__0>d.MoveNext() in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagController.cs:line 719 --- End of stack trace from previous location ---    at Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagControllerExtensions.InvokeService[T](ControllerBase controller, Func`1 serviceCall, ILogger logger) in /_/src/Microsoft.Diagnostics.Monitoring.WebApi/Controllers/DiagControllerExtensions.cs:line 57",
    "State": {
        "Message": "Request failed.",
        "{OriginalFormat}": "Request failed."
    },
    "Scopes": [
        {
            "Message": "SpanId:cab9dde8f67d58fb, TraceId:f466c3e8ebb202208a5ec6d42f013591, ParentId:263c08c90ec8929c",
            "SpanId": "cab9dde8f67d58fb",
            "TraceId": "f466c3e8ebb202208a5ec6d42f013591",
            "ParentId": "263c08c90ec8929c"
        },
        {
            "Message": "ConnectionId:0HMIRCMP5M5GH",
            "ConnectionId": "0HMIRCMP5M5GH"
        },
        {
            "Message": "RequestPath:/livemetrics RequestId:0HMIRCMP5M5GH:00000002",
            "RequestId": "0HMIRCMP5M5GH:00000002",
            "RequestPath": "/livemetrics"
        },
        {
            "Message": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)",
            "ActionId": "8accbb03-0591-4ce4-8407-5a631e02c09d",
            "ActionName": "Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureMetrics (Microsoft.Diagnostics.Monitoring.WebApi)"
        },
        {
            "Message": "ArtifactType:livemetrics",
            "ArtifactType": "livemetrics"
        }
    ]
}