Metalama//Commented Examples/Logging/Step 8.​ Avoiding infinite recursions
Open sandboxFocus

Logging example, step 8: Avoiding infinite recursion

Infinite recursion can occur when one method's logging logic calls another method's logging logic. Infinite recursions can cause stack overflow exceptions, resulting in crashes or unintended side effects. It consumes system resources, negatively affecting performance and potentially rendering the application, and any other application on the same device, unresponsive. In addition, excessive log entries generated by recursion make it challenging to locate the real cause of the problem, complicate log analysis, and increase storage requirements.

Therefore, infinite recursions in logging must be avoided at all costs.

The first step is to avoid logging the ToString method. However, sometimes a non-logged ToString method can access logged properties or methods, and indirectly cause an infinite recursion. The most reliable approach is to add the following code in the logging pattern:

using ( var guard = LoggingRecursionGuard.Begin() )
{
  if ( guard.CanLog )
  {
    this._logger.LogTrace( message );
  }
}

We can update the previous example with this new approach:

Source Code



1public class LoginService
2{
3    // The 'password' parameter will not be logged because of its name.
4    public bool VerifyPassword( string account, string password ) => account == password;











































5
6    [return: NotLogged]
7    public string GetSaltedHash( string account, string password, [NotLogged] string salt ) =>
8        account + password + salt;


















































9}
Transformed Code
1using System;
2using Microsoft.Extensions.Logging;
3
4public class LoginService
5{
6    // The 'password' parameter will not be logged because of its name.
7    public bool VerifyPassword( string account, string password )
8{
9        var isTracingEnabled = this._logger.IsEnabled(LogLevel.Trace);
10        if (isTracingEnabled)
11        {
12            using (var guard = global::LoggingRecursionGuard.Begin())
13            {
14                if (guard.CanLog)
15                {
16                    LoggerExtensions.LogTrace(this._logger, $"LoginService.VerifyPassword(account = {{{account}}}, password = <redacted> ) started.");
17                }
18            }
19        }
20
21        try
22        {
23            bool result;
24            result = account == password;
25            if (isTracingEnabled)
26            {
27                using (var guard_1 = global::LoggingRecursionGuard.Begin())
28                {
29                    if (guard_1.CanLog)
30                    {
31                        LoggerExtensions.LogTrace(this._logger, $"LoginService.VerifyPassword(account = {{{account}}}, password = <redacted> ) returned {result}.");
32                    }
33                }
34            }
35
36            return result;
37        }
38        catch (Exception e) when (this._logger.IsEnabled(LogLevel.Warning))
39        {
40            using (var guard_2 = global::LoggingRecursionGuard.Begin())
41            {
42                if (guard_2.CanLog)
43                {
44                    LoggerExtensions.LogWarning(this._logger, $"LoginService.VerifyPassword(account = {{{account}}}, password = <redacted> ) failed: {e.Message}");
45                }
46            }
47
48            throw;
49        }
50    }
51
52    [return: NotLogged]
53    public string GetSaltedHash( string account, string password, [NotLogged] string salt )
54{
55        var isTracingEnabled = this._logger.IsEnabled(LogLevel.Trace);
56        if (isTracingEnabled)
57        {
58            using (var guard = global::LoggingRecursionGuard.Begin())
59            {
60                if (guard.CanLog)
61                {
62                    LoggerExtensions.LogTrace(this._logger, $"LoginService.GetSaltedHash(account = {{{account}}}, password = <redacted> , salt = <redacted> ) started.");
63                }
64            }
65        }
66
67        try
68        {
69            string result;
70            result =         account + password + salt;
71            if (isTracingEnabled)
72            {
73                using (var guard_1 = global::LoggingRecursionGuard.Begin())
74                {
75                    if (guard_1.CanLog)
76                    {
77                        LoggerExtensions.LogTrace(this._logger, $"LoginService.GetSaltedHash(account = {{{account}}}, password = <redacted> , salt = <redacted> ) returned <redacted>.");
78                    }
79                }
80            }
81
82            return result;
83        }
84        catch (Exception e) when (this._logger.IsEnabled(LogLevel.Warning))
85        {
86            using (var guard_2 = global::LoggingRecursionGuard.Begin())
87            {
88                if (guard_2.CanLog)
89                {
90                    LoggerExtensions.LogWarning(this._logger, $"LoginService.GetSaltedHash(account = {{{account}}}, password = <redacted> , salt = <redacted> ) failed: {e.Message}");
91                }
92            }
93
94            throw;
95        }
96    }
97
98    private ILogger _logger;
99
100    public LoginService
101    (ILogger<LoginService> logger = default)
102    {
103        this._logger = logger ?? throw new System.ArgumentNullException(nameof(logger));
104    }
105}

Infrastructure code

LoggingRecursionGuard uses a thread-static field to indicate whether logging is currently occurring:

