| | | 1 | | // Copyright (c) Microsoft Corporation. All rights reserved. |
| | | 2 | | // Licensed under the MIT License. |
| | | 3 | | |
| | | 4 | | using System; |
| | | 5 | | using System.Collections.Generic; |
| | | 6 | | using System.Diagnostics; |
| | | 7 | | using System.Diagnostics.Tracing; |
| | | 8 | | using System.IO; |
| | | 9 | | using System.Text; |
| | | 10 | | using System.Threading; |
| | | 11 | | using System.Threading.Tasks; |
| | | 12 | | using Azure.Core.Diagnostics; |
| | | 13 | | |
| | | 14 | | namespace Azure.Core.Pipeline |
| | | 15 | | { |
| | | 16 | | internal class LoggingPolicy : HttpPipelinePolicy |
| | | 17 | | { |
| | 132 | 18 | | public LoggingPolicy(bool logContent, int maxLength, string[] allowedHeaderNames, string[] allowedQueryParameter |
| | | 19 | | { |
| | 132 | 20 | | _sanitizer = new HttpMessageSanitizer(allowedQueryParameters, allowedHeaderNames); |
| | 132 | 21 | | _logContent = logContent; |
| | 132 | 22 | | _maxLength = maxLength; |
| | 132 | 23 | | _assemblyName = assemblyName; |
| | 132 | 24 | | } |
| | | 25 | | |
| | | 26 | | private const double RequestTooLongTime = 3.0; // sec |
| | | 27 | | |
| | 2 | 28 | | private static readonly AzureCoreEventSource s_eventSource = AzureCoreEventSource.Singleton; |
| | | 29 | | |
| | | 30 | | private readonly bool _logContent; |
| | | 31 | | private readonly int _maxLength; |
| | | 32 | | private HttpMessageSanitizer _sanitizer; |
| | | 33 | | private readonly string? _assemblyName; |
| | | 34 | | |
| | | 35 | | public override async ValueTask ProcessAsync(HttpMessage message, ReadOnlyMemory<HttpPipelinePolicy> pipeline) |
| | | 36 | | { |
| | 1074 | 37 | | await ProcessAsync(message, pipeline, true).ConfigureAwait(false); |
| | 1064 | 38 | | } |
| | | 39 | | |
| | | 40 | | private async ValueTask ProcessAsync(HttpMessage message, ReadOnlyMemory<HttpPipelinePolicy> pipeline, bool asyn |
| | | 41 | | { |
| | 2130 | 42 | | if (!s_eventSource.IsEnabled()) |
| | | 43 | | { |
| | 0 | 44 | | if (async) |
| | | 45 | | { |
| | 0 | 46 | | await ProcessNextAsync(message, pipeline).ConfigureAwait(false); |
| | | 47 | | } |
| | | 48 | | else |
| | | 49 | | { |
| | 0 | 50 | | ProcessNext(message, pipeline); |
| | | 51 | | } |
| | 0 | 52 | | return; |
| | | 53 | | } |
| | | 54 | | |
| | 2130 | 55 | | Request request = message.Request; |
| | | 56 | | |
| | 2130 | 57 | | s_eventSource.Request(request.ClientRequestId, request.Method.ToString(), FormatUri(request.Uri), FormatHead |
| | | 58 | | |
| | 2130 | 59 | | Encoding? requestTextEncoding = null; |
| | | 60 | | |
| | 2130 | 61 | | if (request.TryGetHeader(HttpHeader.Names.ContentType, out var contentType)) |
| | | 62 | | { |
| | 16 | 63 | | ContentTypeUtilities.TryGetTextEncoding(contentType, out requestTextEncoding); |
| | | 64 | | } |
| | | 65 | | |
| | 2130 | 66 | | var logWrapper = new ContentEventSourceWrapper(s_eventSource, _logContent, _maxLength, message.CancellationT |
| | | 67 | | |
| | 2130 | 68 | | await logWrapper.LogAsync(request.ClientRequestId, request.Content, requestTextEncoding, async).ConfigureAwa |
| | | 69 | | |
| | 2130 | 70 | | var before = Stopwatch.GetTimestamp(); |
| | | 71 | | |
| | | 72 | | try |
| | | 73 | | { |
| | 2130 | 74 | | if (async) |
| | | 75 | | { |
| | 1074 | 76 | | await ProcessNextAsync(message, pipeline).ConfigureAwait(false); |
| | | 77 | | } |
| | | 78 | | else |
| | | 79 | | { |
| | 1056 | 80 | | ProcessNext(message, pipeline); |
| | | 81 | | } |
| | 2110 | 82 | | } |
| | 20 | 83 | | catch (Exception ex) |
| | | 84 | | { |
| | 20 | 85 | | s_eventSource.ExceptionResponse(request.ClientRequestId, ex.ToString()); |
| | 20 | 86 | | throw; |
| | | 87 | | } |
| | | 88 | | |
| | 2110 | 89 | | var after = Stopwatch.GetTimestamp(); |
| | | 90 | | |
| | 2110 | 91 | | bool isError = message.ResponseClassifier.IsErrorResponse(message); |
| | | 92 | | |
| | 2110 | 93 | | Response response = message.Response; |
| | 2110 | 94 | | ContentTypeUtilities.TryGetTextEncoding(response.Headers.ContentType, out Encoding? responseTextEncoding); |
| | | 95 | | |
| | 2110 | 96 | | bool wrapResponseContent = response.ContentStream != null && |
| | 2110 | 97 | | response.ContentStream?.CanSeek == false && |
| | 2110 | 98 | | logWrapper.IsEnabled(isError); |
| | | 99 | | |
| | 2110 | 100 | | double elapsed = (after - before) / (double)Stopwatch.Frequency; |
| | | 101 | | |
| | 2110 | 102 | | if (isError) |
| | | 103 | | { |
| | 438 | 104 | | s_eventSource.ErrorResponse(response.ClientRequestId, response.Status, response.ReasonPhrase, FormatHead |
| | | 105 | | } |
| | | 106 | | else |
| | | 107 | | { |
| | 1672 | 108 | | s_eventSource.Response(response.ClientRequestId, response.Status, response.ReasonPhrase, FormatHeaders(r |
| | | 109 | | } |
| | | 110 | | |
| | 2110 | 111 | | if (wrapResponseContent) |
| | | 112 | | { |
| | 20 | 113 | | response.ContentStream = new LoggingStream(response.ClientRequestId, logWrapper, _maxLength, response.Co |
| | | 114 | | } |
| | | 115 | | else |
| | | 116 | | { |
| | 2090 | 117 | | await logWrapper.LogAsync(response.ClientRequestId, isError, response.ContentStream, responseTextEncodin |
| | | 118 | | } |
| | | 119 | | |
| | 2110 | 120 | | if (elapsed > RequestTooLongTime) |
| | | 121 | | { |
| | 0 | 122 | | s_eventSource.ResponseDelay(response.ClientRequestId, elapsed); |
| | | 123 | | } |
| | 2110 | 124 | | } |
| | | 125 | | |
| | | 126 | | private string FormatUri(RequestUriBuilder requestUri) |
| | | 127 | | { |
| | 2130 | 128 | | return _sanitizer.SanitizeUrl(requestUri.ToString()); |
| | | 129 | | } |
| | | 130 | | |
| | | 131 | | public override void Process(HttpMessage message, ReadOnlyMemory<HttpPipelinePolicy> pipeline) |
| | | 132 | | { |
| | 1056 | 133 | | ProcessAsync(message, pipeline, false).EnsureCompleted(); |
| | 1046 | 134 | | } |
| | | 135 | | |
| | | 136 | | private string FormatHeaders(IEnumerable<HttpHeader> headers) |
| | | 137 | | { |
| | 4240 | 138 | | var stringBuilder = new StringBuilder(); |
| | 33212 | 139 | | foreach (HttpHeader header in headers) |
| | | 140 | | { |
| | 12366 | 141 | | stringBuilder.Append(header.Name); |
| | 12366 | 142 | | stringBuilder.Append(':'); |
| | 12366 | 143 | | string newValue = _sanitizer.SanitizeHeader(header.Name, header.Value); |
| | 12366 | 144 | | stringBuilder.AppendLine(newValue); |
| | | 145 | | } |
| | 4240 | 146 | | return stringBuilder.ToString(); |
| | | 147 | | } |
| | | 148 | | |
| | | 149 | | private class LoggingStream : ReadOnlyStream |
| | | 150 | | { |
| | | 151 | | private readonly string _requestId; |
| | | 152 | | |
| | | 153 | | private readonly ContentEventSourceWrapper _eventSourceWrapper; |
| | | 154 | | |
| | | 155 | | private int _maxLoggedBytes; |
| | | 156 | | |
| | | 157 | | private readonly Stream _originalStream; |
| | | 158 | | |
| | | 159 | | private readonly bool _error; |
| | | 160 | | |
| | | 161 | | private readonly Encoding? _textEncoding; |
| | | 162 | | |
| | | 163 | | private int _blockNumber; |
| | | 164 | | |
| | 20 | 165 | | public LoggingStream(string requestId, ContentEventSourceWrapper eventSourceWrapper, int maxLoggedBytes, Str |
| | | 166 | | { |
| | | 167 | | // Should only wrap non-seekable streams |
| | | 168 | | Debug.Assert(!originalStream.CanSeek); |
| | 20 | 169 | | _requestId = requestId; |
| | 20 | 170 | | _eventSourceWrapper = eventSourceWrapper; |
| | 20 | 171 | | _maxLoggedBytes = maxLoggedBytes; |
| | 20 | 172 | | _originalStream = originalStream; |
| | 20 | 173 | | _error = error; |
| | 20 | 174 | | _textEncoding = textEncoding; |
| | 20 | 175 | | } |
| | | 176 | | |
| | | 177 | | public override long Seek(long offset, SeekOrigin origin) |
| | | 178 | | { |
| | 0 | 179 | | return _originalStream.Seek(offset, origin); |
| | | 180 | | } |
| | | 181 | | |
| | | 182 | | public override int Read(byte[] buffer, int offset, int count) |
| | | 183 | | { |
| | 30 | 184 | | var result = _originalStream.Read(buffer, offset, count); |
| | | 185 | | |
| | 30 | 186 | | var countToLog = result; |
| | 30 | 187 | | DecrementLength(ref countToLog); |
| | 30 | 188 | | LogBuffer(buffer, offset, countToLog); |
| | | 189 | | |
| | 30 | 190 | | return result; |
| | | 191 | | } |
| | | 192 | | |
| | | 193 | | private void LogBuffer(byte[] buffer, int offset, int count) |
| | | 194 | | { |
| | 60 | 195 | | if (count == 0) |
| | | 196 | | { |
| | 24 | 197 | | return; |
| | | 198 | | } |
| | | 199 | | |
| | 36 | 200 | | _eventSourceWrapper.Log(_requestId, _error, buffer, offset, count, _textEncoding, _blockNumber); |
| | | 201 | | |
| | 36 | 202 | | _blockNumber++; |
| | 36 | 203 | | } |
| | | 204 | | |
| | | 205 | | public override async Task<int> ReadAsync(byte[] buffer, int offset, int count, CancellationToken cancellati |
| | | 206 | | { |
| | 30 | 207 | | var result = await _originalStream.ReadAsync(buffer, offset, count, cancellationToken).ConfigureAwait(fa |
| | | 208 | | |
| | 30 | 209 | | var countToLog = result; |
| | 30 | 210 | | DecrementLength(ref countToLog); |
| | 30 | 211 | | LogBuffer(buffer, offset, countToLog); |
| | | 212 | | |
| | 30 | 213 | | return result; |
| | 30 | 214 | | } |
| | | 215 | | |
| | 0 | 216 | | public override bool CanRead => _originalStream.CanRead; |
| | 0 | 217 | | public override bool CanSeek => _originalStream.CanSeek; |
| | 0 | 218 | | public override long Length => _originalStream.Length; |
| | | 219 | | public override long Position |
| | | 220 | | { |
| | 0 | 221 | | get => _originalStream.Position; |
| | 0 | 222 | | set => _originalStream.Position = value; |
| | | 223 | | } |
| | | 224 | | |
| | | 225 | | public override void Close() |
| | | 226 | | { |
| | 0 | 227 | | _originalStream.Close(); |
| | 0 | 228 | | } |
| | | 229 | | |
| | | 230 | | protected override void Dispose(bool disposing) |
| | | 231 | | { |
| | 0 | 232 | | base.Dispose(disposing); |
| | | 233 | | |
| | 0 | 234 | | _originalStream.Dispose(); |
| | 0 | 235 | | } |
| | | 236 | | |
| | | 237 | | private void DecrementLength(ref int count) |
| | | 238 | | { |
| | 60 | 239 | | var left = Math.Min(count, _maxLoggedBytes); |
| | 60 | 240 | | count = left; |
| | 60 | 241 | | _maxLoggedBytes -= count; |
| | 60 | 242 | | } |
| | | 243 | | } |
| | | 244 | | |
| | | 245 | | private readonly struct ContentEventSourceWrapper |
| | | 246 | | { |
| | | 247 | | private const int CopyBufferSize = 8 * 1024; |
| | | 248 | | private readonly AzureCoreEventSource? _eventSource; |
| | | 249 | | |
| | | 250 | | private readonly int _maxLength; |
| | | 251 | | |
| | | 252 | | private readonly CancellationToken _cancellationToken; |
| | | 253 | | |
| | | 254 | | public ContentEventSourceWrapper(AzureCoreEventSource eventSource, bool logContent, int maxLength, Cancellat |
| | | 255 | | { |
| | 2130 | 256 | | _eventSource = logContent ? eventSource : null; |
| | 2130 | 257 | | _maxLength = maxLength; |
| | 2130 | 258 | | _cancellationToken = cancellationToken; |
| | 2130 | 259 | | } |
| | | 260 | | |
| | | 261 | | public async ValueTask LogAsync(string requestId, bool isError, Stream? stream, Encoding? textEncoding, bool |
| | | 262 | | { |
| | 2090 | 263 | | EventType eventType = ResponseOrError(isError); |
| | | 264 | | |
| | 2090 | 265 | | if (stream == null || !IsEnabled(eventType)) |
| | | 266 | | { |
| | 2070 | 267 | | return; |
| | | 268 | | } |
| | | 269 | | |
| | 20 | 270 | | var bytes = await FormatAsync(stream, async).ConfigureAwait(false).EnsureCompleted(async); |
| | 20 | 271 | | Log(requestId, eventType, bytes, textEncoding); |
| | | 272 | | |
| | 2090 | 273 | | } |
| | | 274 | | |
| | | 275 | | public async ValueTask LogAsync(string requestId, RequestContent? content, Encoding? textEncoding, bool asyn |
| | | 276 | | { |
| | 2130 | 277 | | EventType eventType = EventType.Request; |
| | | 278 | | |
| | 2130 | 279 | | if (content == null || !IsEnabled(eventType)) |
| | | 280 | | { |
| | 2114 | 281 | | return; |
| | | 282 | | } |
| | | 283 | | |
| | 16 | 284 | | var bytes = await FormatAsync(content, async).ConfigureAwait(false).EnsureCompleted(async); |
| | | 285 | | |
| | 16 | 286 | | Log(requestId, eventType, bytes, textEncoding); |
| | 2130 | 287 | | } |
| | | 288 | | |
| | | 289 | | public void Log(string requestId, bool isError, byte[] buffer, int offset, int length, Encoding? textEncodin |
| | | 290 | | { |
| | 36 | 291 | | EventType eventType = ResponseOrError(isError); |
| | | 292 | | |
| | 36 | 293 | | if (buffer == null || !IsEnabled(eventType)) |
| | | 294 | | { |
| | 0 | 295 | | return; |
| | | 296 | | } |
| | | 297 | | |
| | 36 | 298 | | var logLength = Math.Min(length, _maxLength); |
| | | 299 | | |
| | | 300 | | byte[] bytes; |
| | 36 | 301 | | if (length == logLength && offset == 0) |
| | | 302 | | { |
| | 0 | 303 | | bytes = buffer; |
| | | 304 | | } |
| | | 305 | | else |
| | | 306 | | { |
| | 36 | 307 | | bytes = new byte[logLength]; |
| | 36 | 308 | | Array.Copy(buffer, offset, bytes, 0, logLength); |
| | | 309 | | } |
| | | 310 | | |
| | 36 | 311 | | Log(requestId, eventType, bytes, textEncoding, block); |
| | 36 | 312 | | } |
| | | 313 | | |
| | | 314 | | public bool IsEnabled(bool isError) |
| | | 315 | | { |
| | 1632 | 316 | | return IsEnabled(ResponseOrError(isError)); |
| | | 317 | | } |
| | | 318 | | |
| | | 319 | | private bool IsEnabled(EventType errorResponse) |
| | | 320 | | { |
| | 3764 | 321 | | return _eventSource != null && |
| | 3764 | 322 | | (_eventSource.IsEnabled(EventLevel.Informational, EventKeywords.All) || |
| | 3764 | 323 | | (errorResponse == EventType.ErrorResponse && _eventSource.IsEnabled(EventLevel.Warning, EventKeyw |
| | | 324 | | } |
| | | 325 | | |
| | | 326 | | private async ValueTask<byte[]> FormatAsync(RequestContent requestContent, bool async) |
| | | 327 | | { |
| | 16 | 328 | | using var memoryStream = new MaxLengthStream(_maxLength); |
| | | 329 | | |
| | 16 | 330 | | if (async) |
| | | 331 | | { |
| | 8 | 332 | | await requestContent.WriteToAsync(memoryStream, _cancellationToken).ConfigureAwait(false); |
| | | 333 | | } |
| | | 334 | | else |
| | | 335 | | { |
| | 8 | 336 | | requestContent.WriteTo(memoryStream, _cancellationToken); |
| | | 337 | | } |
| | | 338 | | |
| | 16 | 339 | | return memoryStream.ToArray(); |
| | 16 | 340 | | } |
| | | 341 | | |
| | | 342 | | private async ValueTask<byte[]> FormatAsync(Stream content, bool async) |
| | | 343 | | { |
| | 20 | 344 | | using var memoryStream = new MaxLengthStream(_maxLength); |
| | | 345 | | |
| | 20 | 346 | | if (async) |
| | | 347 | | { |
| | 10 | 348 | | await content.CopyToAsync(memoryStream, CopyBufferSize, _cancellationToken).ConfigureAwait(false); |
| | | 349 | | } |
| | | 350 | | else |
| | | 351 | | { |
| | 10 | 352 | | content.CopyTo(memoryStream); |
| | | 353 | | } |
| | | 354 | | |
| | 20 | 355 | | content.Seek(0, SeekOrigin.Begin); |
| | | 356 | | |
| | 20 | 357 | | return memoryStream.ToArray(); |
| | 20 | 358 | | } |
| | | 359 | | |
| | | 360 | | private void Log(string requestId, EventType eventType, byte[] bytes, Encoding? textEncoding, int? block = n |
| | | 361 | | { |
| | 72 | 362 | | string? stringValue = textEncoding?.GetString(bytes); |
| | | 363 | | |
| | | 364 | | // We checked IsEnabled before we got here |
| | | 365 | | Debug.Assert(_eventSource != null); |
| | 72 | 366 | | AzureCoreEventSource azureCoreEventSource = _eventSource!; |
| | | 367 | | |
| | 72 | 368 | | switch (eventType) |
| | | 369 | | { |
| | 16 | 370 | | case EventType.Request when stringValue != null: |
| | 8 | 371 | | azureCoreEventSource.RequestContentText(requestId, stringValue); |
| | 8 | 372 | | break; |
| | | 373 | | case EventType.Request: |
| | 8 | 374 | | azureCoreEventSource.RequestContent(requestId, bytes); |
| | 8 | 375 | | break; |
| | | 376 | | |
| | | 377 | | // Response |
| | 32 | 378 | | case EventType.Response when block != null && stringValue != null: |
| | 12 | 379 | | azureCoreEventSource.ResponseContentTextBlock(requestId, block.Value, stringValue); |
| | 12 | 380 | | break; |
| | 20 | 381 | | case EventType.Response when block != null: |
| | 8 | 382 | | azureCoreEventSource.ResponseContentBlock(requestId, block.Value, bytes); |
| | 8 | 383 | | break; |
| | 12 | 384 | | case EventType.Response when stringValue != null: |
| | 8 | 385 | | azureCoreEventSource.ResponseContentText(requestId, stringValue); |
| | 8 | 386 | | break; |
| | | 387 | | case EventType.Response: |
| | 4 | 388 | | azureCoreEventSource.ResponseContent(requestId, bytes); |
| | 4 | 389 | | break; |
| | | 390 | | |
| | | 391 | | // ResponseError |
| | 24 | 392 | | case EventType.ErrorResponse when block != null && stringValue != null: |
| | 8 | 393 | | azureCoreEventSource.ErrorResponseContentTextBlock(requestId, block.Value, stringValue); |
| | 8 | 394 | | break; |
| | 16 | 395 | | case EventType.ErrorResponse when block != null: |
| | 8 | 396 | | azureCoreEventSource.ErrorResponseContentBlock(requestId, block.Value, bytes); |
| | 8 | 397 | | break; |
| | 8 | 398 | | case EventType.ErrorResponse when stringValue != null: |
| | 4 | 399 | | azureCoreEventSource.ErrorResponseContentText(requestId, stringValue); |
| | 4 | 400 | | break; |
| | | 401 | | case EventType.ErrorResponse: |
| | 4 | 402 | | azureCoreEventSource.ErrorResponseContent(requestId, bytes); |
| | | 403 | | break; |
| | | 404 | | } |
| | 4 | 405 | | } |
| | | 406 | | |
| | | 407 | | private static EventType ResponseOrError(bool isError) |
| | | 408 | | { |
| | 3758 | 409 | | return isError ? EventType.ErrorResponse : EventType.Response; |
| | | 410 | | } |
| | | 411 | | |
| | | 412 | | private enum EventType |
| | | 413 | | { |
| | | 414 | | Request, |
| | | 415 | | Response, |
| | | 416 | | ErrorResponse |
| | | 417 | | } |
| | | 418 | | |
| | | 419 | | private class MaxLengthStream : MemoryStream |
| | | 420 | | { |
| | | 421 | | private int _bytesLeft; |
| | | 422 | | |
| | 36 | 423 | | public MaxLengthStream(int maxLength) : base() |
| | | 424 | | { |
| | 36 | 425 | | _bytesLeft = maxLength; |
| | 36 | 426 | | } |
| | | 427 | | |
| | | 428 | | public override void Write(byte[] buffer, int offset, int count) |
| | | 429 | | { |
| | 36 | 430 | | DecrementLength(ref count); |
| | 36 | 431 | | if (count > 0) |
| | | 432 | | { |
| | 36 | 433 | | base.Write(buffer, offset, count); |
| | | 434 | | } |
| | 36 | 435 | | } |
| | | 436 | | |
| | | 437 | | public override Task WriteAsync(byte[] buffer, int offset, int count, CancellationToken cancellationToke |
| | | 438 | | { |
| | 8 | 439 | | return count > 0 ? base.WriteAsync(buffer, offset, count, cancellationToken) : Task.CompletedTask; |
| | | 440 | | } |
| | | 441 | | |
| | | 442 | | private void DecrementLength(ref int count) |
| | | 443 | | { |
| | 36 | 444 | | var left = Math.Min(count, _bytesLeft); |
| | 36 | 445 | | count = left; |
| | | 446 | | |
| | 36 | 447 | | _bytesLeft -= count; |
| | 36 | 448 | | } |
| | | 449 | | } |
| | | 450 | | } |
| | | 451 | | } |
| | | 452 | | } |