From 7aca4fb4e6c65820bbee8ffb887ba3689d3970c1 Mon Sep 17 00:00:00 2001 From: Madalyn Redding Date: Tue, 11 Jun 2024 17:47:02 -0400 Subject: [PATCH 1/2] update --- eng/Packages.Data.props | 3 +- .../src/Internal/ClientModelEventSource.cs | 70 +---------- .../src/Internal/ClientModelLogMessages.cs | 78 ++++++++++++ .../src/Options/LoggingOptions.cs | 16 +++ .../src/Pipeline/ClientLoggingPolicy.cs | 117 +++++++++++++----- .../src/System.ClientModel.csproj | 1 + 6 files changed, 187 insertions(+), 98 deletions(-) create mode 100644 sdk/core/System.ClientModel/src/Internal/ClientModelLogMessages.cs diff --git a/eng/Packages.Data.props b/eng/Packages.Data.props index ad61b5db63a8d..631ab1feb6a8c 100644 --- a/eng/Packages.Data.props +++ b/eng/Packages.Data.props @@ -102,8 +102,9 @@ - + + diff --git a/sdk/core/System.ClientModel/src/Internal/ClientModelEventSource.cs b/sdk/core/System.ClientModel/src/Internal/ClientModelEventSource.cs index 2c1f024861bc5..a45b650afbe04 100644 --- a/sdk/core/System.ClientModel/src/Internal/ClientModelEventSource.cs +++ b/sdk/core/System.ClientModel/src/Internal/ClientModelEventSource.cs @@ -28,30 +28,11 @@ internal sealed class ClientModelEventSource : EventSource private const int ErrorResponseContentTextBlockEvent = 16; private const int RequestContentTextEvent = 17; private const int ExceptionResponseEvent = 18; - private const int BackgroundRefreshFailedEvent = 19; - private const int RequestRedirectEvent = 20; - private const int RequestRedirectBlockedEvent = 21; - private const int RequestRedirectCountExceededEvent = 22; - private const int PipelineTransportOptionsNotAppliedEvent = 23; + private const int PipelineTransportOptionsNotAppliedEvent = 23; // TODO - private ClientModelEventSource(string eventSourceName, string[]? traits) : base(eventSourceName, EventSourceSettings.Default, traits) { } + private ClientModelEventSource(string eventSourceName) : base(eventSourceName, EventSourceSettings.Default) { } - public static ClientModelEventSource Create(string eventSourceName, string[]? traits) => new(eventSourceName, traits); - - [Event(BackgroundRefreshFailedEvent, Level = EventLevel.Informational, Message = "Background token refresh [{0}] failed with exception {1}")] - public void BackgroundRefreshFailed(string? requestId, string exception) - { - WriteEvent(BackgroundRefreshFailedEvent, requestId, exception); - } - - [NonEvent] - public void Request(PipelineRequest request, string? requestId, string? assemblyName, PipelineMessageSanitizer sanitizer) - { - if (IsEnabled(EventLevel.Informational, EventKeywords.None)) - { - Request(requestId, request.Method.ToString(), sanitizer.SanitizeUrl(request.Uri!.AbsoluteUri), FormatHeaders(request.Headers, sanitizer), assemblyName); - } - } + public static ClientModelEventSource Create(string eventSourceName) => new(eventSourceName); [Event(RequestEvent, Level = EventLevel.Informational, Message = "Request [{0}] {1} {2}\r\n{3}client assembly: {4}")] [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026", Justification = "WriteEvent is used with primitive types.")] @@ -60,22 +41,6 @@ public void Request(string? requestId, string method, string uri, string headers WriteEvent(RequestEvent, requestId, method, uri, headers, clientAssembly); } - [NonEvent] - public void RequestContent(string? requestId, byte[] content, Encoding? textEncoding) - { - if (IsEnabled(EventLevel.Verbose, EventKeywords.None)) - { - if (textEncoding is not null) - { - RequestContentText(requestId, textEncoding.GetString(content)); - } - else - { - RequestContent(requestId, content); - } - } - } - [Event(RequestContentEvent, Level = EventLevel.Verbose, Message = "Request [{0}] content: {1}")] [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026", Justification = "WriteEvent is used with an array with primitive type elements.")] public void RequestContent(string? requestId, byte[] content) @@ -259,34 +224,6 @@ public void ExceptionResponse(string? requestId, string exception) WriteEvent(ExceptionResponseEvent, requestId, exception); } - [NonEvent] - public void RequestRedirect(PipelineRequest request, string requestId, Uri redirectUri, PipelineResponse response) - { - if (IsEnabled(EventLevel.Verbose, EventKeywords.None)) - { - RequestRedirect(requestId, request.Uri!.AbsoluteUri, redirectUri.AbsoluteUri, response.Status); - } - } - - [Event(RequestRedirectEvent, Level = EventLevel.Verbose, Message = "Request [{0}] Redirecting from {1} to {2} in response to status code {3}")] - [UnconditionalSuppressMessage("ReflectionAnalysis", "IL2026", Justification = "WriteEvent is used with primitive types.")] - public void RequestRedirect(string? requestId, string from, string to, int status) - { - WriteEvent(RequestRedirectEvent, requestId, from, to, status); - } - - [Event(RequestRedirectBlockedEvent, Level = EventLevel.Warning, Message = "Request [{0}] Insecure HTTPS to HTTP redirect from {1} to {2} was blocked.")] - public void RequestRedirectBlocked(string? requestId, string from, string to) - { - WriteEvent(RequestRedirectBlockedEvent, requestId, from, to); - } - - [Event(RequestRedirectCountExceededEvent, Level = EventLevel.Warning, Message = "Request [{0}] Exceeded max number of redirects. Redirect from {1} to {2} blocked.")] - public void RequestRedirectCountExceeded(string? requestId, string from, string to) - { - WriteEvent(RequestRedirectCountExceededEvent, requestId, from, to); - } - [NonEvent] public void PipelineTransportOptionsNotApplied(Type optionsType) { @@ -302,7 +239,6 @@ public void PipelineTransportOptionsNotApplied(string optionsType) WriteEvent(PipelineTransportOptionsNotAppliedEvent, optionsType); } - [NonEvent] private static string FormatHeaders(IEnumerable> headers, PipelineMessageSanitizer sanitizer) { var stringBuilder = new StringBuilder(); diff --git a/sdk/core/System.ClientModel/src/Internal/ClientModelLogMessages.cs b/sdk/core/System.ClientModel/src/Internal/ClientModelLogMessages.cs new file mode 100644 index 0000000000000..eba4bb2c95ffc --- /dev/null +++ b/sdk/core/System.ClientModel/src/Internal/ClientModelLogMessages.cs @@ -0,0 +1,78 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. +// Licensed under the MIT License. + +using System; +using System.Collections.Generic; +using System.Text; +using Microsoft.Extensions.Logging; + +namespace System.ClientModel.Internal; + +internal static partial class ClientModelLogMessages +{ + private const int RequestEvent = 1; + private const int RequestContentEvent = 2; + private const int ResponseEvent = 5; + private const int ResponseContentEvent = 6; + private const int ResponseDelayEvent = 7; + private const int ErrorResponseEvent = 8; + private const int ErrorResponseContentEvent = 9; + private const int RequestRetryingEvent = 10; + private const int ResponseContentBlockEvent = 11; + private const int ErrorResponseContentBlockEvent = 12; + private const int ResponseContentTextEvent = 13; + private const int ErrorResponseContentTextEvent = 14; + private const int ResponseContentTextBlockEvent = 15; + private const int ErrorResponseContentTextBlockEvent = 16; + private const int RequestContentTextEvent = 17; + private const int ExceptionResponseEvent = 18; + private const int PipelineTransportOptionsNotAppliedEvent = 23; // TODO + + [LoggerMessage(RequestEvent, LogLevel.Information, "Request [{requestId}] {method} {uri}\r\n{headers}client assembly: {assemblyName}", EventName = "Request")] + public static partial void Request(ILogger logger, string requestId, string method, string uri, string headers, string? assemblyName); + + // TODO - these are verbose logs in EventSource, should they be trace logs here? + [LoggerMessage(RequestContentEvent, LogLevel.Information, "Request [{requestId}] content: {content}", EventName = "RequestContent")] + public static partial void RequestContent(ILogger logger, string requestId, byte[] content); + + // same as above + [LoggerMessage(RequestContentTextEvent, LogLevel.Information, "Request [{requestId}] content: {content}", EventName="RequestContentText")] + public static partial void RequestContentText(ILogger logger, string requestID, string content); + + [LoggerMessage(ResponseEvent, LogLevel.Information, "Response [{requestId}] {status} {reasonPhrase} ({seconds:00.0}s)\r\n{headers}", EventName = "Response")] + public static partial void Response(ILogger logger, string requestID, int status, string reasonPhrase, double seconds, string headers); + + // same + [LoggerMessage(ResponseContentEvent, LogLevel.Information, "Response [{requestId}] content: {content}", EventName = "ResponseContent")] + public static partial void ResponseContent(ILogger logger, string requestId, byte[] content); + + [LoggerMessage(ResponseContentTextEvent, LogLevel.Information, "Response [{requestId}] content: {content}", EventName = "ResponseContentText")] + public static partial void ResponseContentText(ILogger logger, string requestId, string content); + + [LoggerMessage(ResponseContentBlockEvent, LogLevel.Information, "Response [{requestId}] content block {blockNumber}: {content}", EventName = "ResponseContentBlock")] + public static partial void ResponseContentBlock(ILogger logger, string requestId, int blockNumber, byte[] content); + + [LoggerMessage(ResponseContentTextBlockEvent, LogLevel.Information, "Response [{requestId}] content block {blockNumber}: {content}", EventName = "ResponseContentTextBlock")] + public static partial void ResponseContentTextBlock(ILogger logger, string requestId, int blockNumber, string content); + + [LoggerMessage(ErrorResponseEvent, LogLevel.Warning, "Error response [{requestId}] {status} {reasonPhrase} ({seconds:00.0}s)\r\n{headers}", EventName = "ErrorResponse")] + public static partial void ErrorResponse(ILogger logger, string requestId, int status, string reasonPhrase, double seconds, string headers); + + [LoggerMessage(ErrorResponseContentEvent, LogLevel.Warning, "Error response [{requestId}] content: {content}", EventName = "ErrorResponseContent")] + public static partial void ErrorResponseContent(ILogger logger, string requestId, byte[] content); + + [LoggerMessage(ErrorResponseContentTextEvent, LogLevel.Warning, "Error response [{requestId}] content: {content}", EventName = "ErrorResponseContentText")] + public static partial void ErrorResponseContentText(ILogger logger, string requestId, string content); + + [LoggerMessage(ErrorResponseContentBlockEvent, LogLevel.Warning, "Error response [{requestId}] content block {blockNumber}: {content}", EventName = "ErrorResponseContentBlock")] + public static partial void ErrorResponseContentBlock(ILogger logger, string requestId, int blockNumber, byte[] content); + + [LoggerMessage(ErrorResponseContentTextBlockEvent, LogLevel.Warning, "Error response [{requestId}] content block {blockNumber}: {content}", EventName = "ErrorResponseContentTextBlock")] + public static partial void ErrorResponseContentTextBlock(ILogger logger, string requestId, int blockNumber, string content); + + [LoggerMessage(RequestRetryingEvent, LogLevel.Information, "Request [{requestId}] attempt number {retryCount} took {seconds:00.0}s", EventName = "RequestRetrying")] + public static partial void RequestRetrying(ILogger logger, string requestId, int retryCount, double seconds); + + [LoggerMessage(ExceptionResponseEvent, LogLevel.Information, "Request [{requestId}] exception {exception}", EventName = "ExceptionResponse")] + public static partial void ExceptionResponse(ILogger logger, string requestId, string exception); +} diff --git a/sdk/core/System.ClientModel/src/Options/LoggingOptions.cs b/sdk/core/System.ClientModel/src/Options/LoggingOptions.cs index 14017ff358019..85d054c64e41f 100644 --- a/sdk/core/System.ClientModel/src/Options/LoggingOptions.cs +++ b/sdk/core/System.ClientModel/src/Options/LoggingOptions.cs @@ -3,6 +3,7 @@ using System.Collections.Generic; using System.Collections.ObjectModel; +using Microsoft.Extensions.Logging; namespace System.ClientModel.Primitives; @@ -48,6 +49,7 @@ public class LoggingOptions private IList _allowedQueryParameters = new List(s_defaultAllowedQueryParameters); private string? _clientAssembly; private string? _requestIdHeaderName; + private ILoggerFactory? _loggerFactory; /// /// Get or sets value indicating whether HTTP pipeline logging is enabled. @@ -63,6 +65,20 @@ public bool IsLoggingEnabled } } + /// + /// TODO. + /// + public ILoggerFactory? LoggerFactory + { + get => _loggerFactory; + set + { + AssertNotFrozen(); + + _loggerFactory = value; + } + } + /// /// Gets or sets value indicating if request or response content should be logged. /// diff --git a/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs b/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs index 5e1c927c7b3b6..9b0e7017dd058 100644 --- a/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs +++ b/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs @@ -13,6 +13,7 @@ using System.Threading; using System.Threading.Tasks; using System.Linq; +using Microsoft.Extensions.Logging; namespace System.ClientModel.Primitives; @@ -22,9 +23,8 @@ namespace System.ClientModel.Primitives; public class ClientLoggingPolicy : PipelinePolicy { private const double RequestTooLongTime = 3.0; // sec - private const string DefaultEventSourceName = "System.ClientModel"; - private static readonly ConcurrentDictionary s_singletonEventSources = new(); + internal static readonly ClientModelEventSource EventSourceSingleton = ClientModelEventSource.Create("System.ClientModel"); private readonly bool _logContent; private readonly int _maxLength; @@ -32,14 +32,13 @@ public class ClientLoggingPolicy : PipelinePolicy private readonly string? _clientRequestIdHeaderName; private readonly bool _isLoggingEnabled; private readonly PipelineMessageSanitizer _sanitizer; + private ILogger? _logger; /// /// TODO. /// - /// - /// /// - protected ClientLoggingPolicy(string logName, string[]? logTraits = default, LoggingOptions? options = default) + public ClientLoggingPolicy(LoggingOptions? options = default) { LoggingOptions loggingOptions = options ?? new LoggingOptions(); _logContent = loggingOptions.IsLoggingContentEnabled; @@ -48,24 +47,8 @@ protected ClientLoggingPolicy(string logName, string[]? logTraits = default, Log _clientRequestIdHeaderName = loggingOptions.RequestIdHeaderName; _isLoggingEnabled = loggingOptions.IsLoggingEnabled; _sanitizer = new PipelineMessageSanitizer(loggingOptions.AllowedQueryParameters.ToArray(), loggingOptions.AllowedHeaderNames.ToArray()); - - string logNameToUse = logName ?? DefaultEventSourceName; - EventSourceSingleton = s_singletonEventSources.GetOrAdd(logNameToUse, _ => ClientModelEventSource.Create(logNameToUse, logTraits)); } - /// - /// TODO. - /// - /// - public ClientLoggingPolicy(LoggingOptions? options = default) : this(DefaultEventSourceName, null, options) - { - } - - /// - /// TODO - /// - internal ClientModelEventSource EventSourceSingleton { get; } - /// public override void Process(PipelineMessage message, IReadOnlyList pipeline, int currentIndex) => ProcessSyncOrAsync(message, pipeline, currentIndex, async: false).EnsureCompleted(); @@ -76,7 +59,10 @@ public override async ValueTask ProcessAsync(PipelineMessage message, IReadOnlyL private async ValueTask ProcessSyncOrAsync(PipelineMessage message, IReadOnlyList pipeline, int currentIndex, bool async) { - if (!_isLoggingEnabled || !EventSourceSingleton.IsEnabled()) + bool eventSourceIsEnabled = EventSourceSingleton.IsEnabled(); + bool loggerIsEnabled = _logger != null; + + if (!_isLoggingEnabled || !(eventSourceIsEnabled || loggerIsEnabled)) { if (async) { @@ -148,14 +134,36 @@ private async ValueTask ProcessSyncOrAsync(PipelineMessage message, IReadOnlyLis return clientRequestId; } - private void LogRequest(PipelineRequest request, string? requestId) + private void LogRequest(PipelineRequest request, string requestId) { - EventSourceSingleton.Request(request, requestId, _assemblyName, _sanitizer); + bool eventSourceIsEnabled = EventSourceSingleton.IsEnabled(EventLevel.Informational, EventKeywords.None); + bool loggerIsEnabled = _logger != null && _logger.IsEnabled(LogLevel.Information); + + if (!ShouldLog() // avoid sanitization cost + { + return; + } + + string uri = _sanitizer.SanitizeUrl(request.Uri!.AbsoluteUri); + string headers = FormatHeaders(request.Headers, _sanitizer); + + if (loggerIsEnabled) + { + ClientModelLogMessages.Request(_logger!, requestId, request.Method, uri, headers, _assemblyName); // _logger is checked above + } + if (eventSourceIsEnabled) + { + EventSourceSingleton.Request(requestId, request.Method, uri, FormatHeaders(request.Headers, _sanitizer), _assemblyName); + } } - private async Task LogRequestContent(PipelineRequest request, string? requestId, bool async, CancellationToken cancellationToken) + private async Task LogRequestContent(PipelineRequest request, string requestId, bool async, CancellationToken cancellationToken) { - if (!_logContent || request.Content == null || !EventSourceSingleton.IsEnabled(EventLevel.Informational, EventKeywords.All)) + bool eventSourceIsEnabled = EventSourceSingleton.IsEnabled(EventLevel.Verbose, EventKeywords.None); + bool loggerIsEnabled = _logger != null && _logger.IsEnabled(LogLevel.Information); + + // if content logging is turned off, there is no content, or both logger and event source are disabled + if (!_logContent || request.Content == null || !(eventSourceIsEnabled || loggerIsEnabled)) { return; // nothing to log } @@ -180,13 +188,44 @@ private async Task LogRequestContent(PipelineRequest request, string? requestId, ContentTypeUtilities.TryGetTextEncoding(contentType, out requestTextEncoding); } - // Log to event source - EventSourceSingleton.RequestContent(requestId, bytes, requestTextEncoding); + // Log text event + if (requestTextEncoding != null) + { + string content = requestTextEncoding.GetString(bytes); + if (eventSourceIsEnabled) + { + EventSourceSingleton.RequestContentText(requestId, content); + } + if (loggerIsEnabled) + { + ClientModelLogMessages.RequestContentText(_logger!, requestId, content); // _logger is checked above + } + } + else // Log bytes + { + if (eventSourceIsEnabled) + { + EventSourceSingleton.RequestContent(requestId, bytes); + } + if (loggerIsEnabled) + { + ClientModelLogMessages.RequestContent(_logger!, requestId, bytes); + } + } } - private void LogResponse(PipelineResponse response, string? responseId, double elapsed) + private void LogResponse(PipelineResponse response, string responseId, double elapsed) { - bool isError = response.IsError; + bool eventSourceIsEnabled = EventSourceSingleton.IsEnabled(); + bool loggerIsEnabled = _logger != null && _logger.IsEnabled(LogLevel.Information); + + if (!(eventSourceIsEnabled || loggerIsEnabled)) // avoid sanitization cost + { + return; + } + + + if (isError) { EventSourceSingleton.ErrorResponse(response, responseId, _sanitizer, elapsed); @@ -197,6 +236,11 @@ private void LogResponse(PipelineResponse response, string? responseId, double e } } + private void LogErrorResponse(PipelineResponse response, string responseId, double elapsed) + { + + } + private void LogResponseContent(PipelineResponse response, string? responseId, bool contentBuffered, bool async, CancellationToken cancellationToken) { var logErrorResponseContent = response.IsError && EventSourceSingleton.IsEnabled(EventLevel.Warning, EventKeywords.All); @@ -264,6 +308,19 @@ private void LogFormattedResponseContent(bool isError, string? clientId, byte[] return clientRequestId; } + private static string FormatHeaders(IEnumerable> headers, PipelineMessageSanitizer sanitizer) + { + var stringBuilder = new StringBuilder(); + foreach (var header in headers) + { + stringBuilder.Append(header.Key); + stringBuilder.Append(':'); + stringBuilder.Append(sanitizer.SanitizeHeader(header.Key, header.Value)); + stringBuilder.Append(Environment.NewLine); + } + return stringBuilder.ToString(); + } + #region MaxLengthStream private class MaxLengthStream : MemoryStream { diff --git a/sdk/core/System.ClientModel/src/System.ClientModel.csproj b/sdk/core/System.ClientModel/src/System.ClientModel.csproj index 8de4e104ab615..2ff26df080258 100644 --- a/sdk/core/System.ClientModel/src/System.ClientModel.csproj +++ b/sdk/core/System.ClientModel/src/System.ClientModel.csproj @@ -12,6 +12,7 @@ + From 12d029733d6a654ff61cdedc4ef8236b91786837 Mon Sep 17 00:00:00 2001 From: Madalyn Redding Date: Thu, 13 Jun 2024 12:38:36 -0400 Subject: [PATCH 2/2] WIP --- sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs b/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs index 9b0e7017dd058..40cf58c816192 100644 --- a/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs +++ b/sdk/core/System.ClientModel/src/Pipeline/ClientLoggingPolicy.cs @@ -139,7 +139,7 @@ private void LogRequest(PipelineRequest request, string requestId) bool eventSourceIsEnabled = EventSourceSingleton.IsEnabled(EventLevel.Informational, EventKeywords.None); bool loggerIsEnabled = _logger != null && _logger.IsEnabled(LogLevel.Information); - if (!ShouldLog() // avoid sanitization cost + if (!(eventSourceIsEnabled || loggerIsEnabled)) // avoid sanitization cost { return; }