MetalamaCommented examplesException HandlingRetryStep 4.​ Adding logging to retry
Open sandboxFocusImprove this doc

Retry example, step 4: Adding logging

In this article, we will add real-world logging to the retry aspect. To learn more about logging, please refer to Example: Logging.

Below is the updated code transformation:

Source Code





1internal class RemoteCalculator
2{
3    private static int _attempts;
4
5    [Retry( Attempts = 5 )]
6    public int Add( int a, int b )
7    {




8        // Let's pretend this method executes remotely
9        // and can fail for network reasons.
10
11        Thread.Sleep( 10 );
12
13        _attempts++;
14        Console.WriteLine( $"Trying for the {_attempts}-th time." );
15
16        if ( _attempts <= 3 )
17        {
18            throw new InvalidOperationException();
19        }
20
21        Console.WriteLine( $"Succeeded." );
22
23        return a + b;
24    }









25
26    [Retry( Attempts = 5 )]
27    public async Task<int> AddAsync( int a, int b )
28    {

















29        // Let's pretend this method executes remotely
30        // and can fail for network reasons.
31
32        await Task.Delay( 10 );
33
34        _attempts++;
35        Console.WriteLine( $"Trying for the {_attempts}-th time." );
36
37        if ( _attempts <= 3 )
38        {
39            throw new InvalidOperationException();
40        }
41
42        Console.WriteLine( $"Succeeded." );
43
44        return a + b;







45    }
46}
Transformed Code
1using System;
2using System.Threading;
3using System.Threading.Tasks;
4using Microsoft.Extensions.Logging;
5
6internal class RemoteCalculator
7{
8    private static int _attempts;
9
10    [Retry( Attempts = 5 )]
11    public int Add( int a, int b )
12    {
13        for (var i = 0; ; i++)
14        {
15            try
16            {
17                // Let's pretend this method executes remotely
18                // and can fail for network reasons.
19
20                Thread.Sleep( 10 );
21
22        _attempts++;
23        Console.WriteLine( $"Trying for the {_attempts}-th time." );
24
25        if ( _attempts <= 3 )
26        {
27            throw new InvalidOperationException();
28        }
29
30        Console.WriteLine( $"Succeeded." );
31
32        return a + b;
33            }
34            catch (Exception e) when (i < 5)
35            {
36                var delay = 100 * Math.Pow(2, i + 1);
37                LoggerExtensions.LogWarning(this._logger, $"RemoteCalculator.Add(a = {{{a}}}, b = {{{b}}}) has failed: {e.Message} Retrying in {delay} ms.");
38                Thread.Sleep((int)delay);
39                LoggerExtensions.LogTrace(this._logger, $"RemoteCalculator.Add(a = {{{a}}}, b = {{{b}}}): retrying now.");
40            }
41        }
42    }
43
44    [Retry( Attempts = 5 )]
45    public async Task<int> AddAsync( int a, int b )
46    {
47        for (var i = 0; ; i++)
48        {
49            try
50            {
51                return await this.AddAsync_Source(a, b);
52            }
53            catch (Exception e) when (i < 5)
54            {
55                var delay = 100 * Math.Pow(2, i + 1);
56                LoggerExtensions.LogWarning(this._logger, $"RemoteCalculator.AddAsync(a = {{{a}}}, b = {{{b}}}) has failed: {e.Message} Retrying in {delay} ms.");
57                await Task.Delay((int)delay);
58                LoggerExtensions.LogTrace(this._logger, $"RemoteCalculator.AddAsync(a = {{{a}}}, b = {{{b}}}): retrying now.");
59            }
60        }
61    }
62private async Task<int> AddAsync_Source(int a, int b)
63    {
64        // Let's pretend this method executes remotely
65        // and can fail for network reasons.
66
67        await Task.Delay( 10 );
68
69        _attempts++;
70        Console.WriteLine( $"Trying for the {_attempts}-th time." );
71
72        if ( _attempts <= 3 )
73        {
74            throw new InvalidOperationException();
75        }
76
77        Console.WriteLine( $"Succeeded." );
78
79        return a + b;
80    }
81    private ILogger _logger;
82
83    public RemoteCalculator
84    (ILogger<RemoteCalculator> logger = default)
85    {
86        this._logger = logger ?? throw new System.ArgumentNullException(nameof(logger));
87    }
88}

The code now produces the following output:

Trying for the 1-th time.
warn: RemoteCalculator[0]
      RemoteCalculator.Add(a = {1}, b = {1}) has failed: Operation is not valid due to the current state of the object. Retrying in 200 ms.
trce: RemoteCalculator[0]
      RemoteCalculator.Add(a = {1}, b = {1}): retrying now.
