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.

Sign up for GitHub

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

Jump to bottom

Default logging behaviour when using InstanceName is unintuitive #1547

Closed
martincostello opened this issue Sep 4, 2023 · 8 comments · Fixed by #1555
Closed

Default logging behaviour when using InstanceName is unintuitive #1547

martincostello opened this issue Sep 4, 2023 · 8 comments · Fixed by #1555
Labels
bug v8 Issues related to the new version 8 of the Polly library.
Milestone
v8.0.0

Comments

@martincostello
Copy link
Member

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.
@martincostello martincostello added bug v8 Issues related to the new version 8 of the Polly library. labels Sep 4, 2023
@martincostello martincostello added this to the v8.0.0 milestone Sep 4, 2023
@martintmk
Copy link
Contributor

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
Copy link
Member Author

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
Copy link
Member Author

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
Copy link
Contributor

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
Copy link
Member Author

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

@martintmk martintmk mentioned this issue Sep 6, 2023
Merged
4 tasks
@martintmk
Copy link
Contributor

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

@martincostello
Copy link
Member Author

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
Copy link
Contributor

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

@github-project-automation github-project-automation bot moved this to Done in Polly v8 Sep 6, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug v8 Issues related to the new version 8 of the Polly library.
Projects
No open projects
Polly v8
Status: Done
Milestone
v8.0.0
Development

Successfully merging a pull request may close this issue.

Fix Name and InstanceName not being set for reloadable pipelines App-vNext/Polly
2 participants
@martincostello @martintmk