Duplicate logging ID and name in health checks

[JamesNK]

Is there an existing issue for this?

• I have searched the existing issues

Describe the bug

Health checks reuses a logging ID and name for end events at different log levels. We don't do this anywhere else in ASP.NET Core.

aspnetcore/src/HealthChecks/HealthChecks/src/DefaultHealthCheckService.cs

Lines 220 to 229 in 4535ea1

	#pragma warning disable SYSLIB1006
	[LoggerMessage(EventIds.HealthCheckEndId, LogLevel.Debug, HealthCheckEndText, EventName = EventIds.HealthCheckEndName)]
	private static partial void HealthCheckEndHealthy(ILogger logger, string HealthCheckName, HealthStatus HealthStatus, double ElapsedMilliseconds, string? HealthCheckDescription);
	[LoggerMessage(EventIds.HealthCheckEndId, LogLevel.Warning, HealthCheckEndText, EventName = EventIds.HealthCheckEndName)]
	private static partial void HealthCheckEndDegraded(ILogger logger, string HealthCheckName, HealthStatus HealthStatus, double ElapsedMilliseconds, string? HealthCheckDescription, Exception? exception);
	[LoggerMessage(EventIds.HealthCheckEndId, LogLevel.Error, HealthCheckEndText, EventName = EventIds.HealthCheckEndName)]
	private static partial void HealthCheckEndUnhealthy(ILogger logger, string HealthCheckName, HealthStatus HealthStatus, double ElapsedMilliseconds, string? HealthCheckDescription, Exception? exception);
	#pragma warning restore SYSLIB1006

Expected Behavior

I think we should have different log messages for different events to be consistent with the rest of the logging.

Steps To Reproduce

No response

Exceptions (if any)

No response

.NET Version

No response

Anything else?

No response

[BrennanConroy]

Similar to #46072

[JamesNK]

Ah, I hadn't seen that.

The difference is those duplicates look like accidents. Health checks look like it was intentionally designed with duplicates.

[eerhardt]

Also note that there are duplicate Ids for HealthCheckPublisherError and HealthCheckPublisherTimeout.

aspnetcore/src/HealthChecks/HealthChecks/src/HealthCheckPublisherHostedService.cs

Lines 201 to 202 in 6a6d775

	public const int HealthCheckPublisherErrorId = 104;
	public const int HealthCheckPublisherTimeoutId = 104;

aspnetcore/src/HealthChecks/HealthChecks/src/HealthCheckPublisherHostedService.cs

Lines 236 to 245 in 6a6d775

	#pragma warning disable SYSLIB1006
	[LoggerMessage(EventIds.HealthCheckPublisherErrorId, LogLevel.Error, "Health check {HealthCheckPublisher} threw an unhandled exception after {ElapsedMilliseconds}ms", EventName = EventIds.HealthCheckPublisherErrorName)]
	private static partial void HealthCheckPublisherError(ILogger logger, IHealthCheckPublisher HealthCheckPublisher, double ElapsedMilliseconds, Exception exception);
	public static void HealthCheckPublisherTimeout(ILogger logger, IHealthCheckPublisher publisher, TimeSpan duration) =>
	HealthCheckPublisherTimeout(logger, publisher, duration.TotalMilliseconds);
	[LoggerMessage(EventIds.HealthCheckPublisherTimeoutId, LogLevel.Error, "Health check {HealthCheckPublisher} was canceled after {ElapsedMilliseconds}ms", EventName = EventIds.HealthCheckPublisherTimeoutName)]
	private static partial void HealthCheckPublisherTimeout(ILogger logger, IHealthCheckPublisher HealthCheckPublisher, double ElapsedMilliseconds);
	#pragma warning restore SYSLIB1006

[mitchdenny]

What would be the possible reason for deliberately duplicating the event IDs here? I think it would be good to fix this but I have two thoughts:

1. Why was it done like this in the first place (Chesterton's fence)?
2. What level of concern do we have about changing these event ids being a breaking change?

[BrennanConroy]

This was likely done because the logs are basically for the same thing, an error occurred during PublishAsync. You can even see in the code that the logs are used right next to each other, just for different exception types:

aspnetcore/src/HealthChecks/HealthChecks/src/HealthCheckPublisherHostedService.cs

Lines 183 to 190 in 6a6d775

	catch (OperationCanceledException)
	{
	Logger.HealthCheckPublisherTimeout(_logger, publisher, duration.GetElapsedTime());
	throw;
	}
	catch (Exception ex)
	{
	Logger.HealthCheckPublisherError(_logger, publisher, duration.GetElapsedTime(), ex);

[mitchdenny]

They are semantically different though. A timeout (notified via a cancellation exception) is very different to an exception that you also happen to record an elapsed time for.

(not doubting your reasoning though ;P)