Skip to content

Commit

Permalink
[Core] Enhance Logging Sample (#26359)
Browse files Browse the repository at this point in the history
* [Core] Enhance Logging Sample

The focus of these changes is to add additional scenarios to the logging
samples that reflect common guidance used for troubleshooting with customer
applications.  In order to accommodate the new content and provide a logical
flow between scenarios, some adjustments to the ordering of existing samples
were performed.

* Added a note advising a more robust file logging implementation for long-term production use.
  • Loading branch information
jsquire committed Jan 14, 2022
1 parent a95328a commit 5df0fb2
Show file tree
Hide file tree
Showing 2 changed files with 166 additions and 24 deletions.
108 changes: 89 additions & 19 deletions sdk/core/Azure.Core/samples/Diagnostics.md
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@

## Logging

Azure SDKs produce various log messages that include information about:
The Azure SDK libraries produce various log messages that include information about:
1. Requests and responses
2. Authentication attempts
3. Retries
Expand All @@ -20,6 +20,23 @@ using AzureEventSourceListener listener = AzureEventSourceListener.CreateConsole

In order for the `AzureEventSourceListener` to collect logs, it must be in scope and active while the client library is in use. If the listener is disposed or otherwise out of scope, logs cannot be collected. Generally, we recommend creating the listener as a top-level member of the class where the Event Hubs client being inspected is used.

### Capture logs to trace

Logging can also be enabled for `Trace` in the same manner as console logging.

```C# Snippet:TraceLogging
// Setup a listener to monitor logged events.
using AzureEventSourceListener listener = AzureEventSourceListener.CreateTraceLogger();
```
### Changing log level

The `CreateConsoleLogger` and `CreateTraceLogger` methods have an optional parameter that specifies a minimum log level to display messages for.

```C# Snippet:LoggingLevel
using AzureEventSourceListener consoleListener = AzureEventSourceListener.CreateConsoleLogger(EventLevel.Warning);
using AzureEventSourceListener traceListener = AzureEventSourceListener.CreateTraceLogger(EventLevel.Informational);
```

### Enabling content logging

By default only URI and headers are logged. To enable content logging, set the `Diagnostics.IsLoggingContentEnabled` client option:
Expand All @@ -34,16 +51,6 @@ SecretClientOptions options = new SecretClientOptions()
};
```

**NOTE:** The content is logged at the `Verbose` level so you might need to change the listener settings for content logs to appear.

### Changing log level

The `CreateConsoleLogger` method has an optional parameter that specifies a minimum log level to display messages for.

```C# Snippet:ConsoleLoggingLevel
using AzureEventSourceListener listener = AzureEventSourceListener.CreateConsoleLogger(EventLevel.Warning);
```

### Logging redacted headers and query parameters

Some sensitive headers and query parameters are not logged by default and are displayed as "REDACTED", to include them in logs use the `Diagnostics.LoggedHeaderNames` and `Diagnostics.LoggedQueryParameters` client options.
Expand Down Expand Up @@ -72,23 +79,86 @@ SecretClientOptions options = new SecretClientOptions()
};
```

### ASP.NET Core applications

