| | 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 | | } |