8000 Add an observability behavior for logging, duration, and tracing by kzu · Pull Request #280 · devlooped/stunts · GitHub
[go: up one dir, main page]

Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions Stunts.slnx
Original file line number Diff line number Diff line change
Expand Up @@ -56,6 +56,7 @@
<Project Path="src/Stunts.CodeAnalysis/Stunts.CodeAnalysis.csproj" />
<Project Path="src/Stunts.CodeFixes/Stunts.CodeFixes.csproj" />
<Project Path="src/Stunts.DynamicProxy/Stunts.DynamicProxy.csproj" />
<Project Path="src/Stunts.Extensions/Stunts.Extensions.csproj" />
<Project Path="src/Stunts.IntegrationTests/Stunts.IntegrationTests.csproj" />
<Project Path="src/Stunts.Package/Stunts.Package.msbuildproj" Type="13b669be-bb05-4ddf-9536-439f39a36129" />
<Project Path="src/Stunts.CompiledProxy/Stunts.CompiledProxy.csproj" />
Expand Down
10000
4 changes: 4 additions & 0 deletions src/Directory.Packages.props
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,10 @@
<PackageVersion Include="System.Security.Cryptography.Xml" Version="10.0.12" />
</ItemGroup>

<ItemGroup Label="Extensions">
<PackageVersion Include="Microsoft.Extensions.Logging.Abstractions" Version="10.0.12" />
</ItemGroup>

<ItemGroup Label="Tests">
<PackageVersion Include="Microsoft.NET.Test.Sdk" Version="18.10.1" />
<PackageVersion Include="Microsoft.TestPlatform.ObjectModel" Version="18.10.1" />
Expand Down
106 changes: 106 additions & 0 deletions src/Stunts.Extensions/ObservabilityArguments.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,106 @@
using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Globalization;
using System.Text;

namespace Stunts
{
/// <summary>
/// Display projection of an invocation's arguments. Changes here are what
/// <see cref="ObservabilityBehavior"/> logs and tags. The target still receives
/// the original arguments.
/// </summary>
public sealed class ObservabilityArguments
{
readonly List<Slot> slots;

internal ObservabilityArguments(IMethodInvocation invocation)
{
slots = new List<Slot>(invocation.Arguments.Count);
foreach (Argument argument in invocation.Arguments)
slots.Add(new Slot(argument.Name, argument.RawValue));
}

/// <summary>
/// Omits the argument from the log and from activity tags.
/// </summary>
/// <param name="name">The parameter name.</param>
/// <exception cref="ArgumentOutOfRangeException">No argument has <paramref name="name"/>.</exception>
public void Drop(string name)
{
Find(name).Dropped = true;
}

/// <summary>
/// Sets the value written for the argument. A previous <see cref="Drop"/> of the same name is cleared.
/// The display value is not type-checked against the parameter.
/// </summary>
/// <param name="name">The parameter name.</param>
/// <param name="display">The value to log and tag.</param>
/// <exception cref="ArgumentOutOfRangeException">No argument has <paramref name="name"/>.</exception>
public void Replace(string name, object? display)
{
var slot = Find(name);
slot.Dropped = false;
slot.Display = display;
}

internal string Format()
{
var builder = new StringBuilder();
foreach (var slot in slots)
{
if (slot.Dropped)
continue;

if (builder.Length > 0)
builder.Append(", ");

builder.Append(slot.Name).Append('=').Append(Format(slot.Display));
}

return builder.ToString();
}

internal void Tag(Activity activity)
{
foreach (var slot in slots)
{
if (!slot.Dropped)
activity.SetTag("arg." + slot.Name, slot.Display);
}
}

Slot Find(string name)
{
if (name == null)
throw new ArgumentNullException(nameof(name));

foreach (var slot in slots)
{
if (slot.Name == name)
return slot;
}

throw new ArgumentOutOfRangeException(nameof(name), name, "No argument has this name.");
}

static string Format(object? display)
=> display switch
{
null => "null",
IFormattable formattable => formattable.ToString(null, CultureInfo.InvariantCulture) ?? "null",
_ => display.ToString() ?? "null"
};

sealed class Slot(string name, object? display)
{
public string Name => name;

public object? Display { get; set; } = display;

public bool Dropped { get; set; }
}
}
}
183 changes: 183 additions & 0 deletions src/Stunts.Extensions/ObservabilityBehavior.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,183 @@
using System;
using System.Diagnostics;
using System.Diagnostics.Metrics;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;

