Default logging behaviour when using InstanceName is unintuitive

[martincostello]

If a user chooses to set a InstanceName on a strategy/pipeline, its value is never passed through to telemetry and is always null.

This is because by default the InstanceNameFormatter is null, so any value is always formatted to be null:

Polly/src/Polly.Core/Registry/ResiliencePipelineRegistryOptions.cs

Lines 38 to 49 in 445c582

	/// <summary>
	/// Gets or sets the formatter that is used by the registry to format the <typeparamref name="TKey"/> to a string that
	/// represents the instance name of the builder.
	/// </summary>
	/// <remarks>
	/// Use custom formatter for composite keys in case you want to have different metric values for a builder and instance key.
	/// In general, pipelines can have the same builder name and different instance names.
	/// </remarks>
	/// <value>
	/// The default value is <see langword="null"/>.
	/// </value>
	public Func<TKey, string>? InstanceNameFormatter { get; set; }

To get the desired behaviour, instead the user has to explicitly configure the internally-registered-by-default ResiliencePipelineRegistryOptions<TKey> type to provide a formatter for each type they generate a registry for:

services.AddOptions<ResiliencePipelineRegistryOptions<string>>()
        .Configure((p) => p.InstanceNameFormatter = (key) => key?.ToString() ?? string.Empty);

This behaviour is not intuitive (I had to work it out by debugging through the Polly sources from my app).

It would be much easier for users to instead just apply a default formatter to the instance the same as we do for BuilderNameFormatter:

Polly/src/Polly.Core/Registry/ResiliencePipelineRegistryOptions.cs

Lines 51 to 63 in 445c582

	/// <summary>
	/// Gets or sets the formatter that is used by the registry to format the <typeparamref name="TKey"/> to a string that
	/// represents the builder name.
	/// </summary>
	/// <remarks>
	/// Use custom formatter for composite keys in case you want to have different metric values for a builder and strategy key.
	/// In general, pipelines can have the same builder name and different pipeline keys.
	/// </remarks>
	/// <value>
	/// The default value is a formatter that formats the keys using the <see cref="object.ToString"/> method.
	/// </value>
	[Required]
	public Func<TKey, string> BuilderNameFormatter { get; set; } = (key) => key?.ToString() ?? string.Empty;

We could always pre-allocate the default formatter delegates as a private static field if allocations are a concern.

[martintmk]

I am not sure whether this is a bur or feature. Let me explain the behavior/thinking about the instance name.

Instance name is meant as an additional dimension in case there are multiple pipeline instances with the same name. It's advanced feature in case composite pipeline keys are used.

For example:

Polly/test/Polly.Extensions.Tests/Issues/IssuesTests.StrategiesPerEndpoint_1365.cs

Line 79 in 305ac23

options.InstanceNameFormatter = key => $"{key.EndpointName}/{key.Resource}";

The reason InstanceNameFormatter does not have a value assigned is that it would produce the same value as BuilderNameFormatter, so there would be no additional information added to the telemetry.

pipeline-name: my-key
pipeline-instance: my-key

These two would always be the same as opposed to:

pipeline-name: my-key
pipeline-instance: null

In the latter example we at least know that no instance was specified automatically. Besides nothing prevents anyone from doing:

new ServiceCollection().AddResiliencePipeline("my-key", builder =>
{
    builder.InstanceName = "my-instance-name";
    builder.AddConcurrencyLimiter(100);
});

In the case above the telemetry is:

pipeline-name: my-key
pipeline-instance: my-instance-name

[martincostello]

I'll re-check what I was doing, but this came up because (if I remember correctly) I saw that despite setting the instance name in the configuration method, the instance name was missing in the logs.

[martincostello]

Yep, the values are missing from the logged values unless the formatter is set.

Not set:

 PollySandbox.IntegrationTests.Can_Get_Movie
   Source: IntegrationTests.cs line 33
   Duration: 516 ms

  Standard Output: 
[2023-09-06 12:42:37Z] info: System.Net.Http.HttpClient.Movies.LogicalHandler[100]
      Start processing HTTP request GET https://dummyapi.online/api/movies/5
[2023-09-06 12:42:37Z] info: System.Net.Http.HttpClient.Movies.LogicalHandler[101]
      End processing HTTP request after 8.9891ms - 200
[2023-09-06 12:42:37Z] info: Polly[3]
      Execution attempt. Source: 'Movies/Retry/Movies/Movies/Retry', Operation Key: 'Movies.GetMovieAsync', Result: 'PollySandbox.Movie', Handled: 'False', Attempt: '0', Execution Time: '53.5176'
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/(null)/(null)', Operation Key: '', Result: ''
[2023-09-06 12:42:37Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/(null)/(null)', Operation Key: '', Result: ''

Set:

 PollySandbox.IntegrationTests.Can_Get_Movie
   Source: IntegrationTests.cs line 33
   Duration: 451 ms

  Standard Output: 
[2023-09-06 12:41:44Z] info: System.Net.Http.HttpClient.Movies.LogicalHandler[100]
      Start processing HTTP request GET https://dummyapi.online/api/movies/5
[2023-09-06 12:41:44Z] info: System.Net.Http.HttpClient.Movies.LogicalHandler[101]
      End processing HTTP request after 8.7178ms - 200
[2023-09-06 12:41:44Z] info: Polly[3]
      Execution attempt. Source: 'Movies/Retry/Movies/Movies/Retry', Operation Key: 'Movies.GetMovieAsync', Result: 'PollySandbox.Movie', Handled: 'False', Attempt: '0', Execution Time: '48.4437'
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/Movies/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/Movies/RateLimit/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/Movies/Timeout/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/Movies/CircuitBreaker/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/Movies/Retry/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/Movies/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/Movies/RateLimit/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/Movies/Timeout/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/Movies/CircuitBreaker/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/Movies/Retry/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/Movies/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/Movies/RateLimit/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/Movies/Timeout/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/Movies/CircuitBreaker/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/Movies/Retry/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/Movies/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/Movies/RateLimit/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/Movies/Timeout/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/Movies/CircuitBreaker/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/Movies/Retry/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/Movies/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/Movies/RateLimit/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/Movies/Timeout/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/Movies/CircuitBreaker/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/Movies/Retry/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/GetMovieAsync/Movies/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/RateLimit/Movies/RateLimit/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Timeout/Movies/Timeout/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/CircuitBreaker/GetMovieAsync/Movies/CircuitBreaker/GetMovieAsync/(null)', Operation Key: '', Result: ''
[2023-09-06 12:41:44Z] info: Polly[0]
      Resilience event occurred. EventName: 'OnReload', Source: 'Movies/Retry/Movies/Retry/(null)', Operation Key: '', Result: ''

[martintmk]

I'll re-check what I was doing, but this came up because (if I remember correctly) I saw that despite setting the instance name in the configuration method, the instance name was missing in the logs.

Can you point me to piece that sets the InstanceName ?

[martincostello]

It doesn't in the PR, I just changed it locally to add builder.InstanceName = builder.Name in a few places.

[martintmk]

I tried to replicate the problem in #1555 but it works ok.

[martincostello]

I've pushed a change to martincostello/polly-sandbox#1 to set InstanceName would should demonstrate the missing values from the formatted logger messages.

[martintmk]

Managed to replicate this, this problem only occurs with reloadable pipelines. Will fix tomorrow.