Semantic Kernel enterprise tutorial: logging and telemetry

Semantic Kernel enterprise logging telemetry isn’t optional when you’re running LLM workloads in production. You need visibility into prompt execution, function calling chains, token consumption, and latency distributions across providers. This guide walks through a production-ready setup using ILogger, OpenTelemetry, and Semantic Kernel’s built-in hooks — plus the gotchas that bite teams after deploy.

Why standard logging isn’t enough

Console.WriteLine and basic ILogger calls capture that something happened. They don’t capture what the model saw, which functions fired, or how many tokens each step consumed. In enterprise SK apps, a single user request might trigger: planner invocation → function calling loop → multiple model calls → vector search → final synthesis. Without correlated telemetry, debugging a 30-second latency spike or a hallucinated function call becomes guesswork.

Semantic Kernel exposes two extension points that matter: FunctionInvocationFilter for synchronous interception and IPromptRenderFilter for prompt inspection. Combined with System.Diagnostics.ActivitySource, you get end-to-end traces that map to your observability stack.

Structured logging foundation

Start with a logger that emits JSON to stdout — your log shipper (Fluent Bit, Vector, Datadog agent) handles the rest. Avoid string interpolation in log messages; use structured properties so queries work.

// Program.cs or Startup.cs
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.DependencyInjection;

var builder = WebApplication.CreateBuilder(args);

builder.Logging.ClearProviders();
builder.Logging.AddJsonConsole(options =>
{
    options.JsonWriterOptions = new System.Text.Json.JsonWriterOptions
    {
        Indented = false
    };
    options.TimestampFormat = "yyyy-MM-ddTHH:mm:ss.fffZ";
});

builder.Services.AddLogging(logging =>
{
    logging.AddFilter("Microsoft.SemanticKernel", LogLevel.Debug);
    logging.AddFilter("KernelFunction", LogLevel.Information);
});

var app = builder.Build();

The AddFilter calls matter. SK’s internal logging is verbose at Debug; you want Information for your own function invocations but Debug for the kernel’s planner and function resolution logic. Adjust per environment.

OpenTelemetry integration

OpenTelemetry is the vendor-neutral standard. Wire it once, export to whatever backend (Jaeger, Zipkin, OTLP endpoint, Honeycomb, Datadog, Grafana Tempo).

// Extensions/OpenTelemetryExtensions.cs
using OpenTelemetry.Logs;
using OpenTelemetry.Metrics;
using OpenTelemetry.Resources;
using OpenTelemetry.Trace;

public static class OpenTelemetryExtensions
{
    public static IServiceCollection AddSKTelemetry(
        this IServiceCollection services,
        IConfiguration config)
    {
        var serviceName = config["OTEL_SERVICE_NAME"] ?? "sk-enterprise-app";
        var otlpEndpoint = config["OTEL_EXPORTER_OTLP_ENDPOINT"];

        services.AddOpenTelemetry()
            .ConfigureResource(r => r
                .AddService(serviceName)
                .AddAttributes(new Dictionary<string, object>
                {
                    ["deployment.environment"] = config["ASPNETCORE_ENVIRONMENT"] ?? "development",
                    ["service.version"] = typeof(Program).Assembly.GetName().Version?.ToString() ?? "unknown"
                }))
            .WithTracing(tracing => tracing
                .AddSource("SemanticKernel")
                .AddSource("KernelFunction")
                .AddHttpClientInstrumentation()
                .AddAspNetCoreInstrumentation()
                .AddEntityFrameworkCoreInstrumentation()
                .SetSampler(new TraceIdRatioBasedSampler(1.0)) // 100% in dev; tune for prod
                .AddOtlpExporter(o => o.Endpoint = new Uri(otlpEndpoint ?? "http://localhost:4317")))
            .WithMetrics(metrics => metrics
                .AddMeter("SemanticKernel")
                .AddMeter("KernelFunction")
                .AddRuntimeInstrumentation()
                .AddAspNetCoreInstrumentation()
                .AddOtlpExporter(o => o.Endpoint = new Uri(otlpEndpoint ?? "http://localhost:4317")))
            .WithLogging(logging => logging
                .AddOtlpExporter(o => o.Endpoint = new Uri(otlpEndpoint ?? "http://localhost:4317")));

        return services;
    }
}

Register it in Program.cs:

builder.Services.AddSKTelemetry(builder.Configuration);

