Skip to content

Commit

Permalink
Use LoggerMessage.Define in HttpSys (#31333)
Browse files Browse the repository at this point in the history
- Use LoggerMessage.Define() throughout HttpSys instead of ILogger extension methods.
- Also updates two incorrect event Id field names.

Fixes #31313.
  • Loading branch information
martincostello authored Mar 28, 2021
1 parent 223541c commit 020745c
Show file tree
Hide file tree
Showing 21 changed files with 534 additions and 64 deletions.
78 changes: 78 additions & 0 deletions src/Servers/HttpSys/src/HttpSysListener.Log.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,78 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.

using System;
using Microsoft.Extensions.Logging;

namespace Microsoft.AspNetCore.Server.HttpSys
{
internal partial class HttpSysListener
{
private static class Log
{
private static readonly Action<ILogger, Exception?> _listenerDisposeError =
LoggerMessage.Define(LogLevel.Error, LoggerEventIds.ListenerDisposeError, "Dispose");

private static readonly Action<ILogger, Exception?> _listenerDisposing =
LoggerMessage.Define(LogLevel.Trace, LoggerEventIds.ListenerDisposing, "Disposing the listener.");

private static readonly Action<ILogger, Exception?> _httpSysListenerCtorError =
LoggerMessage.Define(LogLevel.Error, LoggerEventIds.HttpSysListenerCtorError, ".Ctor");

private static readonly Action<ILogger, Exception?> _listenerStartError =
LoggerMessage.Define(LogLevel.Error, LoggerEventIds.ListenerStartError, "Start");

private static readonly Action<ILogger, Exception?> _listenerStarting =
LoggerMessage.Define(LogLevel.Trace, LoggerEventIds.ListenerStarting, "Starting the listener.");

private static readonly Action<ILogger, Exception?> _listenerStopError =
LoggerMessage.Define(LogLevel.Error, LoggerEventIds.ListenerStopError, "Stop");

private static readonly Action<ILogger, Exception?> _listenerStopping =
LoggerMessage.Define(LogLevel.Trace, LoggerEventIds.ListenerStopping, "Stopping the listener.");

private static readonly Action<ILogger, ulong, Exception?> _requestValidationFailed =
LoggerMessage.Define<ulong>(LogLevel.Error, LoggerEventIds.RequestValidationFailed, "Error validating request {RequestId}");

public static void ListenerDisposeError(ILogger logger, Exception exception)
{
_listenerDisposeError(logger, exception);
}

public static void ListenerDisposing(ILogger logger)
{
_listenerDisposing(logger, null);
}

public static void HttpSysListenerCtorError(ILogger logger, Exception exception)
{
_httpSysListenerCtorError(logger, exception);
}

public static void ListenerStartError(ILogger logger, Exception exception)
{
_listenerStartError(logger, exception);
}

public static void ListenerStarting(ILogger logger)
{
_listenerStarting(logger, null);
}

public static void ListenerStopError(ILogger logger, Exception exception)
{
_listenerStopError(logger, exception);
}

public static void ListenerStopping(ILogger logger)
{
_listenerStopping(logger, null);
}

public static void RequestValidationFailed(ILogger logger, Exception exception, ulong requestId)
{
_requestValidationFailed(logger, requestId, exception);
}
}
}
}
18 changes: 9 additions & 9 deletions src/Servers/HttpSys/src/HttpSysListener.cs
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,7 @@ namespace Microsoft.AspNetCore.Server.HttpSys
/// <summary>
/// An HTTP server wrapping the Http.Sys APIs that accepts requests.
/// </summary>
internal class HttpSysListener : IDisposable
internal partial class HttpSysListener : IDisposable
{
// Win8# 559317 fixed a bug in Http.sys's HttpReceiveClientCertificate method.
// Without this fix IOCP callbacks were not being called although ERROR_IO_PENDING was
Expand Down Expand Up @@ -92,7 +92,7 @@ public HttpSysListener(HttpSysOptions options, ILoggerFactory loggerFactory)
_requestQueue?.Dispose();
_urlGroup?.Dispose();
_serverSession?.Dispose();
Logger.LogError(LoggerEventIds.HttpSysListenerCtorError, exception, ".Ctor");
Log.HttpSysListenerCtorError(Logger, exception);
throw;
}
}
Expand Down Expand Up @@ -135,7 +135,7 @@ public void Start()
{
CheckDisposed();

Logger.LogTrace(LoggerEventIds.ListenerStarting, "Starting the listener.");
Log.ListenerStarting(Logger);

// Make sure there are no race conditions between Start/Stop/Abort/Close/Dispose.
// Start needs to setup all resources. Abort/Stop must not interfere while Start is
Expand Down Expand Up @@ -177,7 +177,7 @@ public void Start()
// Make sure the HttpListener instance can't be used if Start() failed.
_state = State.Disposed;
DisposeInternal();
Logger.LogError(LoggerEventIds.ListenerStartError, exception, "Start");
Log.ListenerStartError(Logger, exception);
throw;
}
}
Expand All @@ -195,7 +195,7 @@ private void Stop()
return;
}