1internal static class LoggingRecursionGuard
2{
3    [ThreadStatic]
4    public static bool _isLogging;
5
6    public static DisposeCookie Begin()
7    {
8        if ( _isLogging )
9        {
10            return new DisposeCookie( false );
11        }
12        else
13        {
14            _isLogging = true;
15            return new DisposeCookie( true );
16        }
17    }
18
19    internal class DisposeCookie : IDisposable
20    {
21        public DisposeCookie( bool canLog )
22        {
23            this.CanLog = canLog;
24        }
25
26        public bool CanLog { get; }
27
28        public void Dispose()
29        {
30            if ( this.CanLog )
31            {
32                _isLogging = false;
33            }
34        }
35    }
36}

Aspect code

The LogAttribute code has been updated as follows:

1using Metalama.Extensions.DependencyInjection;
2using Metalama.Framework.Aspects;
3using Metalama.Framework.Code;
4using Metalama.Framework.Code.SyntaxBuilders;
5using Microsoft.Extensions.Logging;
6
7public class LogAttribute : OverrideMethodAspect
8{
9    [IntroduceDependency]
10    private readonly ILogger _logger;
11
12    public override dynamic? OverrideMethod()
13    {
14        // Determine if tracing is enabled.
15        var isTracingEnabled = this._logger.IsEnabled( LogLevel.Trace );
16
17        // Write entry message.
18        if ( isTracingEnabled )
19        {
20            var entryMessage = BuildInterpolatedString( false );
21            entryMessage.AddText( " started." );
22
23            using ( var guard = LoggingRecursionGuard.Begin() )
24            {
25                if ( guard.CanLog )
26                {
27                    this._logger.LogTrace( (string) entryMessage.ToValue() );
28                }
29            }
30        }
31
32        try
33        {
34            // Invoke the method and store the result in a variable.
35            var result = meta.Proceed();
36
37            if ( isTracingEnabled )
38            {
39                // Display the success message. The message is different when the method is void.
40                var successMessage = BuildInterpolatedString( true );
41
42                if ( meta.Target.Method.ReturnType.Is( typeof(void) ) )
43                {
44                    // When the method is void, display a constant text.
45                    successMessage.AddText( " succeeded." );
46                }
47                else
48                {
49                    // When the method has a return value, add it to the message.
50                    successMessage.AddText( " returned " );
51
52                    if ( SensitiveParameterFilter.IsSensitive( meta.Target.Method.ReturnParameter ) )
53                    {
54                        successMessage.AddText( "<redacted>" );
55                    }
56                    else
57                    {
58                        successMessage.AddExpression( result );
59                    }
60
61                    successMessage.AddText( "." );
62                }
63
64                using ( var guard = LoggingRecursionGuard.Begin() )
65                {
66                    if ( guard.CanLog )
67                    {
68                        this._logger.LogTrace( (string) successMessage.ToValue() );
69                    }
70                }
71            }
72
73            return result;
74        }
75        catch ( Exception e ) when ( this._logger.IsEnabled( LogLevel.Warning ) )
76        {
77            // Display the failure message.
78            var failureMessage = BuildInterpolatedString( false );
79            failureMessage.AddText( " failed: " );
80            failureMessage.AddExpression( e.Message );
81
82            using ( var guard = LoggingRecursionGuard.Begin() )
83            {
84                if ( guard.CanLog )
85                {
86                    this._logger.LogWarning( (string) failureMessage.ToValue() );
87                }
88            }
89
90            throw;
91        }
92    }
93
94    // Builds an InterpolatedStringBuilder with the beginning of the message.
95    private static InterpolatedStringBuilder BuildInterpolatedString( bool includeOutParameters )
96    {
97        var stringBuilder = new InterpolatedStringBuilder();
98
99        // Include the type and method name.
100        stringBuilder.AddText( meta.Target.Type.ToDisplayString( CodeDisplayFormat.MinimallyQualified ) );
101        stringBuilder.AddText( "." );
102        stringBuilder.AddText( meta.Target.Method.Name );
103        stringBuilder.AddText( "(" );
104        var i = meta.CompileTime( 0 );
105
106        // Include a placeholder for each parameter.
107        foreach ( var p in meta.Target.Parameters )
108        {
109            var comma = i > 0 ? ", " : "";
110
111            if ( SensitiveParameterFilter.IsSensitive( p ) )
112            {
113                // Do not log sensitive parameters.
114                stringBuilder.AddText( $"{comma}{p.Name} = <redacted> " );
115            }
116            else if ( p.RefKind == RefKind.Out && !includeOutParameters )
117            {
118                // When the parameter is 'out', we cannot read the value.
119                stringBuilder.AddText( $"{comma}{p.Name} = <out> " );
120            }
121            else
122            {
123                // Otherwise, add the parameter value.
124                stringBuilder.AddText( $"{comma}{p.Name} = {{" );
125                stringBuilder.AddExpression( p.Value );
126                stringBuilder.AddText( "}" );
127            }
128
129            i++;
130        }
131
132        stringBuilder.AddText( ")" );
133
134        return stringBuilder;
135    }
136}