Pitfall: The AddSource("SemanticKernel") line only captures activities if SK emits them. As of SK 1.19+, the kernel uses ActivitySource internally for function invocations and prompt rendering. Verify your version — earlier releases required manual instrumentation.

Function invocation filter: the telemetry backbone

FunctionInvocationFilter runs before and after every kernel function (native or semantic). This is where you capture latency, token counts, arguments, results, and errors — correlated via Activity.

// Telemetry/FunctionTelemetryFilter.cs
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel;
using System.Diagnostics;

public sealed class FunctionTelemetryFilter : IFunctionInvocationFilter
{
    private static readonly ActivitySource ActivitySource = new("KernelFunction");
    private readonly ILogger<FunctionTelemetryFilter> _logger;

    public FunctionTelemetryFilter(ILogger<FunctionTelemetryFilter> logger)
    {
        _logger = logger;
    }

    public async Task OnFunctionInvocationAsync(
        FunctionInvocationContext context,
        Func<FunctionInvocationContext, Task> next)
    {
        var functionName = context.Function.Name;
        var pluginName = context.Function.PluginName ?? "default";

        using var activity = ActivitySource.StartActivity(
            $"{pluginName}.{functionName}",
            ActivityKind.Internal,
            Activity.Current?.Context ?? default);

        // Enrich with structured attributes
        activity?.SetTag("sk.function.name", functionName);
        activity?.SetTag("sk.function.plugin", pluginName);
        activity?.SetTag("sk.function.is_semantic", context.Function.IsSemantic);

        // Log arguments (sanitize PII!)
        var argsJson = SanitizeArguments(context.Arguments);
        activity?.SetTag("sk.function.arguments", argsJson);
        _logger.LogInformation("Function invoked: {Plugin}.{Function} Args: {Args}",
            pluginName, functionName, argsJson);

        var stopwatch = Stopwatch.StartNew();
        Exception? exception = null;

        try
        {
            await next(context);
        }
        catch (Exception ex)
        {
            exception = ex;
            activity?.SetStatus(ActivityStatusCode.Error, ex.Message);
            activity?.RecordException(ex);
            _logger.LogError(ex, "Function failed: {Plugin}.{Function}", pluginName, functionName);
            throw;
        }
        finally
        {
            stopwatch.Stop();
            activity?.SetTag("sk.function.duration_ms", stopwatch.ElapsedMilliseconds);
            activity?.SetTag("sk.function.success", exception is null);

            if (context.Result is not null)
            {
                var resultJson = SanitizeResult(context.Result);
                activity?.SetTag("sk.function.result", resultJson);
                _logger.LogInformation("Function completed: {Plugin}.{Function} Duration: {Duration}ms Result: {Result}",
                    pluginName, functionName, stopwatch.ElapsedMilliseconds, resultJson);
            }
        }
    }

    private static string SanitizeArguments(KernelArguments args)
    {
        // Never log raw user input, API keys, or PII in production
        var dict = new Dictionary<string, object?>();
        foreach (var (key, value) in args)
        {
            if (IsSensitiveKey(key))
            {
                dict[key] = "[REDACTED]";
            }
            else
            {
                dict[key] = value?.ToString()?.Length > 1000
                    ? value.ToString()![..1000] + "...[TRUNCATED]"
                    : value?.ToString();
            }
        }
        return System.Text.Json.JsonSerializer.Serialize(dict);
    }

    private static string SanitizeResult(FunctionResult result)
    {
        var value = result.GetValue<object?>();
        if (value is string s && s.Length > 2000)
            return s[..2000] + "...[TRUNCATED]";
        return System.Text.Json.JsonSerializer.Serialize(value);
    }

    private static bool IsSensitiveKey(string key) => key.ContainsAny(
        "key", "secret", "password", "token", "authorization", "api", "credential");
}

Register the filter when building the kernel:

// KernelBuilderExtensions.cs
using Microsoft.Extensions.DependencyInjection;
using Microsoft.SemanticKernel;

public static class KernelBuilderExtensions
{
    public static IKernelBuilder AddTelemetryFilters(this IKernelBuilder builder)
    {
        builder.Services.AddSingleton<IFunctionInvocationFilter, FunctionTelemetryFilter>();
        // Prompt render filter below
        return builder;
    }
}

// Program.cs
var kernel = builder.Services.AddKernel()
    .AddTelemetryFilters()
    .AddOpenAIChatCompletion(modelId, apiKey) // or your provider
    .Build();

