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.

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

[docs] Add exception logging best practices #6037

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
Open
Changes from all commits
Commits
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
180 changes: 145 additions & 35 deletions docs/logs/README.md
Original file line number Diff line number Diff line change
Expand Up @@ -25,33 +25,17 @@ OpenTelemetry .NET:
* [Getting Started - Console Application](./getting-started-console/README.md)
* [Logging with Complex Objects](./complex-objects/README.md)

## Structured Logging

:heavy_check_mark: You should use structured logging.

* Structured logging is more efficient than unstructured logging.
* Filtering and redaction can happen on individual key-value pairs instead of
the entire log message.
* Storage and indexing are more efficient.
* Structured logging makes it easier to manage and consume logs.

:stop_sign: You should avoid string interpolation.

> [!WARNING]
> The following code has bad performance due to [string
interpolation](https://learn.microsoft.com/dotnet/csharp/tutorials/string-interpolation):

```csharp
var food = "tomato";
var price = 2.99;
## Logging API

logger.LogInformation($"Hello from {food} {price}.");
```
### ILogger

Refer to the [logging performance
benchmark](../../test/Benchmarks/Logs/LogBenchmarks.cs) for more details.
.NET supports high performance, structured logging via the
[`Microsoft.Extensions.Logging.ILogger`](https://docs.microsoft.com/dotnet/api/microsoft.extensions.logging.ilogger)
interface (including
[`ILogger<TCategoryName>`](https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.ilogger-1))
to help monitor application behavior and diagnose issues.

## Package Version
#### Package Version

:heavy_check_mark: You should always use the
[`ILogger`](https://docs.microsoft.com/dotnet/api/microsoft.extensions.logging.ilogger)
Expand All @@ -69,16 +53,6 @@ package, regardless of the .NET runtime version being used:
backward compatibility on `Microsoft.Extensions.Logging` even during major
version bumps, so compatibility is not a concern here.

## Logging API

### ILogger

.NET supports high performance, structured logging via the
[`Microsoft.Extensions.Logging.ILogger`](https://docs.microsoft.com/dotnet/api/microsoft.extensions.logging.ilogger)
interface (including
[`ILogger<TCategoryName>`](https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.ilogger-1))
to help monitor application behavior and diagnose issues.

#### Get Logger

In order to use the `ILogger` interface, you need to first get a logger. How to
Expand Down Expand Up @@ -125,7 +99,38 @@ are not super expensive, they still come with CPU and memory cost, and are meant
to be reused throughout the application. Refer to the [logging performance
benchmark](../../test/Benchmarks/Logs/LogBenchmarks.cs) for more details.

#### Use Logger
#### Write log messages

:heavy_check_mark: You should use structured logging.

* Structured logging is more efficient than unstructured logging.
* Filtering and redaction can happen on individual key-value pairs instead of
the entire log message.
* Storage and indexing are more efficient.
* Structured logging makes it easier to manage and consume logs.

```csharp
var food = "tomato";
var price = 2.99;

logger.LogInformation("Hello from {food} {price}.", food, price);
```

:stop_sign: You should avoid string interpolation.

> [!WARNING]
> The following code has bad performance due to [string
interpolation](https://learn.microsoft.com/dotnet/csharp/tutorials/string-interpolation):

```csharp
var food = "tomato";
var price = 2.99;

logger.LogInformation($"Hello from {food} {price}.");
```

Refer to the [logging performance
benchmark](../../test/Benchmarks/Logs/LogBenchmarks.cs) for more details.

:heavy_check_mark: You should use [compile-time logging source
generation](https://docs.microsoft.com/dotnet/core/extensions/logger-message-generator)
Expand Down Expand Up @@ -222,6 +227,111 @@ code is now depending on which logger is being enabled, not to mention the
argument evaluation might have significant side effects that are now depending
on the logging configuration.

:heavy_check_mark: You should use a dedicated parameter to log exceptions when
using the compile-time source generator.

```csharp
var food = "tomato";
var price = 2.99;

try
{
// Execute some logic

logger.SayHello(food, price);
}
catch (Exception ex)
{
logger.SayHelloFailure(ex, food, price);
}

internal static partial class LoggerExtensions
{
[LoggerMessage(Level = LogLevel.Information, Message = "Hello from {food} {price}.")]
public static partial void SayHello(this ILogger logger, string food, double price);

[LoggerMessage(Level = LogLevel.Error, Message = "Could not say hello from {food} {price}.")]
public static partial void SayHelloFailure(this ILogger logger, Exception exception, string food, double price);
}
```

> [!NOTE]
> When using the compile-time source generator the first `Exception` parameter
> detected is automatically given special handling. It **SHOULD NOT** be part of
> the message template. For details see: [Log method
> anatomy](https://learn.microsoft.com/dotnet/core/extensions/logger-message-generator#log-method-anatomy).

:heavy_check_mark: You should use the dedicated overloads to log exceptions when
using the logging extensions methods.
cijothomas marked this conversation as resolved.
Show resolved Hide resolved

```csharp
var food = "tomato";
var price = 2.99;

try
{
// Execute some logic

logger.LogInformation("Hello from {food} {price}.", food, price);
}
catch (Exception ex)
{
logger.LogError(ex, "Could not say hello from {food} {price}.", food, price);
}
```

:stop_sign: You should avoid adding exception details into the message template.

You want to use the correct `Exception` APIs because the OpenTelemetry
Specification [defines dedicated
attributes](https://github.com/open-telemetry/semantic-conventions/blob/main/docs/exceptions/exceptions-logs.md)
for `Exception` details. The following examples show what **NOT** to do. In
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If a user does not want to get the stack details (due to cost etc.), then there is no opt-out mechanism today, so this maybe a viable workaround folks can use today. i.e they send ex.msg, and ex.type as normal parameters, and not pass in the exception object...

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's a good point. Probably doesn't belong in best practices though. What if we put that somewhere with more advanced content or somewhere showing customizations?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That'd be good (move it elsewhere)

these cases the details won't be lost, but the dedicated attributes also won't
be added.

```csharp
var food = "tomato";
var price = 2.99;

try
{
// Execute some logic

logger.SayHello(food, price);
}
catch (Exception ex)
{
logger.SayHelloFailure(food, price, ex.Message);
}

internal static partial class LoggerExtensions
{
[LoggerMessage(Level = LogLevel.Information, Message = "Hello from {food} {price}.")]
public static partial void SayHello(this ILogger logger, string food, double price);

// BAD - Exception should not be part of the message template. Use the dedicated parameter.
[LoggerMessage(Level = LogLevel.Error, Message = "Could not say hello from {food} {price} {message}.")]
public static partial void SayHelloFailure(this ILogger logger, string food, double price, string message);
}
```

```csharp
var food = "tomato";
var price = 2.99;

try
{
// Execute some logic

logger.LogInformation("Hello from {food} {price}.", food, price);
}
catch (Exception ex)
{
// BAD - Exception should not be part of the message template. Use the dedicated parameter.
logger.LogError("Could not say hello from {food} {price} {message}.", food, price, ex.Message);
}
```

## LoggerFactory

In many cases, you can use [ILogger](#ilogger) without having to interact with
Expand Down