Logger.LogTrace(LoggerEventIds.ListenerStopping, "Stopping the listener.");
Log.ListenerStopping(Logger);

// If this instance created the queue then remove the URL prefixes before shutting down.
if (_requestQueue.Created)
Expand All @@ -210,7 +210,7 @@ private void Stop()
}
catch (Exception exception)
{
Logger.LogError(LoggerEventIds.ListenerStopError, exception, "Stop");
Log.ListenerStopError(Logger, exception);
throw;
}
}
Expand Down Expand Up @@ -238,14 +238,14 @@ private void Dispose(bool disposing)
{
return;
}
Logger.LogTrace(LoggerEventIds.ListenerDisposing, "Disposing the listener.");
Log.ListenerDisposing(Logger);

Stop();
DisposeInternal();
}
catch (Exception exception)
{
Logger.LogError(LoggerEventIds.ListenerDisposeError, exception, "Dispose");
Log.ListenerDisposeError(Logger, exception);
throw;
}
finally
Expand Down Expand Up @@ -305,7 +305,7 @@ internal bool ValidateRequest(NativeRequestContext requestMemory)
}
catch (Exception ex)
{
Logger.LogError(LoggerEventIds.RequestValidationFailed, ex, "Error validating request {RequestId}", requestMemory.RequestId);
Log.RequestValidationFailed(Logger, ex, requestMemory.RequestId);
return false;
}

Expand Down
5 changes: 3 additions & 2 deletions src/Servers/HttpSys/src/LoggerEventIds.cs
Original file line number Diff line number Diff line change
Expand Up @@ -25,12 +25,12 @@ internal static class LoggerEventIds
public static EventId RegisteringPrefix = new EventId(19, "RegisteringPrefix");
public static EventId UnregisteringPrefix = new EventId(20, "UnregisteringPrefix");
public static EventId CloseUrlGroupError = new EventId(21, "CloseUrlGroupError");
public static EventId ChannelBindingUnSupported = new EventId(22, "ChannelBindingUnSupported");
public static EventId ChannelBindingUnsupported = new EventId(22, "ChannelBindingUnSupported");
public static EventId ChannelBindingMissing = new EventId(23, "ChannelBindingMissing");
public static EventId RequestError = new EventId(24, "RequestError");
public static EventId ErrorInReadingCertificate = new EventId(25, "ErrorInReadingCertificate");
public static EventId ChannelBindingNeedsHttps = new EventId(26, "ChannelBindingNeedsHttps");
public static EventId ChannelBindingRetrived = new EventId(27, "ChannelBindingRetrived");
public static EventId ChannelBindingRetrieved = new EventId(27, "ChannelBindingRetrived");
public static EventId AbortError = new EventId(28, "AbortError");
public static EventId ErrorWhileRead = new EventId(29, "ErrorWhileRead");
public static EventId ErrorWhenReadBegun = new EventId(30, "ErrorWhenReadBegun");
Expand All @@ -51,5 +51,6 @@ internal static class LoggerEventIds
public static EventId ListenerStopError = new EventId(45, "ListenerStopError");
public static EventId ListenerDisposing = new EventId(46, "ListenerDisposing");
public static EventId RequestValidationFailed = new EventId(47, "RequestValidationFailed");
public static EventId CreateDisconnectTokenError = new EventId(48, "CreateDisconnectTokenError");
}
}
87 changes: 87 additions & 0 deletions src/Servers/HttpSys/src/MessagePump.Log.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,87 @@
// Copyright (c) .NET Foundation. All rights reserved.
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.

