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