If your are using Azure SDK libraries in ASP.NET Core application consider using the `Microsoft.Extensions.Azure` package that provides integration with `Microsoft.Extensions.Logging` library. See [Microsoft.Extensions.Azure readme](https://github.com/Azure/azure-sdk-for-net/blob/main/sdk/extensions/Microsoft.Extensions.Azure/README.md) for more details.


### Custom logging callback

The `AzureEventSourceListener` class can also be used with a custom callback that allows log messages to be written to destination of your choice.

```C# Snippet:LoggingCallback
using AzureEventSourceListener listener = new AzureEventSourceListener(
(e, message) => Console.WriteLine("[{0:HH:mm:ss:fff}][{1}] {2}", DateTimeOffset.Now, e.Level, message),
(args, message) => Console.WriteLine("[{0:HH:mm:ss:fff}][{1}] {2}", DateTimeOffset.Now, args.Level, message),
level: EventLevel.Verbose);
```

When targeting .NET Standard 2.1, .NET Core 2.2, or newer, you might instead use `e.TimeStamp` to log the time the event was written instead of rendered, like above. It's in UTC format, so if you want to log the local time like in the example call `ToLocaleTime()` first.
For help diagnosing multi-threading issues, you might also log `e.OSThreadId` which is also available on those same targets.
When targeting .NET Standard 2.1, .NET Core 2.2, or newer, you might instead use `args.TimeStamp` to log the time the event was written instead of rendered, like above. It's in UTC format, so if you want to log the local time like in the example call `ToLocaleTime()` first.
For help diagnosing multi-threading issues, you might also log `args.OSThreadId` which is also available on those same targets.

More information about the `args` parameter for the callback can be found in the [EventWrittenEventArgs](https://docs.microsoft.com/dotnet/api/system.diagnostics.tracing.eventwritteneventargs) documentation.

### Applying filtering logic

The custom callback can be used with the listener to help filter log messages to reduce volume and noise when troubleshooting.

In the following example, `Verbose` messages for the `Azure-Identity` event source are captured and written to `Trace`. Log messages for the `Azure-Messaging-EventHubs` event source are filtered to capture only a specific set to aid in debugging publishing, which are then written to the console.

```C# Snippet:LoggingWithFilters
using AzureEventSourceListener listener = new AzureEventSourceListener((args, message) =>
{
if (args.EventSource.Name.StartsWith("Azure-Identity") && args.Level == EventLevel.Verbose)
{
Trace.WriteLine(message);
}
else if (args.EventSource.Name.StartsWith("Azure-Messaging-EventHubs"))
{
switch (args.EventId)
{
case 3: // Event Publish Start
case 4: // Event Publish Complete
case 5: // Event Publish Error
Console.WriteLine(message);
break;
}
}
}, EventLevel.LogAlways);
```

### Capture filtered logs to a file

For scenarios where capturing logs to `Trace` or console isn't ideal, log information can be streamed into a variety of targets, such as Azure Storage, databases, and files for durable persistence.

The following example demonstrates capturing error logs to a text file so that they can be analyzed later, while capturing non-error information to console. Its important to note that a simple approach is used for illustration. This form may be helpful for troubleshooting, but a more robust and performant approach is recommended for long-term production use.

```C# Snippet:FileLogging
using Stream stream = new FileStream(
"<< PATH TO FILE >>",
FileMode.OpenOrCreate,
FileAccess.Write,
FileShare.Read);

using StreamWriter streamWriter = new StreamWriter(stream)
{
AutoFlush = true
};

using AzureEventSourceListener listener = new AzureEventSourceListener((args, message) =>
{
if (args.EventSource.Name.StartsWith("Azure-Identity"))
{
switch (args.Level)
{
case EventLevel.Error:
streamWriter.Write(message);
break;
default:
Console.WriteLine(message);
break;
}
}
}, EventLevel.LogAlways);
```

### Logging in ASP.NET Core applications

If your are using Azure SDK libraries in ASP.NET Core application consider using the `Microsoft.Extensions.Azure` package that provides integration with `Microsoft.Extensions.Logging` library. See [Microsoft.Extensions.Azure readme](https://github.com/Azure/azure-sdk-for-net/blob/main/sdk/extensions/Microsoft.Extensions.Azure/README.md) for more details.

## ActivitySource support

Expand Down
82 changes: 77 additions & 5 deletions sdk/core/Azure.Core/tests/samples/LoggingSamples.cs
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@
using System;
using System.Diagnostics;
using System.Diagnostics.Tracing;
using System.Net.Http;
using System.IO;
using Azure.Core.Diagnostics;
using Azure.Core.Pipeline;
using Azure.Identity;
Expand All @@ -16,19 +16,29 @@ namespace Azure.Core.Samples
public class LoggingSamples
{
[Test]
public void Logging()
public void ConsoleLogging()
{
#region Snippet:ConsoleLogging
// Setup a listener to monitor logged events.
using AzureEventSourceListener listener = AzureEventSourceListener.CreateConsoleLogger();
#endregion
}

[Test]
public void TraceLogging()
{
#region Snippet:TraceLogging
// Setup a listener to monitor logged events.
using AzureEventSourceListener listener = AzureEventSourceListener.CreateTraceLogger();
#endregion
}

[Test]
public void LoggingLevel()
{
#region Snippet:ConsoleLoggingLevel
using AzureEventSourceListener listener = AzureEventSourceListener.CreateConsoleLogger(EventLevel.Warning);
#region Snippet:LoggingLevel
using AzureEventSourceListener consoleListener = AzureEventSourceListener.CreateConsoleLogger(EventLevel.Warning);
using AzureEventSourceListener traceListener = AzureEventSourceListener.CreateTraceLogger(EventLevel.Informational);
#endregion
}

Expand All @@ -37,7 +47,7 @@ public void LoggingCallback()
{
#region Snippet:LoggingCallback
using AzureEventSourceListener listener = new AzureEventSourceListener(
(e, message) => Console.WriteLine("[{0:HH:mm:ss:fff}][{1}] {2}", DateTimeOffset.Now, e.Level, message),
(args, message) => Console.WriteLine("[{0:HH:mm:ss:fff}][{1}] {2}", DateTimeOffset.Now, args.Level, message),
level: EventLevel.Verbose);
#endregion
}
Expand Down Expand Up @@ -86,6 +96,68 @@ public static void LoggingRedactedHeaderAll()
#endregion
}

[Test]
public static void LoggingWithFilters()
{
#region Snippet:LoggingWithFilters
using AzureEventSourceListener listener = new AzureEventSourceListener((args, message) =>
{
if (args.EventSource.Name.StartsWith("Azure-Identity") && args.Level == EventLevel.Verbose)
{
Trace.WriteLine(message);
}
else if (args.EventSource.Name.StartsWith("Azure-Messaging-EventHubs"))
{
switch (args.EventId)
{
case 3: // Event Publish Start
case 4: // Event Publish Complete
case 5: // Event Publish Error
Console.WriteLine(message);
break;
}
}
}, EventLevel.LogAlways);
#endregion
}

[Test]
public static void FileLogging()
{
#region Snippet:FileLogging
#if SNIPPET
using Stream stream = new FileStream(
"<< PATH TO FILE >>",
FileMode.OpenOrCreate,
FileAccess.Write,
FileShare.Read);
#else
using Stream stream = new MemoryStream();
#endif

using StreamWriter streamWriter = new StreamWriter(stream)
{
AutoFlush = true
};

using AzureEventSourceListener listener = new AzureEventSourceListener((args, message) =>
{
if (args.EventSource.Name.StartsWith("Azure-Identity"))
{
switch (args.Level)
{
case EventLevel.Error:
streamWriter.Write(message);
break;
default:
Console.WriteLine(message);
break;
}
}
}, EventLevel.LogAlways);
#endregion
}

[Test]
[Ignore("Only verifying that the sample builds")]
public void ClientRequestId()
Expand Down

0 comments on commit 5df0fb2

Please sign in to comment.