search

dotnet / dotnet-monitor

This repository contains the source code for .NET Monitor - a tool that allows you to gather diagnostic data from running applications using HTTP endpoints
MIT License
638 stars 113 forks source link

OverlappingEventSourceTests_AspNetResponseStatusTest fails often #2762

Open jander-msft opened 2 years ago

jander-msft commented 2 years ago

The OverlappingEventSourceTests_AspNetResponseStatusTest 

System.Threading.Tasks.TaskCanceledException : A task was canceled.
   at Microsoft.Diagnostics.Monitoring.TestCommon.TaskCompletionSourceExtensions.WithCancellation[T](TaskCompletionSource`1 source, CancellationToken token) in /Users/runner/work/1/s/src/Tools/dotnet-monitor/TaskCompletionSourceExtensions.cs:line 30
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.Runners.MonitorCollectRunner.WaitForCollectionRuleEventAsync(Int32 eventId, String ruleName, CancellationToken token) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests/Runners/MonitorCollectRunner.CollectionRule.cs:line 58
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.Runners.MonitorCollectRunnerExtensions.WaitForCollectionRuleActionsCompletedAsync(MonitorCollectRunner runner, String ruleName, TimeSpan timeout) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests/Runners/MonitorRunnerExtensions.cs:line 152
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.OverlappingEventSourceTests.ValidateAspNetTriggerCollected(Task ruleTask, ApiClient client, String hostName, String[] paths, String expectedFilePath, String expectedFileContent) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests/OverlappingEventSourceTests.cs:line 152
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.OverlappingEventSourceTests.<>c__DisplayClass7_0.<<OverlappingEventSourceTests_AspNetResponseStatusTest>b__0>d.MoveNext() in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests/OverlappingEventSourceTests.cs:line 66
--- End of stack trace from previous location ---
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.Runners.ScenarioRunner.<>c__DisplayClass0_0.<<SingleTarget>b__0>d.MoveNext() in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests/Runners/ScenarioRunner.cs:line 60
--- End of stack trace from previous location ---
   at Microsoft.Diagnostics.Monitoring.TestCommon.Runners.AppRunnerExtensions.ExecuteAsync(AppRunner runner, Func`1 func) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.TestCommon/Runners/AppRunnerExtensions.cs:line 33
   at Microsoft.Diagnostics.Monitoring.TestCommon.Runners.AppRunnerExtensions.ExecuteAsync(AppRunner runner, Func`1 func) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.TestCommon/Runners/AppRunnerExtensions.cs:line 47
   at Microsoft.Diagnostics.Monitoring.TestCommon.Runners.AppRunnerExtensions.ExecuteAsync(AppRunner runner, Func`1 func) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.TestCommon/Runners/AppRunnerExtensions.cs:line 52
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.Runners.ScenarioRunner.SingleTarget(ITestOutputHelper outputHelper, IHttpClientFactory httpClientFactory, DiagnosticPortConnectionMode mode, String scenarioName, Func`3 appValidate, Func`3 postAppValidate, Action`1 configureApp, Action`1 configureTool, Boolean disableHttpEgress, String profilerLogLevel) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests/Runners/ScenarioRunner.cs:line 58
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.Runners.ScenarioRunner.SingleTarget(ITestOutputHelper outputHelper, IHttpClientFactory httpClientFactory, DiagnosticPortConnectionMode mode, String scenarioName, Func`3 appValidate, Func`3 postAppValidate, Action`1 configureApp, Action`1 configureTool, Boolean disableHttpEgress, String profilerLogLevel) in /Users/runner/work/1/s/src/Tests/Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests/Runners/ScenarioRunner.cs:line 67
   at Microsoft.Diagnostics.Monitoring.Tool.FunctionalTests.Runners.ScenarioRunner.SingleTarget(ITestOutputHelper outputHelper, IHttpClientFactory httpClientFactory, DiagnosticPortConnectionMode mode, String scenarioName, Func`3 appValidate, Func`3 postAppValidate, Action`1 configureApp, Action`1 configureTool, Boolean disableHttpEgress, String

The collection rule that is being monitored does complete its actions, but it seems to come at a much later time than expected:

[Monitor] {"Timestamp":"12:34:25 ","EventId":60,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.Startup","Message":"Tell us about your experience with dotnet monitor: https://aka.ms/dotnet-monitor-survey","State":{"Message":"Tell us about your experience with dotnet monitor: https://aka.ms/dotnet-monitor-survey","link":"https://aka.ms/dotnet-monitor-survey","{OriginalFormat}":"Tell us about your experience with dotnet monitor: {link}"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":77,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.Startup","Message":"Connection mode: Listen at \u0027/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/594ff877-2b16-4751-87b6-b18382bd77fe\u0027","State":{"Message":"Connection mode: Listen at \u0027/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/594ff877-2b16-4751-87b6-b18382bd77fe\u0027","path":"/var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/594ff877-2b16-4751-87b6-b18382bd77fe","{OriginalFormat}":"Connection mode: Listen at \u0027{path}\u0027"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":13,"LogLevel":"Warning","Category":"Microsoft.Diagnostics.Tools.Monitor.Startup","Message":"WARNING: Authentication has been disabled. This can pose a security risk and is not intended for production environments.","State":{"Message":"WARNING: Authentication has been disabled. This can pose a security risk and is not intended for production environments.","{OriginalFormat}":"WARNING: Authentication has been disabled. This can pose a security risk and is not intended for production environments."},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":14,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Now listening on: http://127.0.0.1:50625","State":{"Message":"Now listening on: http://127.0.0.1:50625","address":"http://127.0.0.1:50625","{OriginalFormat}":"Now listening on: {address}"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":14,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Now listening on: http://127.0.0.1:50626","State":{"Message":"Now listening on: http://127.0.0.1:50626","address":"http://127.0.0.1:50626","{OriginalFormat}":"Now listening on: {address}"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":16,"LogLevel":"Debug","Category":"Microsoft.Diagnostics.Tools.Monitor.Startup","Message":"Bound default address: http://127.0.0.1:50625","State":{"Message":"Bound default address: http://127.0.0.1:50625","address":"http://127.0.0.1:50625","{OriginalFormat}":"Bound default address: {address}"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":17,"LogLevel":"Debug","Category":"Microsoft.Diagnostics.Tools.Monitor.Startup","Message":"Bound metrics address: http://127.0.0.1:50626","State":{"Message":"Bound metrics address: http://127.0.0.1:50626","address":"http://127.0.0.1:50626","{OriginalFormat}":"Bound metrics address: {address}"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":0,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Application started. Press Ctrl\u002BC to shut down.","State":{"Message":"Application started. Press Ctrl\u002BC to shut down.","{OriginalFormat}":"Application started. Press Ctrl\u002BC to shut down."},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":0,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Hosting environment: Production","State":{"Message":"Hosting environment: Production","EnvName":"Production","{OriginalFormat}":"Hosting environment: {EnvName}"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":0,"LogLevel":"Information","Category":"Microsoft.Hosting.Lifetime","Message":"Content root path: /Users/runner/work/1/s/artifacts/bin/dotnet-monitor/Debug/net7.0/","State":{"Message":"Content root path: /Users/runner/work/1/s/artifacts/bin/dotnet-monitor/Debug/net7.0/","ContentRoot":"/Users/runner/work/1/s/artifacts/bin/dotnet-monitor/Debug/net7.0/","{OriginalFormat}":"Content root path: {ContentRoot}"},"Scopes":[]}
[Monitor] {"Timestamp":"12:34:25 ","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:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543"}]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":29,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService","Message":"Collection rule \u0027FunctionalTestRule\u0027 started.","State":{"Message":"Collection rule \u0027FunctionalTestRule\u0027 started.","ruleName":"FunctionalTestRule","{OriginalFormat}":"Collection rule \u0027{ruleName}\u0027 started."},"Scopes":[{"Message":"TargetProcessId:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543 CollectionRuleName:FunctionalTestRule","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543","CollectionRuleName":"FunctionalTestRule"}]}
[Monitor] {"Timestamp":"12:34:25 ","EventId":35,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService","Message":"Collection rule \u0027FunctionalTestRule\u0027 trigger \u0027AspNetResponseStatus\u0027 started.","State":{"Message":"Collection rule \u0027FunctionalTestRule\u0027 trigger \u0027AspNetResponseStatus\u0027 started.","ruleName":"FunctionalTestRule","triggerType":"AspNetResponseStatus","{OriginalFormat}":"Collection rule \u0027{ruleName}\u0027 trigger \u0027{triggerType}\u0027 started."},"Scopes":[{"Message":"TargetProcessId:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543 CollectionRuleName:FunctionalTestRule","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543","CollectionRuleName":"FunctionalTestRule"},{"Message":"CollectionRuleTriggerType:AspNetResponseStatus","CollectionRuleTriggerType":"AspNetResponseStatus"}]}
[Monitor] {"Timestamp":"12:34:25 ","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:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":1,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Hosting.Diagnostics","Message":"Request starting HTTP/1.1 GET http://127.0.0.1:50625/processes - -","State":{"Message":"Request starting HTTP/1.1 GET http://127.0.0.1:50625/processes - -","Protocol":"HTTP/1.1","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"http","Host":"127.0.0.1:50625","PathBase":"","Path":"/processes","QueryString":""},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":0,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Routing.EndpointMiddleware","Message":"Executing endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","State":{"Message":"Executing endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","EndpointName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)","{OriginalFormat}":"Executing endpoint \u0027{EndpointName}\u0027"},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":102,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","Message":"Route matched with {action = \u0022GetProcesses\u0022, controller = \u0022Diag\u0022}. Executing controller action with signature System.Threading.Tasks.Task\u00601[Microsoft.AspNetCore.Mvc.ActionResult\u00601[System.Collections.Generic.IEnumerable\u00601[Microsoft.Diagnostics.Monitoring.WebApi.Models.ProcessIdentifier]]] GetProcesses() on controller Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController (Microsoft.Diagnostics.Monitoring.WebApi).","State":{"Message":"Route matched with {action = \u0022GetProcesses\u0022, controller = \u0022Diag\u0022}. Executing controller action with signature System.Threading.Tasks.Task\u00601[Microsoft.AspNetCore.Mvc.ActionResult\u00601[System.Collections.Generic.IEnumerable\u00601[Microsoft.Diagnostics.Monitoring.WebApi.Models.ProcessIdentifier]]] GetProcesses() on controller Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController (Microsoft.Diagnostics.Monitoring.WebApi).","RouteData":"{action = \u0022GetProcesses\u0022, controller = \u0022Diag\u0022}","MethodInfo":"System.Threading.Tasks.Task\u00601[Microsoft.AspNetCore.Mvc.ActionResult\u00601[System.Collections.Generic.IEnumerable\u00601[Microsoft.Diagnostics.Monitoring.WebApi.Models.ProcessIdentifier]]] GetProcesses()","Controller":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController","AssemblyName":"Microsoft.Diagnostics.Monitoring.WebApi","{OriginalFormat}":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName})."},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"},{"Message":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)","ActionId":"987e41d7-cb96-4167-a1a8-6d70db2d6552","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":5,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController","Message":"Written to HTTP stream.","State":{"Message":"Written to HTTP stream.","{OriginalFormat}":"Written to HTTP stream."},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"},{"Message":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)","ActionId":"987e41d7-cb96-4167-a1a8-6d70db2d6552","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":1,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Mvc.Infrastructure.ObjectResultExecutor","Message":"Executing ObjectResult, writing value of type \u0027System.Collections.Generic.List\u00601[[Microsoft.Diagnostics.Monitoring.WebApi.Models.ProcessIdentifier, Microsoft.Diagnostics.Monitoring.WebApi, Version=8.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35]]\u0027.","State":{"Message":"Executing ObjectResult, writing value of type \u0027System.Collections.Generic.List\u00601[[Microsoft.Diagnostics.Monitoring.WebApi.Models.ProcessIdentifier, Microsoft.Diagnostics.Monitoring.WebApi, Version=8.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35]]\u0027.","ObjectResultType":"ObjectResult","Type":"System.Collections.Generic.List\u00601[[Microsoft.Diagnostics.Monitoring.WebApi.Models.ProcessIdentifier, Microsoft.Diagnostics.Monitoring.WebApi, Version=8.0.0.0, Culture=neutral, PublicKeyToken=31bf3856ad364e35]]","{OriginalFormat}":"Executing {ObjectResultType}, writing value of type \u0027{Type}\u0027."},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"},{"Message":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)","ActionId":"987e41d7-cb96-4167-a1a8-6d70db2d6552","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":105,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","Message":"Executed action Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi) in 94.3249ms","State":{"Message":"Executed action Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi) in 94.3249ms","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)","ElapsedMilliseconds":94.3249,"{OriginalFormat}":"Executed action {ActionName} in {ElapsedMilliseconds}ms"},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":1,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Routing.EndpointMiddleware","Message":"Executed endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","State":{"Message":"Executed endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","EndpointName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.GetProcesses (Microsoft.Diagnostics.Monitoring.WebApi)","{OriginalFormat}":"Executed endpoint \u0027{EndpointName}\u0027"},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":2,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Hosting.Diagnostics","Message":"Request finished HTTP/1.1 GET http://127.0.0.1:50625/processes - - - 200 - application/json;\u002Bcharset=utf-8 213.8372ms","State":{"Message":"Request finished HTTP/1.1 GET http://127.0.0.1:50625/processes - - - 200 - application/json;\u002Bcharset=utf-8 213.8372ms","ElapsedMilliseconds":213.8372,"StatusCode":200,"ContentType":"application/json; charset=utf-8","ContentLength":null,"Protocol":"HTTP/1.1","Method":"GET","Scheme":"http","Host":"127.0.0.1:50625","PathBase":"","Path":"/processes","QueryString":""},"Scopes":[{"Message":"SpanId:d21f64f3ffd4d455, TraceId:86beff62dc07830ee42f24f3f4ebd83f, ParentId:0000000000000000","SpanId":"d21f64f3ffd4d455","TraceId":"86beff62dc07830ee42f24f3f4ebd83f","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/processes RequestId:0HMLLNGB7D5BL:00000001","RequestId":"0HMLLNGB7D5BL:00000001","RequestPath":"/processes"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":1,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Hosting.Diagnostics","Message":"Request starting HTTP/1.1 GET http://127.0.0.1:50625/trace?pid=42253\u0026durationSeconds=-1\u0026profile=Http - -","State":{"Message":"Request starting HTTP/1.1 GET http://127.0.0.1:50625/trace?pid=42253\u0026durationSeconds=-1\u0026profile=Http - -","Protocol":"HTTP/1.1","Method":"GET","ContentType":null,"ContentLength":null,"Scheme":"http","Host":"127.0.0.1:50625","PathBase":"","Path":"/trace","QueryString":"?pid=42253\u0026durationSeconds=-1\u0026profile=Http"},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":0,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Routing.EndpointMiddleware","Message":"Executing endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","State":{"Message":"Executing endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","EndpointName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)","{OriginalFormat}":"Executing endpoint \u0027{EndpointName}\u0027"},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":102,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","Message":"Route matched with {action = \u0022CaptureTrace\u0022, controller = \u0022Diag\u0022}. Executing controller action with signature System.Threading.Tasks.Task\u00601[Microsoft.AspNetCore.Mvc.ActionResult] CaptureTrace(System.Nullable\u00601[System.Int32], System.Nullable\u00601[System.Guid], System.String, Microsoft.Diagnostics.Monitoring.WebApi.Models.TraceProfile, Int32, System.String) on controller Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController (Microsoft.Diagnostics.Monitoring.WebApi).","State":{"Message":"Route matched with {action = \u0022CaptureTrace\u0022, controller = \u0022Diag\u0022}. Executing controller action with signature System.Threading.Tasks.Task\u00601[Microsoft.AspNetCore.Mvc.ActionResult] CaptureTrace(System.Nullable\u00601[System.Int32], System.Nullable\u00601[System.Guid], System.String, Microsoft.Diagnostics.Monitoring.WebApi.Models.TraceProfile, Int32, System.String) on controller Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController (Microsoft.Diagnostics.Monitoring.WebApi).","RouteData":"{action = \u0022CaptureTrace\u0022, controller = \u0022Diag\u0022}","MethodInfo":"System.Threading.Tasks.Task\u00601[Microsoft.AspNetCore.Mvc.ActionResult] CaptureTrace(System.Nullable\u00601[System.Int32], System.Nullable\u00601[System.Guid], System.String, Microsoft.Diagnostics.Monitoring.WebApi.Models.TraceProfile, Int32, System.String)","Controller":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController","AssemblyName":"Microsoft.Diagnostics.Monitoring.WebApi","{OriginalFormat}":"Route matched with {RouteData}. Executing controller action with signature {MethodInfo} on controller {Controller} ({AssemblyName})."},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"},{"Message":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)","ActionId":"79492f0c-70bb-4edf-8f61-56c38222a90a","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)"}]}
[Monitor] {"Timestamp":"12:34:26 ","EventId":3,"LogLevel":"Debug","Category":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController","Message":"Resolved target process.","State":{"Message":"Resolved target process.","{OriginalFormat}":"Resolved target process."},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"},{"Message":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)","ActionId":"79492f0c-70bb-4edf-8f61-56c38222a90a","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)"},{"Message":"ArtifactType:trace","ArtifactType":"trace"},{"Message":"ArtifactSource_ProcessId:42253 ArtifactSource_RuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543","ArtifactSource_ProcessId":"42253","ArtifactSource_RuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543"}]}
[Monitor] {"Timestamp":"12:34:56 ","EventId":36,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService","Message":"Collection rule \u0027FunctionalTestRule\u0027 trigger \u0027AspNetResponseStatus\u0027 completed.","State":{"Message":"Collection rule \u0027FunctionalTestRule\u0027 trigger \u0027AspNetResponseStatus\u0027 completed.","ruleName":"FunctionalTestRule","triggerType":"AspNetResponseStatus","{OriginalFormat}":"Collection rule \u0027{ruleName}\u0027 trigger \u0027{triggerType}\u0027 completed."},"Scopes":[{"Message":"TargetProcessId:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543 CollectionRuleName:FunctionalTestRule","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543","CollectionRuleName":"FunctionalTestRule"},{"Message":"CollectionRuleTriggerType:AspNetResponseStatus","CollectionRuleTriggerType":"AspNetResponseStatus"}]}
[Monitor] {"Timestamp":"12:34:56 ","EventId":2,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Monitoring.WebApi.OutputStreamResult","Message":"Request canceled.","State":{"Message":"Request canceled.","{OriginalFormat}":"Request canceled."},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"},{"Message":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)","ActionId":"79492f0c-70bb-4edf-8f61-56c38222a90a","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)"},{"Message":"ArtifactType:trace ArtifactSource_ProcessId:42253 ArtifactSource_RuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543","ArtifactType":"trace","ArtifactSource_ProcessId":"42253","ArtifactSource_RuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543"}]}
[Monitor] {"Timestamp":"12:34:56 ","EventId":105,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Mvc.Infrastructure.ControllerActionInvoker","Message":"Executed action Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi) in 30370.7456ms","State":{"Message":"Executed action Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi) in 30370.7456ms","ActionName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)","ElapsedMilliseconds":30370.7456,"{OriginalFormat}":"Executed action {ActionName} in {ElapsedMilliseconds}ms"},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"}]}
[Monitor] {"Timestamp":"12:34:56 ","EventId":1,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Routing.EndpointMiddleware","Message":"Executed endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","State":{"Message":"Executed endpoint \u0027Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)\u0027","EndpointName":"Microsoft.Diagnostics.Monitoring.WebApi.Controllers.DiagController.CaptureTrace (Microsoft.Diagnostics.Monitoring.WebApi)","{OriginalFormat}":"Executed endpoint \u0027{EndpointName}\u0027"},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"}]}
[Monitor] {"Timestamp":"12:34:56 ","EventId":2,"LogLevel":"Information","Category":"Microsoft.AspNetCore.Hosting.Diagnostics","Message":"Request finished HTTP/1.1 GET http://127.0.0.1:50625/trace?pid=42253\u0026durationSeconds=-1\u0026profile=Http - - - 200 - application/octet-stream 30408.4427ms","State":{"Message":"Request finished HTTP/1.1 GET http://127.0.0.1:50625/trace?pid=42253\u0026durationSeconds=-1\u0026profile=Http - - - 200 - application/octet-stream 30408.4427ms","ElapsedMilliseconds":30408.4427,"StatusCode":200,"ContentType":"application/octet-stream","ContentLength":null,"Protocol":"HTTP/1.1","Method":"GET","Scheme":"http","Host":"127.0.0.1:50625","PathBase":"","Path":"/trace","QueryString":"?pid=42253\u0026durationSeconds=-1\u0026profile=Http"},"Scopes":[{"Message":"SpanId:b88a8a5104943128, TraceId:6d10ef23c9a696e53783b4f775120c44, ParentId:0000000000000000","SpanId":"b88a8a5104943128","TraceId":"6d10ef23c9a696e53783b4f775120c44","ParentId":"0000000000000000"},{"Message":"ConnectionId:0HMLLNGB7D5BL","ConnectionId":"0HMLLNGB7D5BL"},{"Message":"RequestPath:/trace RequestId:0HMLLNGB7D5BL:00000002","RequestId":"0HMLLNGB7D5BL:00000002","RequestPath":"/trace"}]}
[Monitor] {"Timestamp":"12:34:56 ","EventId":33,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService","Message":"Collection rule \u0027FunctionalTestRule\u0027 action \u0027Execute\u0027 started.","State":{"Message":"Collection rule \u0027FunctionalTestRule\u0027 action \u0027Execute\u0027 started.","ruleName":"FunctionalTestRule","actionType":"Execute","{OriginalFormat}":"Collection rule \u0027{ruleName}\u0027 action \u0027{actionType}\u0027 started."},"Scopes":[{"Message":"TargetProcessId:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543 CollectionRuleName:FunctionalTestRule","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543","CollectionRuleName":"FunctionalTestRule"},{"Message":"CollectionRuleTriggerType:AspNetResponseStatus","CollectionRuleTriggerType":"AspNetResponseStatus"},{"Message":"CollectionRuleActionType:Execute CollectionRuleActionIndex:0","CollectionRuleActionType":"Execute","CollectionRuleActionIndex":0}]}
[Monitor] {"Timestamp":"12:34:57 ","EventId":34,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService","Message":"Collection rule \u0027FunctionalTestRule\u0027 action \u0027Execute\u0027 completed.","State":{"Message":"Collection rule \u0027FunctionalTestRule\u0027 action \u0027Execute\u0027 completed.","ruleName":"FunctionalTestRule","actionType":"Execute","{OriginalFormat}":"Collection rule \u0027{ruleName}\u0027 action \u0027{actionType}\u0027 completed."},"Scopes":[{"Message":"TargetProcessId:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543 CollectionRuleName:FunctionalTestRule","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543","CollectionRuleName":"FunctionalTestRule"},{"Message":"CollectionRuleTriggerType:AspNetResponseStatus","CollectionRuleTriggerType":"AspNetResponseStatus"}]}
[Monitor] {"Timestamp":"12:34:57 ","EventId":39,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService","Message":"Collection rule \u0027FunctionalTestRule\u0027 actions completed.","State":{"Message":"Collection rule \u0027FunctionalTestRule\u0027 actions completed.","ruleName":"FunctionalTestRule","{OriginalFormat}":"Collection rule \u0027{ruleName}\u0027 actions completed."},"Scopes":[{"Message":"TargetProcessId:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543 CollectionRuleName:FunctionalTestRule","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543","CollectionRuleName":"FunctionalTestRule"},{"Message":"CollectionRuleTriggerType:AspNetResponseStatus","CollectionRuleTriggerType":"AspNetResponseStatus"}]}
[Monitor] {"Timestamp":"12:34:57 ","EventId":35,"LogLevel":"Information","Category":"Microsoft.Diagnostics.Tools.Monitor.CollectionRules.CollectionRuleService","Message":"Collection rule \u0027FunctionalTestRule\u0027 trigger \u0027AspNetResponseStatus\u0027 started.","State":{"Message":"Collection rule \u0027FunctionalTestRule\u0027 trigger \u0027AspNetResponseStatus\u0027 started.","ruleName":"FunctionalTestRule","triggerType":"AspNetResponseStatus","{OriginalFormat}":"Collection rule \u0027{ruleName}\u0027 trigger \u0027{triggerType}\u0027 started."},"Scopes":[{"Message":"TargetProcessId:42253 TargetRuntimeInstanceCookie:b816f639dbcd4aa5aab829c39ae6f543 CollectionRuleName:FunctionalTestRule","TargetProcessId":"42253","TargetRuntimeInstanceCookie":"b816f639dbcd4aa5aab829c39ae6f543","CollectionRuleName":"FunctionalTestRule"},{"Message":"CollectionRuleTriggerType:AspNetResponseStatus","CollectionRuleTriggerType":"AspNetResponseStatus"},{"Message":"CollectionRuleTriggerType:AspNetResponseStatus","CollectionRuleTriggerType":"AspNetResponseStatus"}]}
schmittjoseph commented 1 year ago

Pipeline analytics show this test to still be flaky.

Example failure: https://dev.azure.com/dnceng-public/public/_build/results?buildId=223180&view=ms.vss-test-web.build-test-results-tab&runId=4189766&resultId=100114&paneView=attachments