Hot Chocolate allows us to create custom diagnostic event listeners, tapping into internal instrumentation events and further processing them. This abstraction allows us to use the logging or tracing infrastructure that we want to use. Further, we provide a default implementation for open telemetry.

Diagnostic events

Currently, we can implement diagnostic event listeners for the following event types:

• Server events
• Execution events
• DataLoader events

We will learn more about creating diagnostic event listeners for these event types in their respective sections.

After creating a diagnostic event listener for any event type, we can register it by calling AddDiagnosticEventListener on the IRequestExecutorBuilder, specifying the newly developed diagnostic event listener as the generic type parameter.

public class Startup
{
    public void ConfigureServices(IServiceCollection services)
    {
        services
            .AddGraphQLServer()
            .AddDiagnosticEventListener<MyExecutionEventListener>();
    }
}

If we need to access services within our event handlers, we can inject them using the constructor. Please note that injected services are effectively singleton since the diagnostic event listener is instantiated once.

public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
    private readonly ILogger<MyExecutionEventListener> _logger;

    public MyExecutionEventListener(ILogger<MyExecutionEventListener> logger)
        => _logger = logger;

    public override void RequestError(IRequestContext context,
        Exception exception)
    {
        _logger.LogError(exception, "A request error occurred!");
    }
}

Scopes

Most diagnostic event handlers have a return type of void, but some return an IDisposable. These event handlers enclose a specific operation, sort of like a scope. This scope is instantiated at the start of the operation and disposed of at the end of the operation.

We can simply create a class implementing IDisposable to create a scope.

public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
    private readonly ILogger<MyExecutionEventListener> _logger;

    public MyExecutionEventListener(ILogger<MyExecutionEventListener> logger)
        => _logger = logger;

    // this is invoked at the start of the `ExecuteRequest` operation
    public override IDisposable ExecuteRequest(IRequestContext context)
    {
        var start = DateTime.UtcNow;

        return new RequestScope(start, _logger);
    }
}

public class RequestScope : IDisposable
{
    private readonly ILogger _logger;
    private readonly DateTime _start;

    public RequestScope(DateTime start, ILogger logger)
    {
        _start = start;
        _logger = logger;
    }

    // this is invoked at the end of the `ExecuteRequest` operation
    public void Dispose()
    {
        var end = DateTime.UtcNow;
        var elapsed = end - _start;

        _logger.LogInformation("Request finished after {Ticks} ticks",
            elapsed.Ticks);
    }
}

If we are not interested in the scope of a specific diagnostic event handler, we can return an EmptyScope. Returning an empty scope where we do not need to track a span will reduce the performance impact of triggering your event.

public override IDisposable ExecuteRequest(IRequestContext context)
{
    _logger.LogInformation("Request execution started!");

    return EmptyScope;
}

Server Events

We can instrument server events of the Hot Chocolate transport layer by creating a class inheriting from ServerDiagnosticEventListener.

public class MyServerEventListener : ServerDiagnosticEventListener
{
    public override IDisposable ExecuteHttpRequest(IRequestContext context)
    {
        // Omitted code for brevity
    }
}

Execution Events

We can hook into execution events of the Hot Chocolate execution engine by creating a class inheriting from ExecutionDiagnosticEventListener.

public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
    public override IDisposable ExecuteRequest(IRequestContext context)
    {
        // Omitted code for brevity
    }
}

The following methods can be overridden.

(*): The ResolveFieldValue event is not invoked per default, as it would be too much overhead to execute the event for each resolver used within a query. We have to override the EnableResolveFieldValue property for the execution engine to invoke the event handler.

public class MyExecutionEventListener : ExecutionDiagnosticEventListener
{
    public override bool EnableResolveFieldValue => true;

    public override IDisposable ResolveFieldValue(IMiddlewareContext context)
    {
        // Omitted code for brevity
    }
}

DataLoader Events

We can hook into DataLoader events by creating a class inheriting from DataLoaderDiagnosticEventListener.

public class MyDataLoaderEventListener : DataLoaderDiagnosticEventListener
{
    public override IDisposable ExecuteBatch<TKey>(IDataLoader dataLoader,
        IReadOnlyList<TKey> keys)
    {
        // Omitted code for brevity
    }
}

The following methods can be overridden.

OpenTelemetry

OpenTelemetry is an open-source project and unified standard for service instrumentation or a way of measuring performance. Sponsored by the Cloud Native Computing Foundation (CNCF), it replaces OpenTracing and OpenCensus. The goal is to standardize how you collect and send telemetry data to a backend platform.

Hot Chocolate has implemented an OpenTelemetry integration, and you can easily opt into it instead of building a custom tracing integration.

Setup

To get started, add the HotChocolate.Diagnostics package to your project.

dotnet add package HotChocolate.Diagnostics

Next, head over to your Program.cs and add AddInstrumentation to your GraphQL configuration.

builder.Services
    .AddGraphQLServer()
    .AddQueryType<Query>()
    .AddInstrumentation();

Now, we need to add OpenTelemetry to our project, and in the example here, we will use it with a Jaeger exporter.

Let's first add the needed packages:

dotnet add package OpenTelemetry.Extensions.Hosting --version 1.0.0-rc8
dotnet add package OpenTelemetry.Instrumentation.AspNetCore --version 1.0.0-rc8
dotnet add package OpenTelemetry.Instrumentation.Http --version 1.0.0-rc8
dotnet add package OpenTelemetry.Exporter.Jaeger --version 1.1.0