using System;
using System.Collections.Generic;
using Microsoft.AspNetCore.Hosting.Server.Features;
using Microsoft.AspNetCore.HttpSys.Internal;
using Microsoft.Extensions.Logging;

namespace Microsoft.AspNetCore.Server.HttpSys
{
internal partial class MessagePump
{
private static class Log
{
private static readonly Action<ILogger, Exception?> _acceptError =
LoggerMessage.Define(LogLevel.Error, LoggerEventIds.AcceptError, "Failed to accept a request.");

private static readonly Action<ILogger, Exception?> _acceptErrorStopping =
LoggerMessage.Define(LogLevel.Debug, LoggerEventIds.AcceptErrorStopping, "Failed to accept a request, the server is stopping.");

private static readonly Action<ILogger, Exception?> _bindingToDefault =
LoggerMessage.Define(LogLevel.Debug, LoggerEventIds.BindingToDefault, $"No listening endpoints were configured. Binding to {Constants.DefaultServerAddress} by default.");

private static readonly Action<ILogger, string, Exception?> _clearedAddresses =
LoggerMessage.Define<string>(LogLevel.Warning, LoggerEventIds.ClearedAddresses, $"Overriding address(es) '{{ServerAddresses)}}'. Binding to endpoints added to {nameof(HttpSysOptions.UrlPrefixes)} instead.");

private static readonly Action<ILogger, string, Exception?> _clearedPrefixes =
LoggerMessage.Define<string>(LogLevel.Warning, LoggerEventIds.ClearedPrefixes, $"Overriding endpoints added to {nameof(HttpSysOptions.UrlPrefixes)} since {nameof(IServerAddressesFeature.PreferHostingUrls)} is set to true. Binding to address(es) '{{ServerAddresses}}' instead. ");

private static readonly Action<ILogger, Exception?> _requestListenerProcessError =
LoggerMessage.Define(LogLevel.Error, LoggerEventIds.RequestListenerProcessError, "ProcessRequestAsync");

private static readonly Action<ILogger, int, Exception?> _stopCancelled =
LoggerMessage.Define<int>(LogLevel.Information, LoggerEventIds.StopCancelled, "Canceled, terminating {OutstandingRequests} request(s).");

private static readonly Action<ILogger, int, Exception?> _waitingForRequestsToDrain =
LoggerMessage.Define<int>(LogLevel.Information, LoggerEventIds.WaitingForRequestsToDrain, "Stopping, waiting for {OutstandingRequests} request(s) to drain.");

public static void AcceptError(ILogger logger, Exception exception)
{
_acceptError(logger, exception);
}

public static void AcceptErrorStopping(ILogger logger, Exception exception)
{
_acceptErrorStopping(logger, exception);
}

public static void BindingToDefault(ILogger logger)
{
_bindingToDefault(logger, null);
}

public static void ClearedAddresses(ILogger logger, ICollection<string> serverAddresses)
{
if (logger.IsEnabled(LogLevel.Warning))
{
_clearedAddresses(logger, string.Join(", ", serverAddresses), null);
}
}

public static void ClearedPrefixes(ILogger logger, ICollection<string> serverAddresses)
{
if (logger.IsEnabled(LogLevel.Warning))
{
_clearedPrefixes(logger, string.Join(", ", serverAddresses), null);
}
}

public static void RequestListenerProcessError(ILogger logger, Exception exception)
{
_requestListenerProcessError(logger, exception);
}

public static void StopCancelled(ILogger logger, int outstandingRequests)
{
_stopCancelled(logger, outstandingRequests, null);
}

public static void WaitingForRequestsToDrain(ILogger logger, int outstandingRequests)
{
_waitingForRequestsToDrain(logger, outstandingRequests, null);
}
}
}
}
21 changes: 9 additions & 12 deletions src/Servers/HttpSys/src/MessagePump.cs
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,7 @@

