Help tracing nested resolvers

[2snEM6]

@pothos/tracing-sentry seems to have a hard time setting up tracing when nested resolvers are involved.

Let's say I have the following query:

query TestQuery {
  info {
    id
    name
  }
}

And Pothos builder is configured to trace all resolvers:

tracing: {
    default: (config) => true,
    wrap: (resolver, options) => traceResolver(resolver, options),
},

And traceResolver is setup this way:

const traceResolver = createSentryWrapper({
  includeArgs: true,
  includeSource: true,
});

Each span created on each resolver execution (id, name) should be nested under info, but instead they're not nested and id and name spans are at the same flat level as their parent info under the transaction root.

I modified createSentryWrapper to make use of Sentry.runWithAsyncContext that uses AsyncLocalStorage to prevent context leaks across async executions. This partially fixes nesting for DB and outgoing http spans created automatically by Sentry instrumentation. However nested resolver spans remain flat. See:

See:

This is my updated implementation of createSentryWrapper:

export function createSentryWrapper<T = unknown>(
  options?: SentryWrapperOptions<T>,
) {
  return <Context extends object = object>(
      resolver: GraphQLFieldResolver<unknown, Context, Record<string, unknown>>,
      fieldOptions: T,
      tracingOptions?: SentryWrapperOptions<T>,
    ): GraphQLFieldResolver<unknown, Context, Record<string, unknown>> =>
    (source, args, ctx, info) => {
      return Sentry.runWithAsyncContext(
        () => {
          const scope = Sentry.getCurrentHub().getScope();
          const transaction = scope.getTransaction();

          if (!transaction) {
            return resolver(source, args, ctx, info);
          }
          // 1. Identify the parent span:
          // This checks the context if there's an active span for the current GraphQL request.
          const parentSpan = scope.getSpan() || transaction;

          const tags = {
            [AttributeNames.FIELD_NAME]: info.fieldName,
            [AttributeNames.FIELD_PATH]: pathToString(info),
            [AttributeNames.FIELD_TYPE]: info.returnType.toString(),
          };

          const data: Record<string, unknown> = {};

          if (tracingOptions?.includeArgs ?? options?.includeArgs) {
            data[AttributeNames.FIELD_ARGS] = args;
          }

          if (tracingOptions?.includeSource ?? options?.includeSource) {
            if (info.fieldNodes?.[0]) {
              data[AttributeNames.SOURCE] = print(info.fieldNodes[0]);
            }
          }
          const span = parentSpan.startChild({
            op: 'graphql.resolve',
            description: info.fieldName,
            tags,
            data,
          }) as Span;

          scope?.setSpan(span);

          tracingOptions?.onSpan?.(span, fieldOptions, source, args, ctx, info);
          options?.onSpan?.(span, fieldOptions, source, args, ctx, info);

          return runFunction(
            () => resolver(source, args, ctx, info),
            () => {
              scope?.setSpan(parentSpan);
              span.finish();
            },
          );
        },
        {
          reuseExisting: false,
        },
      );
    };
}

I am using graphql-yoga and the Envelope Sentry plugin which starts a transaction on each GraphQL execution.

Thank you

[hayes]

The tracing plugin has helper to manage connecting parent spans. You can see example usage in the open telemetry plugin: https://github.com/hayes/pothos/blob/main/packages/tracing-opentelemetry/src/index.ts#L32

[2snEM6]

Thank you! I ended up doing something like this

export function createSentryWrapper<T = unknown>(
  options?: SentryWrapperOptions<T>,
) {
  return <Context extends object = object>(
      resolver: GraphQLFieldResolver<unknown, Context, Record<string, unknown>>,
      fieldOptions: T,
      tracingOptions?: SentryWrapperOptions<T>,
    ): GraphQLFieldResolver<unknown, Context, Record<string, unknown>> =>
    (source, args, ctx, info) => {
      return Sentry.runWithAsyncContext(
        () => {
          const scope = Sentry.getCurrentHub().getScope();
          const transaction = scope.getTransaction();

          if (!transaction) {
            return resolver(source, args, ctx, info);
          }

          const span = createSpanWithParent<Sentry.Span>(
            ctx,
            info,
            (path, parentSpan) => {
              const computedParentSpan =
                parentSpan || scope.getSpan() || transaction;

              const tags = {
                [AttributeNames.FIELD_NAME]: info.fieldName,
                [AttributeNames.FIELD_PATH]: path,
                [AttributeNames.FIELD_TYPE]: info.returnType.toString(),
              };

              const data: Record<string, unknown> = {};

              if (tracingOptions?.includeArgs ?? options?.includeArgs) {
                data[AttributeNames.FIELD_ARGS] = args;
              }

              if (tracingOptions?.includeSource ?? options?.includeSource) {
                if (info.fieldNodes?.[0]) {
                  data[AttributeNames.SOURCE] = print(info.fieldNodes[0]);
                }
              }

              const childSpan = computedParentSpan.startChild({
                op: 'graphql.resolve',
                description: info.fieldName,
                tags,
                data,
              });

              scope?.setSpan(childSpan);

              return childSpan;
            },
          );

          tracingOptions?.onSpan?.(span, fieldOptions, source, args, ctx, info);
          options?.onSpan?.(span, fieldOptions, source, args, ctx, info);

          return runFunction(
            () => resolver(source, args, ctx, info),
            (err: unknown) => {
              if (err && !isOriginalGraphQLError(err)) {
                if (
                  (err instanceof ApiError && !err.isUserError) ||
                  !(err instanceof ApiError)
                ) {
                  const code = extractErrorCode(err as unknown);

                  const errorInfo = {
                    code,
                    operationName: info.operation.name?.value,
                    query: info.operation.loc?.source.body,
                    variableValues: info.variableValues,
                  };

                  Sentry.withScope((errScope) => {
                    attachInfoToScope(errScope, errorInfo);
                    Sentry.captureException(err);
                  });
                }
              }
              span.finish();
            },
          );
        },
        {
          reuseExisting: false,
        },
      );
    };
}

Not sure if this bit: const computedParentSpan = parentSpan || scope.getSpan() || transaction; is accurate, but it seems to work!

[2snEM6]

Something I noticed is that it's better to capture errors here than in the operation root resolver, this way Sentry highlights which resolver is faulty. So, I ended up moving the error capturing logic from the graphql-yoga setup logic to here. I wrap all resolvers

[hayes]

makes sense. I would be careful about wrapping all resolvers if you are sensitive to performance, this will add a lot of overhead to your requests. I think for a lot of applications this doesn't really matter, but be aware this can get expensive under heavy loads.

[2snEM6]

Thank you! On our case we measured performance and it didn't really make any difference, but I will keep this in mind for the future. Before this I wanted to only wrap fields that had resolver functions defined explicitly, but for whatever reason even if i don't define the resolver function for a field, it's still there. Do you know why?

[2snEM6]

In this piece of code basically: