Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Use LoggerMessage.Define in HttpSys #31333

Merged
merged 4 commits into from
Mar 28, 2021
Merged

Use LoggerMessage.Define in HttpSys #31333

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
b239111
Use LoggerMessage.Define in HttpSys
martincostello Mar 28, 2021
36de4d7
Remove log partials with one message
martincostello Mar 28, 2021
cded083
Split events that shared an event ID
martincostello Mar 28, 2021
b13dd4d
Restore nested Log classes
martincostello Mar 28, 2021
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
78 changes: 78 additions & 0 deletions src/Servers/HttpSys/src/HttpSysListener.Log.cs
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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
View file
Open in desktop
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