namespace Stunts
{
/// <summary>
/// Logs a call, records its duration in milliseconds, and writes an activity named for the member.
/// </summary>
/// <remarks>
/// Add this behavior first. The pipeline runs the first behavior outermost, so one activity and one
/// duration cover every behavior added after it. The duration is <see cref="ProceedOutcome.Elapsed"/>
/// in milliseconds and includes the time until a returned <see cref="Task"/> or <see cref="ValueTask"/> completes.
/// </remarks>
/// <param name="logger">Receives one event per settled call.</param>
/// <param name="duration">Duration histogram, in milliseconds. Create it with unit <c>ms</c>.</param>
/// <param name="activities">Activity source. <see cref="Source"/> is used when this is <see langword="null"/>.</param>
/// <param name="redact">Optional projection of arguments before they are logged or tagged.</param>
/// <exception cref="ArgumentNullException"><paramref name="logger"/> or <paramref name="duration"/> is <see langword="null"/>.</exception>
public sealed class ObservabilityBehavior(ILogger logger, Histogram<double> duration, ActivitySource? activities = null, ObservabilityRedaction? redact = null) : IStuntBehavior
{
/// <summary>Event name <c>StuntInvocation</c>.</summary>
public static EventId StuntInvocation { get; } = new(1, "StuntInvocation");

/// <summary>Activity source named <c>Stunts</c>.</summary>
public static ActivitySource Source { get; } = new("Stunts");

readonly ILogger log = logger ?? throw new ArgumentNullException(nameof(logger));
readonly Histogram<double> histogram = duration ?? throw new ArgumentNullException(nameof(duration));
readonly ActivitySource source = activities ?? Source;

/// <summary>
/// Observes every call with <paramref name="logger"/> and a histogram named
/// <c>stunts.invocation.duration</c> (unit <c>ms</c>) on <paramref name="meter"/>.
/// Activities come from <see cref="Source"/>.
/// </summary>
/// <param name="logger">Receives one event per settled call.</param>
/// <param name="meter">Owns the duration histogram.</param>
/// <param name="redact">Optional projection of arguments before they are logged or tagged.</param>
/// <exception cref="ArgumentNullException"><paramref name="logger"/> or <paramref name="meter"/> is <see langword="null"/>.</exception>
public ObservabilityBehavior(ILogger logger, Meter meter, ObservabilityRedaction? redact = null)
: this(logger, CreateDuration(meter), Source, redact)
{
}

/// <summary>
/// Returns a behavior that uses this instance's logger, histogram, and activity source with <paramref name="redact"/>.
/// </summary>
/// <param name="redact">Projection of arguments before they are logged or tagged.</param>
/// <exception cref="ArgumentNullException"><paramref name="redact"/> is <see langword="null"/>.</exception>
public ObservabilityBehavior WithRedaction(ObservabilityRedaction redact)
{
if (redact == null)
throw new ArgumentNullException(nameof(redact));

return new ObservabilityBehavior(log, histogram, source, redact);
}

/// <summary>Observes every invocation.</summary>
public bool AppliesTo(IMethodInvocation invocation) => true;

/// <summary>
/// Redacts arguments, starts an activity named for the member, and calls <paramref name="next"/> once through <c>Proceed</c>.
/// A synchronous exception is recorded and then propagates. An awaitable is returned immediately and observed when it settles.
/// </summary>
public IMethodReturn Execute(IMethodInvocation invocation, ExecuteHandler next)
{
var projection = new ObservabilityArguments(invocation);
redact?.Invoke(invocation, projection);

var member = invocation.MethodBase.Name;
var stuntType = StuntType(invocation.Target);
var activity = source.StartActivity(member, ActivityKind.Internal);
if (activity != null)
{
activity.SetTag("stunt.type", stuntType);
activity.SetTag("member.name", member);
projection.Tag(activity);
}

return invocation.Proceed(next, (outcome, again) =>
{
Observe(outcome, activity, stuntType, member, projection);
return new ValueTask<ProceedOutcome>(outcome);
});
}

void Observe(ProceedOutcome outcome, Activity? activity, string stuntType, string member, ObservabilityArguments projection)
{
var status = Status(outcome);
try
{
if (activity != null && outcome.Exception is not OperationCanceledException)
activity.SetStatus(outcome.Exception == null ? ActivityStatusCode.Ok : ActivityStatusCode.Error);
}
catch
{
// A listener failure must not replace the invocation outcome.
}

try
{
histogram.Record(outcome.Elapsed.TotalMilliseconds, new TagList
{
{ "stunt.type", stuntType },
{ "member.name", member },
{ "status", status }
});
}
catch
{
// A listener failure must not replace the invocation outcome.
}

try
{
var level = outcome.Exception switch
{
null => LogLevel.Information,
OperationCanceledException => LogLevel.Warning,
_ => LogLevel.Error
};
if (log.IsEnabled(level))
{
log.Log(
level,
StuntInvocation,
outcome.Exception is OperationCanceledException ? null : outcome.Exception,
"{StuntType}.{Member} {Status} in {DurationMilliseconds} ms {Arguments}",
stuntType,
member,
status,
outcome.Elapsed.TotalMilliseconds,
projection.Format());
}
}
catch
{
// A logger failure must not replace the invocation outcome.
}

try
{
activity?.Dispose();
}
catch
{
// Stopping the activity must not replace the invocation outcome.
}
}

static Histogram<double> CreateDuration(Meter meter)
{
if (meter == null)
throw new ArgumentNullException(nameof(meter));

return meter.CreateHistogram<double>("stunts.invocation.duration", unit: "ms");
}

static string StuntType(object target)
{
var type = target.GetType();
return type.FullName ?? type.Name;
}

static string Status(ProceedOutcome outcome)
=> outcome.Exception switch
{
null => "ok",
OperationCanceledException => "canceled",
_ => "error"
};
}

/// <summary>
/// Projects invocation arguments before <see cref="ObservabilityBehavior"/> logs or tags them.
/// </summary>
/// <param name="invocation">The invocation whose arguments can be dropped or replaced.</param>
/// <param name="arguments">The display projection. The target receives the original arguments.</param>
public delegate void ObservabilityRedaction(IMethodInvocation invocation, ObservabilityArguments arguments);
}
18 changes: 18 additions & 0 deletions src/Stunts.Extensions/Stunts.Extensions.csproj
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
<Project Sdk="Microsoft.NET.Sdk">