namespace Microsoft.AspNetCore.Server.HttpSys
{
internal class MessagePump : IServer
internal partial class MessagePump : IServer
{
private readonly ILogger _logger;
private readonly HttpSysOptions _options;
Expand Down Expand Up @@ -87,8 +87,7 @@ public Task StartAsync<TContext>(IHttpApplication<TContext> application, Cancell
{
if (_options.UrlPrefixes.Count > 0)
{
_logger.LogWarning(LoggerEventIds.ClearedPrefixes, $"Overriding endpoints added to {nameof(HttpSysOptions.UrlPrefixes)} since {nameof(IServerAddressesFeature.PreferHostingUrls)} is set to true." +
$" Binding to address(es) '{string.Join(", ", _serverAddresses.Addresses)}' instead. ");
Log.ClearedPrefixes(_logger, _serverAddresses.Addresses);

Listener.Options.UrlPrefixes.Clear();
}
Expand All @@ -99,20 +98,18 @@ public Task StartAsync<TContext>(IHttpApplication<TContext> application, Cancell
{
if (hostingUrlsPresent)
{
_logger.LogWarning(LoggerEventIds.ClearedAddresses, $"Overriding address(es) '{string.Join(", ", _serverAddresses.Addresses)}'. " +
$"Binding to endpoints added to {nameof(HttpSysOptions.UrlPrefixes)} instead.");
Log.ClearedAddresses(_logger, _serverAddresses.Addresses);

_serverAddresses.Addresses.Clear();
}

}
else if (hostingUrlsPresent)
{
UpdateUrlPrefixes(serverAddressCopy);
}
else if (Listener.RequestQueue.Created)
{
_logger.LogDebug(LoggerEventIds.BindingToDefault, $"No listening endpoints were configured. Binding to {Constants.DefaultServerAddress} by default.");
Log.BindingToDefault(_logger);

Listener.Options.UrlPrefixes.Add(Constants.DefaultServerAddress);
}
Expand Down Expand Up @@ -207,11 +204,11 @@ private async Task ProcessRequestsWorker()
Debug.Assert(Stopping);
if (Stopping)
{
_logger.LogDebug(LoggerEventIds.AcceptErrorStopping, exception, "Failed to accept a request, the server is stopping.");
Log.AcceptErrorStopping(_logger, exception);
}
else
{
_logger.LogError(LoggerEventIds.AcceptError, exception, "Failed to accept a request.");
Log.AcceptError(_logger, exception);
}
continue;
}
Expand All @@ -223,7 +220,7 @@ private async Task ProcessRequestsWorker()
{
// Request processing failed to be queued in threadpool
// Log the error message, release throttle and move on
_logger.LogError(LoggerEventIds.RequestListenerProcessError, ex, "ProcessRequestAsync");
Log.RequestListenerProcessError(_logger, ex);
}
}
Interlocked.Decrement(ref _acceptorCounts);
Expand All @@ -237,7 +234,7 @@ void RegisterCancelation()
{
if (Interlocked.Exchange(ref _shutdownSignalCompleted, 1) == 0)
{
_logger.LogInformation(LoggerEventIds.StopCancelled, "Canceled, terminating " + _outstandingRequests + " request(s).");
Log.StopCancelled(_logger, _outstandingRequests);
_shutdownSignal.TrySetResult();
}
});
Expand All @@ -255,7 +252,7 @@ void RegisterCancelation()
// Wait for active requests to drain
if (_outstandingRequests > 0)
{
_logger.LogInformation(LoggerEventIds.WaitingForRequestsToDrain, "Stopping, waiting for " + _outstandingRequests + " request(s) to drain.");
Log.WaitingForRequestsToDrain(_logger, _outstandingRequests);
RegisterCancelation();
}
else
Expand Down
Loading

0 comments on commit 020745c

Please sign in to comment.