Trying for the 2-th time.
warn: RemoteCalculator[0]
      RemoteCalculator.Add(a = {1}, b = {1}) has failed: Operation is not valid due to the current state of the object. Retrying in 400 ms.
trce: RemoteCalculator[0]
      RemoteCalculator.Add(a = {1}, b = {1}): retrying now.
Trying for the 3-th time.
warn: RemoteCalculator[0]
      RemoteCalculator.Add(a = {1}, b = {1}) has failed: Operation is not valid due to the current state of the object. Retrying in 800 ms.
trce: RemoteCalculator[0]
      RemoteCalculator.Add(a = {1}, b = {1}): retrying now.
Trying for the 4-th time.
Succeeded
Warning

Be careful when including sensitive information (e.g., user credentials, personal data, etc.) in logs as they can pose a security risk. Avoid exposing sensitive data and remove them from logs using techniques such as Logging example, step 7: Removing sensitive data.

Implementation

To improve logging, we included the method name and parameter values in the logging message using the LoggingHelper.BuildInterpolatedString method. For more information about the method, refer to Logging example, step 2: Adding the method name and Logging example, step 3: Adding parameters values.

To substitute Console.WriteLine with ILogger and inject the ILogger into the target class, we used dependency injection. Refer to Logging example, step 4: Using ILogger for details.

Below is the aspect code update:

1using Metalama.Extensions.DependencyInjection;
2using Metalama.Framework.Aspects;
3using Metalama.Framework.Code;
4using Metalama.Framework.Code.SyntaxBuilders;
5using Microsoft.Extensions.Logging;
6
7#pragma warning disable CS8618, CS0649
8
9public class RetryAttribute : OverrideMethodAspect
10{
11    [IntroduceDependency]
12    private readonly ILogger _logger;
13
14    /// <summary>
15    /// Gets or sets the maximum number of times that the method should be executed.
16    /// </summary>
17    public int Attempts { get; set; } = 3;
18
19    /// <summary>
20    /// Gets or set the delay, in ms, to wait between the first and the second attempt.
21    /// The delay is doubled at every further attempt.
22    /// </summary>
23    public double Delay { get; set; } = 100;
24
25    // Template for non-async methods.
26    public override dynamic? OverrideMethod()
27    {
28        for ( var i = 0;; i++ )
29        {
30            try
31            {
32                return meta.Proceed();
33            }
34            catch ( Exception e ) when ( i < this.Attempts )
35            {
36                var delay = this.Delay * Math.Pow( 2, i + 1 );
37
38                var waitMessage = LoggingHelper.BuildInterpolatedString( false );
39                waitMessage.AddText( " has failed: " );
40                waitMessage.AddExpression( e.Message );
41                waitMessage.AddText( " Retrying in " );
42                waitMessage.AddExpression( delay );
43                waitMessage.AddText( " ms." );
44
45                this._logger.LogWarning( (string) waitMessage.ToValue() );
46
47                Thread.Sleep( (int) delay );
48
49                var retryingMessage = LoggingHelper.BuildInterpolatedString( false );
50                retryingMessage.AddText( ": retrying now." );
51
52                this._logger.LogTrace( (string) retryingMessage.ToValue() );
53            }
54        }
55    }
56
57    // Template for async methods.
58    public override async Task<dynamic?> OverrideAsyncMethod()
59    {
60        var cancellationTokenParameter
61            = meta.Target.Parameters.LastOrDefault( p => p.Type.Is( typeof(CancellationToken) ) );
62
63        for ( var i = 0;; i++ )
64        {
65            try
66            {
67                return await meta.ProceedAsync();
68            }
69            catch ( Exception e ) when ( i < this.Attempts )
70            {
71                var delay = this.Delay * Math.Pow( 2, i + 1 );
72
73                var waitMessage = LoggingHelper.BuildInterpolatedString( false );
74                waitMessage.AddText( " has failed: " );
75                waitMessage.AddExpression( e.Message );
76                waitMessage.AddText( " Retrying in " );
77                waitMessage.AddExpression( delay );
78                waitMessage.AddText( " ms." );
79
80                this._logger.LogWarning( (string) waitMessage.ToValue() );
81
82                if ( cancellationTokenParameter != null )
83                {
84                    await Task.Delay( (int) delay, cancellationTokenParameter.Value );
85                }
86                else
87                {
88                    await Task.Delay( (int) delay );
89                }
90
91                var retryingMessage = LoggingHelper.BuildInterpolatedString( false );
92                retryingMessage.AddText( ": retrying now." );
93
94                this._logger.LogTrace( (string) retryingMessage.ToValue() );
95            }
96        }
97    }
98}