Tradeoff: This filter runs on every function invocation. In a planner-driven loop with 15+ function calls, you get 15+ activities. That’s correct for observability but increases trace volume. Sample in production (see sampler config above) or add a ShouldTrace predicate to the filter.

Prompt render filter: capturing what the model sees

IPromptRenderFilter lets you inspect the final rendered prompt before it hits the model. Critical for debugging prompt template issues, variable injection failures, and token estimation.

// Telemetry/PromptTelemetryFilter.cs
using Microsoft.Extensions.Logging;
using Microsoft.SemanticKernel;
using System.Diagnostics;

public sealed class PromptTelemetryFilter : IPromptRenderFilter
{
    private static readonly ActivitySource ActivitySource = new("SemanticKernel.Prompt");
    private readonly ILogger<PromptTelemetryFilter> _logger;

    public PromptTelemetryFilter(ILogger<PromptTelemetryFilter> logger)
    {
        _logger = logger;
    }

    public async Task OnPromptRenderAsync(
        PromptRenderContext context,
        Func<PromptRenderContext, Task> next)
    {
        using var activity = ActivitySource.StartActivity(
            "prompt.render",
            ActivityKind.Internal,
            Activity.Current?.Context ?? default);

        activity?.SetTag("sk.prompt.template", context.PromptTemplateConfig.Template);
        activity?.SetTag("sk.prompt.template_format", context.PromptTemplateConfig.TemplateFormat);

        await next(context);

        var renderedPrompt = context.RenderedPrompt;
        var tokenEstimate = EstimateTokens(renderedPrompt);

        activity?.SetTag("sk.prompt.rendered_length", renderedPrompt?.Length ?? 0);
        activity?.SetTag("sk.prompt.estimated_tokens", tokenEstimate);
        activity?.SetTag("sk.prompt.rendered", TruncateForTrace(renderedPrompt));

        _logger.LogDebug("Prompt rendered: {Length} chars, ~{Tokens} tokens",
            renderedPrompt?.Length ?? 0, tokenEstimate);
    }

    private static int EstimateTokens(string? text)
    {
        if (string.IsNullOrEmpty(text)) return 0;
        // Rough approximation: ~4 chars per token for English
        // Replace with tiktoken for accuracy if needed
        return text.Length / 4;
    }

    private static string? TruncateForTrace(string? text, int maxLength = 500)
    {
        if (string.IsNullOrEmpty(text)) return text;
        return text.Length > maxLength ? text[..maxLength] + "...[TRUNCATED]" : text;
    }
}

Register it alongside the function filter:

public static IKernelBuilder AddTelemetryFilters(this IKernelBuilder builder)
{
    builder.Services.AddSingleton<IFunctionInvocationFilter, FunctionTelemetryFilter>();
    builder.Services.AddSingleton<IPromptRenderFilter, PromptTelemetryFilter>();
    return builder;
}

Pitfall: PromptRenderFilter fires for every prompt render, including internal planner prompts. In a ReAct loop, you’ll see the planner’s prompt, then each function’s prompt, then the final synthesis prompt. Correlate them via Activity.Current.TraceId — they share the same trace.

Token usage and cost tracking

SK doesn’t expose token counts natively for all providers. You need to hook the HTTP layer or use provider-specific response metadata. For OpenAI-compatible endpoints, the response includes usage.

// Telemetry/TokenUsageHandler.cs
using System.Diagnostics;
using System.Net.Http;
using System.Text.Json;

public sealed class TokenUsageHandler : DelegatingHandler
{
    private static readonly ActivitySource ActivitySource = new("SemanticKernel.TokenUsage");
    private readonly ILogger<TokenUsageHandler> _logger;

    public TokenUsageHandler(ILogger<TokenUsageHandler> logger)
    {
        _logger = logger;
    }

