From 18145880fa8a8832a40e8e79d53691ba78d823ff Mon Sep 17 00:00:00 2001 From: Ryan Nowak Date: Sat, 22 Sep 2018 19:21:16 -0700 Subject: [PATCH] Improved logging for health checks - Add logging of description/data - Add logging for aggregate begin/end --- .../HealthChecksSample/GCInfoHealthCheck.cs | 4 +- samples/HealthChecksSample/Program.cs | 2 +- .../DefaultHealthCheckService.cs | 130 ++++++++++++++++-- 3 files changed, 124 insertions(+), 12 deletions(-) diff --git a/samples/HealthChecksSample/GCInfoHealthCheck.cs b/samples/HealthChecksSample/GCInfoHealthCheck.cs index 20bcc1eb11..c708f3ed3c 100644 --- a/samples/HealthChecksSample/GCInfoHealthCheck.cs +++ b/samples/HealthChecksSample/GCInfoHealthCheck.cs @@ -65,8 +65,8 @@ namespace HealthChecksSample { "Gen2Collections", GC.CollectionCount(2) }, }; - // Report failure if the allocated memory is >= the threshold - var result = allocated >= options.Threshold; + // Report failure if the allocated memory is >= the threshold. Negated because true == success + var result = !(allocated >= options.Threshold); return Task.FromResult(new HealthCheckResult( result, diff --git a/samples/HealthChecksSample/Program.cs b/samples/HealthChecksSample/Program.cs index 425b0b3f1a..0ed4ff6e3a 100644 --- a/samples/HealthChecksSample/Program.cs +++ b/samples/HealthChecksSample/Program.cs @@ -15,7 +15,7 @@ namespace HealthChecksSample { _scenarios = new Dictionary(StringComparer.OrdinalIgnoreCase) { - { "", typeof(DBHealthStartup) }, + { "", typeof(CustomWriterStartup) }, { "basic", typeof(BasicStartup) }, { "writer", typeof(CustomWriterStartup) }, { "liveness", typeof(LivenessProbeStartup) }, diff --git a/src/Microsoft.Extensions.Diagnostics.HealthChecks/DefaultHealthCheckService.cs b/src/Microsoft.Extensions.Diagnostics.HealthChecks/DefaultHealthCheckService.cs index eae633dca0..f1a41ea303 100644 --- a/src/Microsoft.Extensions.Diagnostics.HealthChecks/DefaultHealthCheckService.cs +++ b/src/Microsoft.Extensions.Diagnostics.HealthChecks/DefaultHealthCheckService.cs @@ -2,8 +2,10 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Collections; using System.Collections.Generic; using System.Linq; +using System.Text; using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; @@ -31,7 +33,7 @@ namespace Microsoft.Extensions.Diagnostics.HealthChecks // We're specifically going out of our way to do this at startup time. We want to make sure you // get any kind of health-check related error as early as possible. Waiting until someone // actually tries to **run** health checks would be real baaaaad. - ValidateRegistrations(_options.Value.Registrations); + ValidateRegistrations(_options.Value.Registrations); } public override async Task CheckHealthAsync( Func predicate, @@ -44,6 +46,9 @@ namespace Microsoft.Extensions.Diagnostics.HealthChecks var context = new HealthCheckContext(); var entries = new Dictionary(StringComparer.OrdinalIgnoreCase); + var totalTime = ValueStopwatch.StartNew(); + Log.HealthCheckProcessingBegin(_logger); + foreach (var registration in registrations) { if (predicate != null && !predicate(registration)) @@ -63,7 +68,7 @@ namespace Microsoft.Extensions.Diagnostics.HealthChecks context.Registration = registration; Log.HealthCheckBegin(_logger, registration); - + HealthReportEntry entry; try { @@ -76,6 +81,7 @@ namespace Microsoft.Extensions.Diagnostics.HealthChecks result.Data); Log.HealthCheckEnd(_logger, registration, entry, stopwatch.GetElapsedTime()); + Log.HealthCheckData(_logger, registration, entry); } // Allow cancellation to propagate. @@ -89,7 +95,9 @@ namespace Microsoft.Extensions.Diagnostics.HealthChecks } } - return new HealthReport(entries); + var report = new HealthReport(entries); + Log.HealthCheckProcessingEnd(_logger, report.Status, totalTime.GetElapsedTime()); + return report; } } @@ -112,26 +120,50 @@ namespace Microsoft.Extensions.Diagnostics.HealthChecks { public static class EventIds { - public static readonly EventId HealthCheckBegin = new EventId(100, "HealthCheckBegin"); - public static readonly EventId HealthCheckEnd = new EventId(101, "HealthCheckEnd"); - public static readonly EventId HealthCheckError = new EventId(102, "HealthCheckError"); + public static readonly EventId HealthCheckProcessingBegin = new EventId(100, "HealthCheckProcessingBegin"); + public static readonly EventId HealthCheckProcessingEnd = new EventId(101, "HealthCheckProcessingEnd"); + + public static readonly EventId HealthCheckBegin = new EventId(102, "HealthCheckBegin"); + public static readonly EventId HealthCheckEnd = new EventId(103, "HealthCheckEnd"); + public static readonly EventId HealthCheckError = new EventId(104, "HealthCheckError"); + public static readonly EventId HealthCheckData = new EventId(105, "HealthCheckData"); } + private static readonly Action _healthCheckProcessingBegin = LoggerMessage.Define( + LogLevel.Debug, + EventIds.HealthCheckProcessingBegin, + "Running health checks"); + + private static readonly Action _healthCheckProcessingEnd = LoggerMessage.Define( + LogLevel.Debug, + EventIds.HealthCheckProcessingEnd, + "Health check processing completed after {ElapsedMilliseconds}ms with combined status {HealthStatus}"); + private static readonly Action _healthCheckBegin = LoggerMessage.Define( LogLevel.Debug, EventIds.HealthCheckBegin, "Running health check {HealthCheckName}"); - private static readonly Action _healthCheckEnd = LoggerMessage.Define( + private static readonly Action _healthCheckEnd = LoggerMessage.Define( LogLevel.Debug, EventIds.HealthCheckEnd, - "Health check {HealthCheckName} completed after {ElapsedMilliseconds}ms with status {HealthCheckStatus}"); + "Health check {HealthCheckName} completed after {ElapsedMilliseconds}ms with status {HealthStatus} and '{HealthCheckDescription}'"); private static readonly Action _healthCheckError = LoggerMessage.Define( LogLevel.Error, EventIds.HealthCheckError, "Health check {HealthCheckName} threw an unhandled exception after {ElapsedMilliseconds}ms"); + public static void HealthCheckProcessingBegin(ILogger logger) + { + _healthCheckProcessingBegin(logger, null); + } + + public static void HealthCheckProcessingEnd(ILogger logger, HealthStatus status, TimeSpan duration) + { + _healthCheckProcessingEnd(logger, duration.TotalMilliseconds, status, null); + } + public static void HealthCheckBegin(ILogger logger, HealthCheckRegistration registration) { _healthCheckBegin(logger, registration.Name, null); @@ -139,13 +171,93 @@ namespace Microsoft.Extensions.Diagnostics.HealthChecks public static void HealthCheckEnd(ILogger logger, HealthCheckRegistration registration, HealthReportEntry entry, TimeSpan duration) { - _healthCheckEnd(logger, registration.Name, duration.TotalMilliseconds, entry.Status, null); + _healthCheckEnd(logger, registration.Name, duration.TotalMilliseconds, entry.Status, entry.Description, null); } public static void HealthCheckError(ILogger logger, HealthCheckRegistration registration, Exception exception, TimeSpan duration) { _healthCheckError(logger, registration.Name, duration.TotalMilliseconds, exception); } + + public static void HealthCheckData(ILogger logger, HealthCheckRegistration registration, HealthReportEntry entry) + { + if (entry.Data.Count > 0 && logger.IsEnabled(LogLevel.Debug)) + { + logger.Log( + LogLevel.Debug, + EventIds.HealthCheckData, + new HealthCheckDataLogValue(registration.Name, entry.Data), + null, + (state, ex) => state.ToString()); + } + } + } + + internal class HealthCheckDataLogValue : IReadOnlyList> + { + private readonly string _name; + private readonly List> _values; + + private string _formatted; + + public HealthCheckDataLogValue(string name, IReadOnlyDictionary values) + { + _name = name; + _values = values.ToList(); + + // We add the name as a kvp so that you can filter by health check name in the logs. + // This is the same parameter name used in the other logs. + _values.Add(new KeyValuePair("HealthCheckName", name)); + } + + public KeyValuePair this[int index] + { + get + { + if (index < 0 || index >= Count) + { + throw new IndexOutOfRangeException(nameof(index)); + } + + return _values[index]; + } + } + + public int Count => _values.Count; + + public IEnumerator> GetEnumerator() + { + return _values.GetEnumerator(); + } + + IEnumerator IEnumerable.GetEnumerator() + { + return _values.GetEnumerator(); + } + + public override string ToString() + { + if (_formatted == null) + { + var builder = new StringBuilder(); + builder.AppendLine($"Health check data for {_name}:"); + + var values = _values; + for (var i = 0; i < values.Count; i++) + { + var kvp = values[i]; + builder.Append(" "); + builder.Append(kvp.Key); + builder.Append(": "); + + builder.AppendLine(kvp.Value?.ToString()); + } + + _formatted = builder.ToString(); + } + + return _formatted; + } } } }