Call tracing example, step 1: Tracing calls to a library

When you investigate a problem without a debugger, for instance in a CI build, you need to know which calls the application makes to a library, with which arguments, and what each call returns. Adding log statements around each call changes many files, and you must remove these statements after the investigation.

In this example, the application calls InventoryClient, a class of a separate class library. The library does not use Metalama, and its source code does not need to be available. One file of the application, TracingFabric.cs, traces every call to the methods of InventoryClient.

Metalama rewrites each call to InventoryClient so that it calls a generated interceptor method. The calling code itself does not change in the source code:

1using Metalama.Samples.CallTracing.Inventory;
2
3namespace Metalama.Samples.CallTracing1;
4
5public class OrderService
6{
7    private readonly InventoryClient _inventory = new();
8
9    public bool CanOrder( string sku, int quantity ) => this._inventory.GetStock( sku ) >= quantity;
10
11    public void PlaceOrder( string sku, int quantity )
12    {
13        this._inventory.Reserve( sku, quantity );
14    }
15}
16

1using Metalama.Samples.CallTracing.Inventory;
2
3namespace Metalama.Samples.CallTracing1;
4
5public class OrderService
6{
7    private readonly InventoryClient _inventory = new();
8
9    public bool CanOrder( string sku, int quantity ) => MetalamaInterceptors.InventoryClient_GetStock_Interceptor( this._inventory,sku:sku ) >= quantity;
10
11    public void PlaceOrder( string sku, int quantity )
12    {
13        MetalamaInterceptors.InventoryClient_Reserve_Interceptor( this._inventory,sku:sku,quantity:quantity );
14    }
15}
16

When the program runs, the interceptors write the following trace. The durations change from one run to another.

[trace] OrderService.CanOrder -> InventoryClient.GetStock(sku: BOOK) returned 10 in 1.198 ms.
[trace] OrderService.PlaceOrder -> InventoryClient.Reserve(sku: BOOK, quantity: 3) succeeded in 0.261 ms.
[trace] OrderService.PlaceOrder -> InventoryClient.Reserve(sku: PEN, quantity: 5) threw InvalidOperationException in 0.741 ms: Only 2 items of 'PEN' are in stock.

Implementation

The project references the Metalama.Extensions.Interceptors package. The tracing is implemented by the following project fabric:

1using Metalama.Extensions.Interceptors;
2using Metalama.Framework.Aspects;
3using Metalama.Framework.Code;
4using Metalama.Framework.Fabrics;
5using Metalama.Samples.CallTracing.Inventory;
6using System.Diagnostics;
7
8namespace Metalama.Samples.CallTracing1;
9
10// Traces the calls to InventoryClient. Delete this file to remove the tracing.
11internal class TracingFabric : ProjectFabric
12{
13    public override void AmendProject( IProjectAmender amender )
14        => amender.InterceptMethods(
15            calls => calls
16                .Type( typeof(InventoryClient) )
17                .AllMethods()
18                .RedirectToSynthesizedMethod( nameof(this.Trace) )
19                .WithGranularity( InterceptorGranularity.Member ) );
20
21    [Template]
22    public dynamic? Trace()
23    {
24        var interceptedMethod = meta.Interception.Method.InterceptedMethod;
25
26        // Build the description of the call: the caller, the called method, and the arguments.
27        var arguments = new List<string>();
28
29        foreach ( var parameter in meta.Interception.Method.ArgumentParameters )
30        {
31            arguments.Add( $"{parameter.Name}: {parameter.Value}" );
32        }
33
34        var call = $"{meta.Interception.CallingType!.Name}.{meta.Interception.CallingMember!.Name} -> "
35                   + $"{interceptedMethod.DeclaringType.Name}.{interceptedMethod.Name}"
36                   + $"({string.Join( ", ", arguments )})";
37
38        var stopwatch = Stopwatch.StartNew();
39
40        try
41        {
42            var result = meta.Proceed();
43
44            if ( interceptedMethod.ReturnType.Equals( SpecialType.Void ) )
45            {
46                Console.WriteLine( $"[trace] {call} succeeded in {stopwatch.Elapsed.TotalMilliseconds:F3} ms." );
47            }
48            else
49            {
50                Console.WriteLine(
51                    $"[trace] {call} returned {result} in {stopwatch.Elapsed.TotalMilliseconds:F3} ms." );
52            }
53
54            return result;
55        }
56        catch ( Exception e )
57        {
58            Console.WriteLine(
59                $"[trace] {call} threw {e.GetType().Name} in {stopwatch.Elapsed.TotalMilliseconds:F3} ms: {e.Message}" );
60
61            throw;
62        }
63    }
64}
65

The AmendProject method registers the interceptors with the InterceptMethods method:

• Type( typeof(InventoryClient) ).AllMethods() selects all the methods that InventoryClient declares. Metalama intercepts the calls to these methods in the source code of the current project.
• RedirectToSynthesizedMethod( nameof(this.Trace) ) generates the interceptor methods from the Trace template. The template is a member of the fabric, so the registration does not need to give a template provider.
• WithGranularity( InterceptorGranularity.Member ) generates one interceptor for each calling member. Without this call, the call sites in different members share an interceptor, and the template cannot read the calling member.

The Trace template is a T# template, like the templates of override aspects. It reads the description of the interception with meta.Interception. This extension property requires C# 14. With an earlier version of C#, use meta.GetExtension<IInterceptionInfo>() instead.

• CallingType and CallingMember give the caller.
• Method.InterceptedMethod gives the method that the call site calls.
• Method.ArgumentParameters gives the parameters of the interceptor that receive the arguments of the call.
• meta.Proceed() calls the intercepted method with the arguments of the call site.

The template measures the duration with a Stopwatch, and writes the result or the exception. Because Reserve returns void, the template checks the return type of the intercepted method at compile time and writes a different message for void methods.

Metalama generates the interceptor methods in an internal static class named MetalamaInterceptors, in the global namespace.

Removing the tracing

The tracing exists only in TracingFabric.cs. To remove it, delete this file. The calling code and the library do not change. To keep the file but enable the tracing only in some builds, see Call tracing example, step 2: Enabling tracing only in a trace build.