    protected override async Task<HttpResponseMessage> SendAsync(
        HttpRequestMessage request,
        CancellationToken cancellationToken)
    {
        var response = await base.SendAsync(request, cancellationToken);

        if (request.RequestUri?.PathAndQuery.Contains("/chat/completions") == true
            && response.IsSuccessStatusCode)
        {
            var content = await response.Content.ReadAsStringAsync(cancellationToken);
            try
            {
                using var doc = JsonDocument.Parse(content);
                if (doc.RootElement.TryGetProperty("usage", out var usage))
                {
                    var promptTokens = usage.GetProperty("prompt_tokens").GetInt32();
                    var completionTokens = usage.GetProperty("completion_tokens").GetInt32();
                    var totalTokens = usage.GetProperty("total_tokens").GetInt32();

                    Activity.Current?.SetTag("sk.usage.prompt_tokens", promptTokens);
                    Activity.Current?.SetTag("sk.usage.completion_tokens", completionTokens);
                    Activity.Current?.SetTag("sk.usage.total_tokens", totalTokens);

                    // Emit metric for cost tracking
                    var meter = new Meter("SemanticKernel");
                    var counter = meter.CreateCounter<long>("sk.tokens.total");
                    counter.Add(totalTokens, new KeyValuePair<string, object?>("type", "total"));
                    counter.Add(promptTokens, new KeyValuePair<string, object?>("type", "prompt"));
                    counter.Add(completionTokens, new KeyValuePair<string, object?>("type", "completion"));

                    _logger.LogInformation("Token usage: Prompt={Prompt} Completion={Completion} Total={Total}",
                        promptTokens, completionTokens, totalTokens);
                }
            }
            catch (JsonException)
            {
                // Non-JSON response or missing usage — ignore
            }
        }

        return response;
    }
}

Register the handler in your HttpClient pipeline for the SK chat completion service:

// Program.cs
builder.Services.AddHttpClient("OpenAI", client =>
{
    client.BaseAddress = new Uri("https://api.openai.com/v1/");
    client.DefaultRequestHeaders.Authorization =
        new AuthenticationHeaderValue("Bearer", apiKey);
})
.AddHttpMessageHandler<TokenUsageHandler>();

// Then pass the named client to SK
builder.Services.AddKernel()
    .AddOpenAIChatCompletion(modelId, "OpenAI"); // Uses named HttpClient

Note: If you route through a gateway like n4n.ai that forwards provider usage fields unchanged, this handler works identically. The gateway honors cache-control hints and returns standard OpenAI-compatible responses.

Correlation IDs and distributed tracing

Every incoming HTTP request should carry a traceparent header (W3C TraceContext). ASP.NET Core does this automatically with AddAspNetCoreInstrumentation(). Propagate it to downstream calls — SK’s HttpClient instrumentation handles this if you use the instrumented client.

For non-HTTP entry points (message queues, scheduled jobs), start the trace manually:

// Background job example
using var activity = ActivitySource.StartActivity("sk.batch.process", ActivityKind.Server);
activity?.SetTag("messaging.system", "rabbitmq");
activity?.SetTag("messaging.message_id", message.Id);

// All SK work inside this scope shares the trace
await kernel.InvokeAsync(plannerFunction, arguments);

Pitfall: If you create Kernel instances per request (not recommended), you lose the singleton filter registrations. Use a singleton Kernel or KernelFactory with scoped arguments via KernelArguments.

Common pitfalls and tradeoffs

Tradeoff: Structured logs vs. metrics vs. traces

• Logs: High cardinality, human-readable, expensive to store. Use for errors, warnings, and key business events.
• Metrics: Low cardinality, cheap, aggregatable. Use for token counts, latency histograms, error rates, function call frequencies.
• Traces: Request-scoped, causal relationships. Use for debugging latency, understanding call graphs, correlating planner → function → model.

Emit all three from the same filters. The FunctionTelemetryFilter above does exactly that: structured log entry, span with attributes, and metric counters.

Production checklist

Before deploying SK telemetry to production:

1. Verify PII redaction — Run a test request with known sensitive data; confirm logs show [REDACTED].
2. Load test trace volume — Simulate 100 RPS; check collector CPU/memory and backend ingestion rate.
3. Validate correlation — Send a request with traceparent; verify the full chain appears in your trace UI (Jaeger, Tempo, Honeycomb).
4. Alert on token anomalies — Set alerts for sk.tokens.total rate spikes (indicates runaway loops or prompt injection).
5. Document sampling strategy — Record your sampler config and retention policies for compliance.
6. Test fallback paths — If your provider fails over (e.g., via gateway), confirm usage fields still propagate.

What’s next

This foundation handles the observability layer. The control layer — routing directives, fallback policies, budget enforcement — lives upstream. If you’re routing across 200+ models with automatic fallback and per-token metering, the same correlation IDs and token metrics flow through the gateway into your traces. The instrumentation doesn’t change; the routing logic just adds sk.routing.model, sk.routing.provider, and sk.routing.fallback_reason attributes.

Start with the filters above. Add the DelegatingHandler for token capture. Wire OpenTelemetry to your backend. Then iterate on alerts and dashboards. You’ll catch the next planner loop regression before users notice.