<PropertyGroup>
<TargetFramework>net10.0</TargetFramework>
<GenerateDocumentationFile>true</GenerateDocumentationFile>
<IsPackable>true</IsPackable>
<Description>Logging, metrics, and tracing behaviors for Stunts.</Description>
</PropertyGroup>

<ItemGroup>
<PackageReference Include="Microsoft.Extensions.Logging.Abstractions" />
</ItemGroup>

<ItemGroup>
<ProjectReference Include="..\Stunts\Stunts.csproj" Pack="false" />
</ItemGroup>

</Project>
10 changes: 10 additions & 0 deletions src/Stunts.Extensions/readme.md
Original file line number Diff line number Diff line change
@@ -0,0 +1,10 @@
[![EULA](https://img.shields.io/badge/EULA-OSMF-blue?labelColor=black&color=C9FF30)](osmfeula.txt)
[![OSS](https://img.shields.io/github/license/devlooped/oss.svg?color=blue)](license.txt)
[![GitHub](https://img.shields.io/badge/-source-181717.svg?logo=GitHub)](https://github.com/devlooped/stunts)

<!-- include https://github.com/devlooped/.github/raw/main/osmf.md -->

<!-- include https://github.com/devlooped/sponsors/raw/main/footer.md -->

<!-- Exclude from auto-expansion by devlooped/actions-include GH action -->
<!-- exclude -->
Loading
0