From: Justin Anderson Date: Tue, 12 Jan 2021 22:04:45 +0000 (-0800) Subject: Logging improvements for dotnet-monitor (#1873) X-Git-Tag: submit/tizen/20210909.063632~17^2~201 X-Git-Url: http://review.tizen.org/git/?a=commitdiff_plain;h=698b96f1695a62167917a2e59ee5ef71e91327d0;p=platform%2Fcore%2Fdotnet%2Fdiagnostics.git Logging improvements for dotnet-monitor (#1873) Log common actions and exceptions with artifact type and process information. Refactor host builder to route lifetime events through logging and include event log by default. Consolidate process acquisition for DiagController with logging scopes. Only write experiment message through logging and always enable its category. Add correlation and process data as blob metadata. --- diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/ActionContextExtensions.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/ActionContextExtensions.cs index e96b60ba3..6e751f922 100644 --- a/src/Microsoft.Diagnostics.Monitoring.RestServer/ActionContextExtensions.cs +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/ActionContextExtensions.cs @@ -2,8 +2,10 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using Microsoft.AspNetCore.Http.Features; using Microsoft.AspNetCore.Mvc; using Microsoft.Diagnostics.NETCore.Client; +using Microsoft.Extensions.Logging; using System; using System.ComponentModel.DataAnnotations; using System.Net; @@ -14,47 +16,79 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer { internal static class ActionContextExtensions { + private const string ExceptionLogMessage = "Request failed."; + public static Task ProblemAsync(this ActionContext context, Exception ex) { - ActionResult result = new BadRequestObjectResult(ex.ToProblemDetails((int)HttpStatusCode.BadRequest)); + if (context.HttpContext.Features.Get().HasStarted) + { + // If already started writing response, do not rewrite + // as this will throw an InvalidOperationException. + return Task.CompletedTask; + } + else + { + ActionResult result = new BadRequestObjectResult(ex.ToProblemDetails((int)HttpStatusCode.BadRequest)); - return result.ExecuteResultAsync(context); + return result.ExecuteResultAsync(context); + } } - public static async Task InvokeAsync(this ActionContext context, Func action) + public static async Task InvokeAsync(this ActionContext context, Func action, ILogger logger) { + CancellationToken token = context.HttpContext.RequestAborted; + // Exceptions are logged in the "when" clause in order to preview the exception + // from the point of where it was thrown. This allows capturing of the log scopes + // that were active when the exception was thrown. Waiting to log during the exception + // handler will miss any scopes that were added during invocation of action. try { - await action(context.HttpContext.RequestAborted); + await action(token); + } + catch (ArgumentException ex) when (LogError(logger, ex)) + { + await context.ProblemAsync(ex); } - catch (ArgumentException ex) + catch (DiagnosticsClientException ex) when (LogError(logger, ex)) { await context.ProblemAsync(ex); } - catch (DiagnosticsClientException ex) + catch (InvalidOperationException ex) when (LogError(logger, ex)) { await context.ProblemAsync(ex); } - catch (InvalidOperationException ex) + catch (OperationCanceledException ex) when (token.IsCancellationRequested && LogInformation(logger, ex)) { await context.ProblemAsync(ex); } - catch (OperationCanceledException ex) + catch (OperationCanceledException ex) when (LogError(logger, ex)) { await context.ProblemAsync(ex); } - catch (MonitoringException ex) + catch (MonitoringException ex) when (LogError(logger, ex)) { await context.ProblemAsync(ex); } - catch (ValidationException ex) + catch (ValidationException ex) when (LogError(logger, ex)) { await context.ProblemAsync(ex); } - catch (UnauthorizedAccessException ex) + catch (UnauthorizedAccessException ex) when (LogError(logger, ex)) { await context.ProblemAsync(ex); } } + + private static bool LogError(ILogger logger, Exception ex) + { + logger.LogError(ex, ExceptionLogMessage); + return true; + } + + private static bool LogInformation(ILogger logger, Exception ex) + { + logger.LogInformation(ex.Message); + return true; + } } } diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/ArtifactMetadataNames.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/ArtifactMetadataNames.cs new file mode 100644 index 000000000..5aebdc9b1 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/ArtifactMetadataNames.cs @@ -0,0 +1,33 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +namespace Microsoft.Diagnostics.Monitoring.RestServer +{ + /// + /// Metadata keys that represent artfiact information. + /// + internal static class ArtifactMetadataNames + { + /// + /// Represents the type of artifact created from the source. + /// + public const string ArtifactType = nameof(ArtifactType); + + /// + /// Metadata keus that represent the source of an artifact. + /// + public static class ArtifactSource + { + /// + /// The ID of the process from which the artifact was collected. + /// + public const string ProcessId = nameof(ArtifactSource) + "_" + nameof(ProcessId); + + /// + /// The runtime instance cookie of the process from which the artifact was collected. + /// + public const string RuntimeInstanceCookie = nameof(ArtifactSource) + "_" + nameof(RuntimeInstanceCookie); + } + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagController.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagController.cs index 09211c4a8..0862e7674 100644 --- a/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagController.cs +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagController.cs @@ -28,6 +28,11 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers [HostRestriction] public class DiagController : ControllerBase { + private const string ArtifactType_Dump = "dump"; + private const string ArtifactType_GCDump = "gcdump"; + private const string ArtifactType_Logs = "logs"; + private const string ArtifactType_Trace = "trace"; + private const TraceProfile DefaultTraceProfiles = TraceProfile.Cpu | TraceProfile.Http | TraceProfile.Metrics; private static readonly MediaTypeHeaderValue NdJsonHeader = new MediaTypeHeaderValue(ContentTypes.ApplicationNdJson); private static readonly MediaTypeHeaderValue EventStreamHeader = new MediaTypeHeaderValue(ContentTypes.TextEventStream); @@ -52,33 +57,24 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers processesIdentifiers.Add(ProcessIdentifierModel.FromProcessInfo(p)); } return new ActionResult>(processesIdentifiers); - }); + }, _logger); } [HttpGet("processes/{processFilter}")] public Task> GetProcess( ProcessFilter processFilter) { - return this.InvokeService(async () => - { - IProcessInfo processInfo = await _diagnosticServices.GetProcessAsync( - processFilter, - HttpContext.RequestAborted); - - return ProcessModel.FromProcessInfo(processInfo); - }); + return InvokeForProcess( + processInfo => ProcessModel.FromProcessInfo(processInfo), + processFilter); } [HttpGet("processes/{processFilter}/env")] public Task>> GetProcessEnvironment( ProcessFilter processFilter) { - return this.InvokeService>(async () => + return InvokeForProcess>(processInfo => { - IProcessInfo processInfo = await _diagnosticServices.GetProcessAsync( - processFilter, - HttpContext.RequestAborted); - var client = new DiagnosticsClient(processInfo.EndpointInfo.Endpoint); try @@ -89,7 +85,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers { throw new InvalidOperationException("Unable to get process environment."); } - }); + }, + processFilter); } [HttpGet("dump/{processFilter?}")] @@ -98,10 +95,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers [FromQuery] DumpType type = DumpType.WithHeap, [FromQuery] string egressProvider = null) { - return this.InvokeService(async () => + return InvokeForProcess(async processInfo => { - IProcessInfo processInfo = await _diagnosticServices.GetProcessAsync(processFilter, HttpContext.RequestAborted); - string dumpFileName = RuntimeInformation.IsOSPlatform(OSPlatform.Windows) ? FormattableString.Invariant($"dump_{GetFileNameTimeStampUtcNow()}.dmp") : FormattableString.Invariant($"core_{GetFileNameTimeStampUtcNow()}"); @@ -116,14 +111,19 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers } else { + KeyValueLogScope scope = new KeyValueLogScope(); + scope.AddArtifactType(ArtifactType_Dump); + scope.AddEndpointInfo(processInfo.EndpointInfo); + return new EgressStreamResult( token => _diagnosticServices.GetDump(processInfo, type, token), egressProvider, dumpFileName, processInfo.EndpointInfo, - ContentTypes.ApplicationOctectStream); + ContentTypes.ApplicationOctectStream, + scope); } - }); + }, processFilter, ArtifactType_Dump); } [HttpGet("gcdump/{processFilter?}")] @@ -131,10 +131,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers ProcessFilter? processFilter, [FromQuery] string egressProvider = null) { - return this.InvokeService(async () => + return InvokeForProcess(processInfo => { - IProcessInfo processInfo = await _diagnosticServices.GetProcessAsync(processFilter, HttpContext.RequestAborted); - string fileName = FormattableString.Invariant($"{GetFileNameTimeStampUtcNow()}_{processInfo.EndpointInfo.ProcessId}.gcdump"); Func> action = async (token) => { @@ -157,12 +155,13 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers }; return Result( + ArtifactType_GCDump, egressProvider, ConvertFastSerializeAction(action), fileName, ContentTypes.ApplicationOctectStream, processInfo.EndpointInfo); - }); + }, processFilter, ArtifactType_GCDump); } [HttpGet("trace/{processFilter?}")] @@ -173,10 +172,10 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers [FromQuery][Range(1, int.MaxValue)] int metricsIntervalSeconds = 1, [FromQuery] string egressProvider = null) { - TimeSpan duration = ConvertSecondsToTimeSpan(durationSeconds); - - return this.InvokeService(async () => + return InvokeForProcess(processInfo => { + TimeSpan duration = ConvertSecondsToTimeSpan(durationSeconds); + var configurations = new List(); if (profile.HasFlag(TraceProfile.Cpu)) { @@ -197,8 +196,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers var aggregateConfiguration = new AggregateSourceConfiguration(configurations.ToArray()); - return await StartTrace(processFilter, aggregateConfiguration, duration, egressProvider); - }); + return StartTrace(processInfo, aggregateConfiguration, duration, egressProvider); + }, processFilter, ArtifactType_Trace); } [HttpPost("trace/{processFilter?}")] @@ -208,10 +207,10 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers [FromQuery][Range(-1, int.MaxValue)] int durationSeconds = 30, [FromQuery] string egressProvider = null) { - TimeSpan duration = ConvertSecondsToTimeSpan(durationSeconds); - - return this.InvokeService(async () => + return InvokeForProcess(processInfo => { + TimeSpan duration = ConvertSecondsToTimeSpan(durationSeconds); + var providers = new List(); foreach (EventPipeProviderModel providerModel in configuration.Providers) @@ -234,8 +233,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers requestRundown: configuration.RequestRundown, bufferSizeInMB: configuration.BufferSizeInMB); - return await StartTrace(processFilter, traceConfiguration, duration, egressProvider); - }); + return StartTrace(processInfo, traceConfiguration, duration, egressProvider); + }, processFilter, ArtifactType_Trace); } [HttpGet("logs/{processFilter?}")] @@ -246,10 +245,9 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers [FromQuery] LogLevel level = LogLevel.Debug, [FromQuery] string egressProvider = null) { - TimeSpan duration = ConvertSecondsToTimeSpan(durationSeconds); - return this.InvokeService(async () => + return InvokeForProcess(processInfo => { - IProcessInfo processInfo = await _diagnosticServices.GetProcessAsync(processFilter, HttpContext.RequestAborted); + TimeSpan duration = ConvertSecondsToTimeSpan(durationSeconds); LogFormat format = ComputeLogFormat(Request.GetTypedHeaders().Accept); if (format == LogFormat.None) @@ -279,23 +277,22 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers }; return Result( + ArtifactType_Logs, egressProvider, action, fileName, contentType, processInfo.EndpointInfo, format != LogFormat.EventStream); - }); + }, processFilter, ArtifactType_Logs); } - private async Task StartTrace( - ProcessFilter? processFilter, + private ActionResult StartTrace( + IProcessInfo processInfo, MonitoringSourceConfiguration configuration, TimeSpan duration, string egressProvider) { - IProcessInfo processInfo = await _diagnosticServices.GetProcessAsync(processFilter, HttpContext.RequestAborted); - string fileName = FormattableString.Invariant($"{GetFileNameTimeStampUtcNow()}_{processInfo.EndpointInfo.ProcessId}.nettrace"); Func action = async (outputStream, token) => @@ -319,6 +316,7 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers }; return Result( + ArtifactType_Trace, egressProvider, action, fileName, @@ -364,7 +362,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers return LogFormat.None; } - private static ActionResult Result( + private ActionResult Result( + string artifactType, string providerName, Func action, string fileName, @@ -372,12 +371,17 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers IEndpointInfo endpointInfo, bool asAttachment = true) { + KeyValueLogScope scope = new KeyValueLogScope(); + scope.AddArtifactType(artifactType); + scope.AddEndpointInfo(endpointInfo); + if (string.IsNullOrEmpty(providerName)) { return new OutputStreamResult( action, contentType, - asAttachment ? fileName : null); + asAttachment ? fileName : null, + scope); } else { @@ -386,7 +390,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers providerName, fileName, endpointInfo, - contentType); + contentType, + scope); } } @@ -429,5 +434,56 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers } }; } + + private Task InvokeForProcess(Func func, ProcessFilter? filter, string artifactType = null) + { + Func> asyncFunc = + processInfo => Task.FromResult(func(processInfo)); + + return InvokeForProcess(asyncFunc, filter, artifactType); + } + + private async Task InvokeForProcess(Func> func, ProcessFilter? filter, string artifactType) + { + ActionResult result = await InvokeForProcess(async processInfo => await func(processInfo), filter, artifactType); + + return result.Result; + } + + private Task> InvokeForProcess(Func> func, ProcessFilter? filter, string artifactType = null) + { + return InvokeForProcess(processInfo => Task.FromResult(func(processInfo)), filter, artifactType); + } + + private async Task> InvokeForProcess(Func>> func, ProcessFilter? filter, string artifactType = null) + { + IDisposable artifactTypeRegistration = null; + if (!string.IsNullOrEmpty(artifactType)) + { + KeyValueLogScope artifactTypeScope = new KeyValueLogScope(); + artifactTypeScope.AddArtifactType(artifactType); + artifactTypeRegistration = _logger.BeginScope(artifactTypeScope); + } + + try + { + return await this.InvokeService(async () => + { + IProcessInfo processInfo = await _diagnosticServices.GetProcessAsync(filter, HttpContext.RequestAborted); + + KeyValueLogScope processInfoScope = new KeyValueLogScope(); + processInfoScope.AddEndpointInfo(processInfo.EndpointInfo); + using var _ = _logger.BeginScope(processInfoScope); + + _logger.LogDebug("Resolved target process."); + + return await func(processInfo); + }, _logger); + } + finally + { + artifactTypeRegistration?.Dispose(); + } + } } } diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagControllerExtensions.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagControllerExtensions.cs index b9857df82..450bbe32f 100644 --- a/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagControllerExtensions.cs +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/DiagControllerExtensions.cs @@ -4,9 +4,11 @@ using Microsoft.AspNetCore.Mvc; using Microsoft.Diagnostics.NETCore.Client; +using Microsoft.Extensions.Logging; using System; using System.ComponentModel.DataAnnotations; using System.Net; +using System.Threading; using System.Threading.Tasks; // For more information on enabling MVC for empty projects, visit https://go.microsoft.com/fwlink/?LinkID=397860 @@ -15,60 +17,71 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers { internal static class DiagControllerExtensions { + private const string ExceptionLogMessage = "Request failed."; + public static ActionResult NotAcceptable(this ControllerBase controller) { return new StatusCodeResult((int)HttpStatusCode.NotAcceptable); } - public static ActionResult InvokeService(this ControllerBase controller, Func serviceCall) + public static ActionResult InvokeService(this ControllerBase controller, Func serviceCall, ILogger logger) { //We can convert ActionResult to ActionResult //and then safely convert back. - return controller.InvokeService(() => serviceCall()).Result; + return controller.InvokeService(() => serviceCall(), logger).Result; } - public static ActionResult InvokeService(this ControllerBase controller, Func> serviceCall) + public static ActionResult InvokeService(this ControllerBase controller, Func> serviceCall, ILogger logger) { //Convert from ActionResult to Task> //and safely convert back. - return controller.InvokeService(() => Task.FromResult(serviceCall())).Result; + return controller.InvokeService(() => Task.FromResult(serviceCall()), logger).Result; } - public static async Task InvokeService(this ControllerBase controller, Func> serviceCall) + public static async Task InvokeService(this ControllerBase controller, Func> serviceCall, ILogger logger) { //Task -> Task> //Then unwrap the result back to ActionResult - ActionResult result = await controller.InvokeService(async () => await serviceCall()); + ActionResult result = await controller.InvokeService(async () => await serviceCall(), logger); return result.Result; } - public static async Task> InvokeService(this ControllerBase controller, Func>> serviceCall) + public static async Task> InvokeService(this ControllerBase controller, Func>> serviceCall, ILogger logger) { + CancellationToken token = controller.HttpContext.RequestAborted; + // Exceptions are logged in the "when" clause in order to preview the exception + // from the point of where it was thrown. This allows capturing of the log scopes + // that were active when the exception was thrown. Waiting to log during the exception + // handler will miss any scopes that were added during invocation of serviceCall. try { return await serviceCall(); } - catch (ArgumentException e) + catch (ArgumentException e) when (LogError(logger, e)) { return controller.Problem(e); } - catch (DiagnosticsClientException e) + catch (DiagnosticsClientException e) when (LogError(logger, e)) { return controller.Problem(e); } - catch (InvalidOperationException e) + catch (InvalidOperationException e) when (LogError(logger, e)) { return controller.Problem(e); } - catch (OperationCanceledException e) + catch (OperationCanceledException e) when (token.IsCancellationRequested && LogInformation(logger, e)) { return controller.Problem(e); } - catch (MonitoringException e) + catch (OperationCanceledException e) when (LogError(logger, e)) { return controller.Problem(e); } - catch (ValidationException e) + catch (MonitoringException e) when (LogError(logger, e)) + { + return controller.Problem(e); + } + catch (ValidationException e) when (LogError(logger, e)) { return controller.Problem(e); } @@ -78,5 +91,17 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers { return controller.BadRequest(ex.ToProblemDetails((int)HttpStatusCode.BadRequest)); } + + private static bool LogError(ILogger logger, Exception ex) + { + logger.LogError(ex, ExceptionLogMessage); + return true; + } + + private static bool LogInformation(ILogger logger, Exception ex) + { + logger.LogInformation(ex.Message); + return true; + } } } diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/MetricsController.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/MetricsController.cs index 617dcf0f7..92eca0ebb 100644 --- a/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/MetricsController.cs +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/Controllers/MetricsController.cs @@ -14,6 +14,8 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers [ApiController] public class MetricsController : ControllerBase { + private const string ArtifactType_Metrics = "metrics"; + private readonly ILogger _logger; private readonly MetricsStoreService _metricsStore; private readonly MetricsOptions _metricsOptions; @@ -37,11 +39,17 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer.Controllers throw new InvalidOperationException("Metrics was not enabled"); } + KeyValueLogScope scope = new KeyValueLogScope(); + scope.AddArtifactType(ArtifactType_Metrics); + return new OutputStreamResult(async (outputStream, token) => - { - await _metricsStore.MetricsStore.SnapshotMetrics(outputStream, token); - }, "text/plain; version=0.0.4"); - }); + { + await _metricsStore.MetricsStore.SnapshotMetrics(outputStream, token); + }, + "text/plain; version=0.0.4", + null, + scope); + }, _logger); } } } diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/EgressStreamResult.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/EgressStreamResult.cs index fbc14d1f8..9239a6494 100644 --- a/src/Microsoft.Diagnostics.Monitoring.RestServer/EgressStreamResult.cs +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/EgressStreamResult.cs @@ -4,6 +4,7 @@ using Microsoft.AspNetCore.Mvc; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using System; using System.Collections.Generic; using System.IO; @@ -15,26 +16,37 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer internal class EgressStreamResult : ActionResult { private readonly Func> _egress; + private readonly KeyValueLogScope _scope; - public EgressStreamResult(Func> action, string endpointName, string artifactName, IEndpointInfo source, string contentType) + public EgressStreamResult(Func> action, string endpointName, string artifactName, IEndpointInfo source, string contentType, KeyValueLogScope scope) { _egress = (service, token) => service.EgressAsync(endpointName, action, artifactName, contentType, source, token); + _scope = scope; } - public EgressStreamResult(Func action, string endpointName, string artifactName, IEndpointInfo source, string contentType) + public EgressStreamResult(Func action, string endpointName, string artifactName, IEndpointInfo source, string contentType, KeyValueLogScope scope) { _egress = (service, token) => service.EgressAsync(endpointName, action, artifactName, contentType, source, token); + _scope = scope; } - public override Task ExecuteResultAsync(ActionContext context) + public override async Task ExecuteResultAsync(ActionContext context) { - return context.InvokeAsync(async (token) => + ILogger logger = context.HttpContext.RequestServices + .GetRequiredService() + .CreateLogger(); + + using var _ = logger.BeginScope(_scope); + + await context.InvokeAsync(async (token) => { IEgressService egressService = context.HttpContext.RequestServices .GetRequiredService(); EgressResult egressResult = await _egress(egressService, token); + logger.LogInformation("Egressed to {0}", egressResult.Value); + // The remaining code is creating a JSON object with a single property and scalar value // that indiates where the stream data was egressed. Because the name of the artifact is // automatically generated by the REST API and the caller of the endpoint might not know @@ -45,7 +57,7 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer ActionResult jsonResult = new JsonResult(data); await jsonResult.ExecuteResultAsync(context); - }); + }, logger); } } } diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/KeyValueLogScope.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/KeyValueLogScope.cs new file mode 100644 index 000000000..2fe1c55c0 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/KeyValueLogScope.cs @@ -0,0 +1,48 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Collections; +using System.Collections.Generic; +using System.Text; + +namespace Microsoft.Diagnostics.Monitoring.RestServer +{ + // Logger implementations have different ways of serializing log scopes. This class helps those loggers + // serialize the scope information in the best way possible for each of the implementations. For example, + // the console logger will only call ToString on the scope data, thus the data needs to be formatted appropriately + // in the ToString method. Another example, the event log logger will check if the scope data impelements + // IEnumerable> and then formats each value from the enumeration; it will fallback + // calling the ToString method otherwise. + internal class KeyValueLogScope : IEnumerable> + { + public IDictionary Values = + new Dictionary(); + + IEnumerator> IEnumerable>.GetEnumerator() + { + return Values.GetEnumerator(); + } + + IEnumerator IEnumerable.GetEnumerator() + { + return ((IEnumerable)Values).GetEnumerator(); + } + + public override string ToString() + { + StringBuilder builder = new StringBuilder(); + foreach (var kvp in Values) + { + if (builder.Length > 0) + { + builder.Append(" "); + } + builder.Append(kvp.Key); + builder.Append(":"); + builder.Append(kvp.Value); + } + return builder.ToString(); + } + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/KeyValueLogScopeExtensions.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/KeyValueLogScopeExtensions.cs new file mode 100644 index 000000000..3a25e2c08 --- /dev/null +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/KeyValueLogScopeExtensions.cs @@ -0,0 +1,26 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Globalization; + +namespace Microsoft.Diagnostics.Monitoring.RestServer +{ + internal static class KeyValueLogScopeExtensions + { + public static void AddArtifactType(this KeyValueLogScope scope, string artifactType) + { + scope.Values.Add("ArtifactType", artifactType); + } + + public static void AddEndpointInfo(this KeyValueLogScope scope, IEndpointInfo endpointInfo) + { + scope.Values.Add( + ArtifactMetadataNames.ArtifactSource.ProcessId, + endpointInfo.ProcessId.ToString(CultureInfo.InvariantCulture)); + scope.Values.Add( + ArtifactMetadataNames.ArtifactSource.RuntimeInstanceCookie, + endpointInfo.RuntimeInstanceCookie.ToString("N")); + } + } +} diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/OutputStreamResult.cs b/src/Microsoft.Diagnostics.Monitoring.RestServer/OutputStreamResult.cs index 67d6cc180..09b205e27 100644 --- a/src/Microsoft.Diagnostics.Monitoring.RestServer/OutputStreamResult.cs +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/OutputStreamResult.cs @@ -3,7 +3,10 @@ // See the LICENSE file in the project root for more information. using Microsoft.AspNetCore.Mvc; +using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Logging; using System; +using System.Collections.Generic; using System.IO; using System.Net.Http.Headers; using System.Threading; @@ -16,17 +19,25 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer private readonly Func _action; private readonly string _contentType; private readonly string _fileDownloadName; + private readonly KeyValueLogScope _scope; - public OutputStreamResult(Func action, string contentType, string fileDownloadName = null) + public OutputStreamResult(Func action, string contentType, string fileDownloadName, KeyValueLogScope scope) { _contentType = contentType; _fileDownloadName = fileDownloadName; _action = action; + _scope = scope; } - public override Task ExecuteResultAsync(ActionContext context) + public override async Task ExecuteResultAsync(ActionContext context) { - return context.InvokeAsync(async (token) => + ILogger logger = context.HttpContext.RequestServices + .GetRequiredService() + .CreateLogger(); + + using var _ = logger.BeginScope(_scope); + + await context.InvokeAsync(async (token) => { if (_fileDownloadName != null) { @@ -43,7 +54,9 @@ namespace Microsoft.Diagnostics.Monitoring.RestServer #endif await _action(context.HttpContext.Response.Body, token); - }); + + logger.LogInformation("Written to HTTP stream."); + }, logger); } } } diff --git a/src/Microsoft.Diagnostics.Monitoring.RestServer/appsettings.json b/src/Microsoft.Diagnostics.Monitoring.RestServer/appsettings.json index def9159a7..f64be2ad1 100644 --- a/src/Microsoft.Diagnostics.Monitoring.RestServer/appsettings.json +++ b/src/Microsoft.Diagnostics.Monitoring.RestServer/appsettings.json @@ -1,7 +1,20 @@ { "Logging": { "LogLevel": { - "Default": "Warning" + "Default": "Information", + "Microsoft": "Warning", + "Microsoft.Hosting.Lifetime": "Information" + }, + "Console": { + "IncludeScopes": true, + "TimestampFormat": "HH:mm:ss " + }, + "EventLog": { + "LogLevel": { + "Default": "Information", + "Microsoft": "Warning", + "Microsoft.Hosting.Lifetime": "Information" + } } }, "AllowedHosts": "*" diff --git a/src/Tools/dotnet-monitor/ActivityExtensions.cs b/src/Tools/dotnet-monitor/ActivityExtensions.cs new file mode 100644 index 000000000..6da548453 --- /dev/null +++ b/src/Tools/dotnet-monitor/ActivityExtensions.cs @@ -0,0 +1,47 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using System.Diagnostics; + +namespace Microsoft.Diagnostics.Tools.Monitor +{ + internal static class ActivityExtensions + { + public static string GetSpanId(this Activity activity) + { + switch (activity.IdFormat) + { + case ActivityIdFormat.Hierarchical: + return activity.Id; + case ActivityIdFormat.W3C: + return activity.SpanId.ToHexString(); + } + return string.Empty; + } + + public static string GetParentId(this Activity activity) + { + switch (activity.IdFormat) + { + case ActivityIdFormat.Hierarchical: + return activity.ParentId; + case ActivityIdFormat.W3C: + return activity.ParentSpanId.ToHexString(); + } + return string.Empty; + } + + public static string GetTraceId(this Activity activity) + { + switch (activity.IdFormat) + { + case ActivityIdFormat.Hierarchical: + return activity.RootId; + case ActivityIdFormat.W3C: + return activity.TraceId.ToHexString(); + } + return string.Empty; + } + } +} diff --git a/src/Tools/dotnet-monitor/ActivityMetadataNames.cs b/src/Tools/dotnet-monitor/ActivityMetadataNames.cs new file mode 100644 index 000000000..0c16986bc --- /dev/null +++ b/src/Tools/dotnet-monitor/ActivityMetadataNames.cs @@ -0,0 +1,36 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +namespace Microsoft.Diagnostics.Tools.Monitor +{ + /// + /// Metadata keys that correspond to properties. + /// + internal static class ActivityMetadataNames + { + /// + /// Represents the ID of the parent activity. + /// + /// + /// This name is the same as logged by the ActivityLogScope. + /// + public const string ParentId = nameof(ParentId); + + /// + /// Represents the ID of the current activity. + /// + /// + /// This name is the same as logged by the ActivityLogScope. + /// + public const string SpanId = nameof(SpanId); + + /// + /// Represents the trace ID of the activity. + /// + /// + /// This name is the same as logged by the ActivityLogScope. + /// + public const string TraceId = nameof(TraceId); + } +} diff --git a/src/Tools/dotnet-monitor/DiagnosticsMonitorCommandHandler.cs b/src/Tools/dotnet-monitor/DiagnosticsMonitorCommandHandler.cs index aa2902de6..e8a82155c 100644 --- a/src/Tools/dotnet-monitor/DiagnosticsMonitorCommandHandler.cs +++ b/src/Tools/dotnet-monitor/DiagnosticsMonitorCommandHandler.cs @@ -8,6 +8,8 @@ using Microsoft.Diagnostics.Monitoring; using Microsoft.Diagnostics.Monitoring.RestServer; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; using System; using System.Collections.Generic; using System.CommandLine; @@ -46,19 +48,19 @@ namespace Microsoft.Diagnostics.Tools.Monitor public async Task Start(CancellationToken token, IConsole console, string[] urls, string[] metricUrls, bool metrics, string diagnosticPort) { //CONSIDER The console logger uses the standard AddConsole, and therefore disregards IConsole. - using IWebHost host = CreateWebHostBuilder(console, urls, metricUrls, metrics, diagnosticPort).Build(); + using IHost host = CreateHostBuilder(console, urls, metricUrls, metrics, diagnosticPort).Build(); await host.RunAsync(token); return 0; } - public IWebHostBuilder CreateWebHostBuilder(IConsole console, string[] urls, string[] metricUrls, bool metrics, string diagnosticPort) + public IHostBuilder CreateHostBuilder(IConsole console, string[] urls, string[] metricUrls, bool metrics, string diagnosticPort) { if (metrics) { urls = urls.Concat(metricUrls).ToArray(); } - IWebHostBuilder builder = WebHost.CreateDefaultBuilder() + return Host.CreateDefaultBuilder() .ConfigureAppConfiguration((IConfigurationBuilder builder) => { //Note these are in precedence order. @@ -74,7 +76,7 @@ namespace Microsoft.Diagnostics.Tools.Monitor builder.AddKeyPerFile(SharedConfigDirectoryPath, optional: true); builder.AddEnvironmentVariables(ConfigPrefix); }) - .ConfigureServices((WebHostBuilderContext context, IServiceCollection services) => + .ConfigureServices((HostBuilderContext context, IServiceCollection services) => { //TODO Many of these service additions should be done through extension methods services.Configure(context.Configuration.GetSection(DiagnosticPortOptions.ConfigurationKey)); @@ -86,11 +88,18 @@ namespace Microsoft.Diagnostics.Tools.Monitor { services.ConfigureMetrics(context.Configuration); } + services.AddSingleton(); }) - .UseUrls(urls) - .UseStartup(); - - return builder; + .ConfigureLogging(builder => + { + // Always allow the experimental tool message to be logged + ExperimentalToolLogger.AddLogFilter(builder); + }) + .ConfigureWebHostDefaults(webBuilder => + { + webBuilder.UseUrls(urls); + webBuilder.UseStartup(); + }); } private static void ConfigureMetricsEndpoint(IConfigurationBuilder builder, string[] metricEndpoints) diff --git a/src/Tools/dotnet-monitor/Egress/AzureBlob/AzureBlobEgressProvider.cs b/src/Tools/dotnet-monitor/Egress/AzureBlob/AzureBlobEgressProvider.cs index cefb0696b..aa24d95ec 100644 --- a/src/Tools/dotnet-monitor/Egress/AzureBlob/AzureBlobEgressProvider.cs +++ b/src/Tools/dotnet-monitor/Egress/AzureBlob/AzureBlobEgressProvider.cs @@ -53,7 +53,7 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress.AzureStorage Logger?.LogDebug("End uploading to storage with headers and metadata."); string blobUriString = GetBlobUri(blobClient); - Logger?.LogInformation("Uploaded stream to {0}", blobUriString); + Logger?.LogDebug("Uploaded stream to {0}", blobUriString); return blobUriString; } catch (AggregateException ex) when (ex.InnerException is RequestFailedException innerException) @@ -101,7 +101,7 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress.AzureStorage Logger?.LogDebug("End writing metadata."); string blobUriString = GetBlobUri(blobClient); - Logger?.LogInformation("Uploaded stream to {0}", blobUriString); + Logger?.LogDebug("Uploaded stream to {0}", blobUriString); return blobUriString; } catch (AggregateException ex) when (ex.InnerException is RequestFailedException innerException) diff --git a/src/Tools/dotnet-monitor/Egress/AzureBlobEgressFactory.cs b/src/Tools/dotnet-monitor/Egress/AzureBlobEgressFactory.cs index 0230693f0..2d7dc45d8 100644 --- a/src/Tools/dotnet-monitor/Egress/AzureBlobEgressFactory.cs +++ b/src/Tools/dotnet-monitor/Egress/AzureBlobEgressFactory.cs @@ -9,6 +9,8 @@ using Microsoft.Extensions.Configuration; using Microsoft.Extensions.Logging; using System; using System.Collections.Generic; +using System.Diagnostics; +using System.Globalization; using System.IO; using System.Threading; using System.Threading.Tasks; @@ -94,9 +96,9 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress IEndpointInfo source, CancellationToken token) { - // TODO: Add metadata based on source var streamOptions = new AzureBlobEgressStreamOptions(); streamOptions.ContentType = contentType; + FillBlobMetadata(streamOptions.Metadata, source); string blobUri = await _provider.EgressAsync(action, fileName, streamOptions, token); @@ -110,14 +112,40 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress IEndpointInfo source, CancellationToken token) { - // TODO: Add metadata based on source var streamOptions = new AzureBlobEgressStreamOptions(); streamOptions.ContentType = contentType; + FillBlobMetadata(streamOptions.Metadata, source); string blobUri = await _provider.EgressAsync(action, fileName, streamOptions, token); return new EgressResult("uri", blobUri); } + + private static void FillBlobMetadata(IDictionary metadata, IEndpointInfo source) + { + // Activity metadata + Activity activity = Activity.Current; + if (null != activity) + { + metadata.Add( + ActivityMetadataNames.ParentId, + activity.GetParentId()); + metadata.Add( + ActivityMetadataNames.SpanId, + activity.GetSpanId()); + metadata.Add( + ActivityMetadataNames.TraceId, + activity.GetTraceId()); + } + + // Artifact metadata + metadata.Add( + ArtifactMetadataNames.ArtifactSource.ProcessId, + source.ProcessId.ToString(CultureInfo.InvariantCulture)); + metadata.Add( + ArtifactMetadataNames.ArtifactSource.RuntimeInstanceCookie, + source.RuntimeInstanceCookie.ToString("N")); + } } /// diff --git a/src/Tools/dotnet-monitor/Egress/Configuration/EgressConfigureOptions.cs b/src/Tools/dotnet-monitor/Egress/Configuration/EgressConfigureOptions.cs index 98e98f56b..379b557a9 100644 --- a/src/Tools/dotnet-monitor/Egress/Configuration/EgressConfigureOptions.cs +++ b/src/Tools/dotnet-monitor/Egress/Configuration/EgressConfigureOptions.cs @@ -2,6 +2,7 @@ // The .NET Foundation licenses this file to you under the MIT license. // See the LICENSE file in the project root for more information. +using Microsoft.Diagnostics.Monitoring.RestServer; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Options; @@ -64,7 +65,9 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress.Configuration { string providerName = providerSection.Key; - using var providerNameScope = _logger.BeginScope(new Dictionary() { { "ProviderName", providerName } }); + KeyValueLogScope providerNameScope = new KeyValueLogScope(); + providerNameScope.Values.Add("EgressProviderName", providerName); + using var providerNameRegistration = _logger.BeginScope(providerNameScope); CommonEgressProviderOptions commonOptions = new CommonEgressProviderOptions(); providerSection.Bind(commonOptions); @@ -76,7 +79,9 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress.Configuration } string providerType = commonOptions.Type; - using var providerTypeScope = _logger.BeginScope(new Dictionary() { { "ProviderType", providerType } }); + KeyValueLogScope providerTypeScope = new KeyValueLogScope(); + providerTypeScope.Values.Add("EgressProviderType", providerType); + using var providerTypeRegistration = _logger.BeginScope(providerTypeScope); if (!_factories.TryGetValue(providerType, out EgressFactory factory)) { @@ -92,7 +97,7 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress.Configuration options.Providers.Add(providerName, provider); - _logger.LogInformation("Added egress provider '{0}'.", providerName); + _logger.LogDebug("Added egress provider '{0}'.", providerName); } _logger.LogDebug("End loading egress providers."); } diff --git a/src/Tools/dotnet-monitor/Egress/FileSystem/FileSystemEgressProvider.cs b/src/Tools/dotnet-monitor/Egress/FileSystem/FileSystemEgressProvider.cs index 19ff5340a..9d41a20b9 100644 --- a/src/Tools/dotnet-monitor/Egress/FileSystem/FileSystemEgressProvider.cs +++ b/src/Tools/dotnet-monitor/Egress/FileSystem/FileSystemEgressProvider.cs @@ -98,7 +98,7 @@ namespace Microsoft.Diagnostics.Tools.Monitor.Egress.FileSystem await WriteFileAsync(action, targetPath, token); } - Logger?.LogInformation("Saved stream to '{0}.", targetPath); + Logger?.LogDebug("Saved stream to '{0}.", targetPath); return targetPath; } diff --git a/src/Tools/dotnet-monitor/ExperimentalToolLogger.cs b/src/Tools/dotnet-monitor/ExperimentalToolLogger.cs new file mode 100644 index 000000000..7e74a6e7c --- /dev/null +++ b/src/Tools/dotnet-monitor/ExperimentalToolLogger.cs @@ -0,0 +1,31 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +using Microsoft.Extensions.Logging; + +namespace Microsoft.Diagnostics.Tools.Monitor +{ + // FUTURE: This log message should be removed when dotnet-monitor is no longer an experimental tool + internal class ExperimentalToolLogger + { + private const string ExperimentMessage = "WARNING: dotnet-monitor is experimental and is not intended for production environments yet."; + + private readonly ILogger _logger; + + public ExperimentalToolLogger(ILogger logger) + { + _logger = logger; + } + + public void LogExperimentMessage() + { + _logger.LogWarning(ExperimentMessage); + } + + public static void AddLogFilter(ILoggingBuilder builder) + { + builder.AddFilter(typeof(ExperimentalToolLogger).FullName, LogLevel.Warning); + } + } +} diff --git a/src/Tools/dotnet-monitor/Program.cs b/src/Tools/dotnet-monitor/Program.cs index 0c979fcdf..df1823fb8 100644 --- a/src/Tools/dotnet-monitor/Program.cs +++ b/src/Tools/dotnet-monitor/Program.cs @@ -3,6 +3,7 @@ // See the LICENSE file in the project root for more information. using Microsoft.Diagnostics.Monitoring; +using Microsoft.Extensions.DependencyInjection; using Microsoft.Tools.Common; using System; using System.CommandLine; @@ -79,12 +80,10 @@ namespace Microsoft.Diagnostics.Tools.Monitor public static Task Main(string[] args) { - // FUTURE: This log message should be removed when dotnet-monitor is no longer an experimental tool - Console.WriteLine("WARNING: dotnet-monitor is experimental and is not intended for production environments yet."); var parser = new CommandLineBuilder() - .AddCommand(CollectCommand()) - .UseDefaults() - .Build(); + .AddCommand(CollectCommand()) + .UseDefaults() + .Build(); return parser.InvokeAsync(args); } } diff --git a/src/Tools/dotnet-monitor/Startup.cs b/src/Tools/dotnet-monitor/Startup.cs index c87c74db4..a75ab2018 100644 --- a/src/Tools/dotnet-monitor/Startup.cs +++ b/src/Tools/dotnet-monitor/Startup.cs @@ -12,10 +12,11 @@ using Microsoft.Diagnostics.Monitoring.RestServer.Controllers; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; using System.Collections.Generic; using System.IO.Compression; -namespace Microsoft.Diagnostics.Monitoring +namespace Microsoft.Diagnostics.Tools.Monitor { internal class Startup { @@ -77,8 +78,13 @@ namespace Microsoft.Diagnostics.Monitoring } // This method gets called by the runtime. Use this method to configure the HTTP request pipeline. - public void Configure(IApplicationBuilder app, IWebHostEnvironment env) + public void Configure( + IApplicationBuilder app, + IWebHostEnvironment env, + ExperimentalToolLogger logger) { + logger.LogExperimentMessage(); + if (env.IsDevelopment()) { app.UseDeveloperExceptionPage();