Now add the OpenTelemetry setup code to the Program.cs:

builder.Logging.AddOpenTelemetry(
    b =>
    {
        b.IncludeFormattedMessage = true;
        b.IncludeScopes = true;
        b.ParseStateValues = true;
        b.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Demo"));
    });

builder.Services
    .AddOpenTelemetryTracing()
    .WithTracing(
      b =>
      {
          b.AddHttpClientInstrumentation();
          b.AddAspNetCoreInstrumentation();
          b.AddHotChocolateInstrumentation();
          b.AddJaegerExporter();
      });

AddHotChocolateInstrumentation will register the Hot Chocolate instrumentation events with OpenTelemetry.

Your Program.cs should look like the following:

using OpenTelemetry.Resources;
using OpenTelemetry.Trace;

var builder = WebApplication.CreateBuilder(args);

builder.Services
    .AddGraphQLServer()
    .AddQueryType<Query>()
    .AddInstrumentation();

builder.Logging.AddOpenTelemetry(
    b => b.SetResourceBuilder(ResourceBuilder.CreateDefault().AddService("Demo")));

builder.Services
    .AddOpenTelemetryTracing()
    .WithTracing(
      b =>
      {
          b.AddHttpClientInstrumentation();
          b.AddAspNetCoreInstrumentation();
          b.AddHotChocolateInstrumentation();
          b.AddJaegerExporter();
      });

var app = builder.Build();
app.MapGraphQL();
app.Run();

When running GraphQL requests, you can now inspect in Jaeger how the request performed and look into the various parts of the execution telemetry.

Options

By default, we have not instrumented all of our execution events. You can drill deeper into the execution telemetry by adding more instrumentation scopes.

builder.Services
    .AddGraphQLServer()
    .AddQueryType<Query>()
    .AddInstrumentation(o =>
    {
        o.Scopes = ActivityScopes.All;
    });

Beware, adding more instrumentation scopes is not free and will add more performance overhead.

Further, if you work with elastic and you want to give your root activity a name that is associated with the executed operation, you can quickly just tell the instrumentation to do just that for you.

builder.Services
    .AddGraphQLServer()
    .AddQueryType<Query>()
    .AddInstrumentation(o =>
    {
        o.RenameRootActivity = true;
    });

Enriching Activities

You can inherit from ActivityEnricher and override the enrich method for an Activity to add custom data or remove default data.

public class CustomActivityEnricher : ActivityEnricher
{
    public CustomActivityEnricher(
        ObjectPool<StringBuilder> stringBuilderPoolPool,
        InstrumentationOptions options)
        : base(stringBuilderPoolPool, options)
    {
    }

    public override void EnrichResolveFieldValue(IMiddlewareContext context, Activity activity)
    {
        base.EnrichResolveFieldValue(context, activity);

        activity.SetTag("custom", "data");
    }
}

Register the custom activity enricher as a singleton:

builder.Services.AddSingleton<ActivityEnricher, CustomActivityEnricher>();

Apollo Tracing

Apollo Tracing is a performance tracing specification for GraphQL servers. It works by returning tracing information about the current request alongside the computed data. While it is not part of the GraphQL specification itself, there is a common agreement in the GraphQL community that all GraphQL servers should support it.

Example

{
  book(id: 1) {
    name
    author
  }
}

The above request would result in the below response if Apollo Tracing is enabled.

{
  "data": {
    "book": {
      "name": "C# in Depth",
      "author": "Jon Skeet"
    }
  },
  "extensions": {
    "tracing": {
      "version": 1,
      "startTime": "2021-09-25T15:31:41.6515774Z",
      "endTime": "2021-09-25T15:31:43.1602255Z",
      "duration": 1508648100,
      "parsing": { "startOffset": 13335, "duration": 781 },
      "validation": { "startOffset": 17012, "duration": 323681 },
      "execution": {
        "resolvers": [
          {
            "path": ["book"],
            "parentType": "Query",
            "fieldName": "book",
            "returnType": "Book",
            "startOffset": 587048,
            "duration": 1004748344
          },
          {
            "path": ["book", "author"],
            "parentType": "Book",
            "fieldName": "author",
            "returnType": "String",
            "startOffset": 1005854823,
            "duration": 500265020
          }
        ]
      }
    }
  }
}

Enabling Apollo Tracing

Apollo Tracing needs to be explicitly enabled by calling AddApolloTracing on the IRequestExecutorBuilder.

public class Startup
{
    public void ConfigureServices(IServiceCollection services)
    {
        services
            .AddGraphQLServer()
            .AddApolloTracing();
    }
}

Further, we can specify a TracingPreference. Per default, it is TracingPreference.OnDemand.

services
    .AddGraphQLServer()
    .AddApolloTracing(TracingPreference.Always);

There are three possible options for the TracingPreference.

On Demand

When Apollo Tracing is added using the TracingPreference.OnDemand, we are required to pass one of the following HTTP headers with our query request in order to enable tracing for this specific request.

• GraphQL-Tracing=1
• X-Apollo-Tracing=1

When using curl this could look like the following.

curl -X POST -H 'GraphQL-Tracing: 1' -H 'Content-Type: application/json' \
    -d '{"query":"{\n  book(id: 1) {\n    name\n    author\n  }\n}\n"}' \
    'http://localhost:5000/graphql'