diff --git a/integrationTests/diagnostics/package.json b/integrationTests/diagnostics/package.json new file mode 100644 index 0000000000..0face40966 --- /dev/null +++ b/integrationTests/diagnostics/package.json @@ -0,0 +1,14 @@ +{ + "description": "graphql-js tracing channels should publish on node:diagnostics_channel", + "private": true, + "type": "module", + "engines": { + "node": ">=22.0.0" + }, + "scripts": { + "test": "node test.js" + }, + "dependencies": { + "graphql": "file:../graphql.tgz" + } +} diff --git a/integrationTests/diagnostics/test.js b/integrationTests/diagnostics/test.js new file mode 100644 index 0000000000..8a0e5cebb4 --- /dev/null +++ b/integrationTests/diagnostics/test.js @@ -0,0 +1,288 @@ +// TracingChannel is marked experimental in Node's docs but is shipped on +// every runtime graphql-js supports. This test exercises it directly. +/* eslint-disable n/no-unsupported-features/node-builtins */ + +import assert from 'node:assert/strict'; +import { AsyncLocalStorage } from 'node:async_hooks'; +import dc from 'node:diagnostics_channel'; + +import { buildSchema, execute, parse, subscribe, validate } from 'graphql'; + +function runParseCases() { + // graphql:parse - synchronous. + { + const events = []; + const handler = { + start: (msg) => events.push({ kind: 'start', source: msg.source }), + end: (msg) => events.push({ kind: 'end', source: msg.source }), + asyncStart: (msg) => + events.push({ kind: 'asyncStart', source: msg.source }), + asyncEnd: (msg) => events.push({ kind: 'asyncEnd', source: msg.source }), + error: (msg) => + events.push({ kind: 'error', source: msg.source, error: msg.error }), + }; + + const channel = dc.tracingChannel('graphql:parse'); + channel.subscribe(handler); + + try { + const doc = parse('{ field }'); + assert.equal(doc.kind, 'Document'); + assert.deepEqual( + events.map((e) => e.kind), + ['start', 'end'], + ); + assert.equal(events[0].source, '{ field }'); + assert.equal(events[1].source, '{ field }'); + } finally { + channel.unsubscribe(handler); + } + } + + // graphql:parse - error path fires start, error, end. + { + const events = []; + const handler = { + start: (msg) => events.push({ kind: 'start', source: msg.source }), + end: (msg) => events.push({ kind: 'end', source: msg.source }), + error: (msg) => + events.push({ kind: 'error', source: msg.source, error: msg.error }), + }; + + const channel = dc.tracingChannel('graphql:parse'); + channel.subscribe(handler); + + try { + assert.throws(() => parse('{ ')); + assert.deepEqual( + events.map((e) => e.kind), + ['start', 'error', 'end'], + ); + assert.ok(events[1].error instanceof Error); + } finally { + channel.unsubscribe(handler); + } + } +} + +function runValidateCase() { + const schema = buildSchema(`type Query { field: String }`); + const doc = parse('{ field }'); + + const events = []; + const handler = { + start: (msg) => + events.push({ + kind: 'start', + schema: msg.schema, + document: msg.document, + }), + end: () => events.push({ kind: 'end' }), + error: (msg) => events.push({ kind: 'error', error: msg.error }), + }; + + const channel = dc.tracingChannel('graphql:validate'); + channel.subscribe(handler); + + try { + const errors = validate(schema, doc); + assert.deepEqual(errors, []); + assert.deepEqual( + events.map((e) => e.kind), + ['start', 'end'], + ); + assert.equal(events[0].schema, schema); + assert.equal(events[0].document, doc); + } finally { + channel.unsubscribe(handler); + } +} + +function runExecuteCase() { + const schema = buildSchema(`type Query { hello: String }`); + const document = parse('query Greeting { hello }'); + + const events = []; + const handler = { + start: (msg) => + events.push({ + kind: 'start', + operationType: msg.operationType, + operationName: msg.operationName, + document: msg.document, + schema: msg.schema, + }), + end: () => events.push({ kind: 'end' }), + asyncStart: () => events.push({ kind: 'asyncStart' }), + asyncEnd: () => events.push({ kind: 'asyncEnd' }), + error: (msg) => events.push({ kind: 'error', error: msg.error }), + }; + + const channel = dc.tracingChannel('graphql:execute'); + channel.subscribe(handler); + + try { + const result = execute({ + schema, + document, + rootValue: { hello: 'world' }, + }); + assert.equal(result.data.hello, 'world'); + assert.deepEqual( + events.map((e) => e.kind), + ['start', 'end'], + ); + assert.equal(events[0].operationType, 'query'); + assert.equal(events[0].operationName, 'Greeting'); + assert.equal(events[0].document, document); + assert.equal(events[0].schema, schema); + } finally { + channel.unsubscribe(handler); + } +} + +async function runSubscribeCase() { + async function* ticks() { + yield { tick: 'one' }; + } + + const schema = buildSchema(` + type Query { dummy: String } + type Subscription { tick: String } + `); + // buildSchema doesn't attach a subscribe resolver to fields; inject one. + schema.getSubscriptionType().getFields().tick.subscribe = () => ticks(); + + const document = parse('subscription Tick { tick }'); + + const events = []; + const handler = { + start: (msg) => + events.push({ + kind: 'start', + operationType: msg.operationType, + operationName: msg.operationName, + }), + end: () => events.push({ kind: 'end' }), + asyncStart: () => events.push({ kind: 'asyncStart' }), + asyncEnd: () => events.push({ kind: 'asyncEnd' }), + error: (msg) => events.push({ kind: 'error', error: msg.error }), + }; + + const channel = dc.tracingChannel('graphql:subscribe'); + channel.subscribe(handler); + + try { + const result = subscribe({ schema, document }); + const stream = typeof result.then === 'function' ? await result : result; + if (stream[Symbol.asyncIterator]) { + await stream.return?.(); + } + // Subscription setup is synchronous here; start/end fire, no async tail. + assert.deepEqual( + events.map((e) => e.kind), + ['start', 'end'], + ); + assert.equal(events[0].operationType, 'subscription'); + assert.equal(events[0].operationName, 'Tick'); + } finally { + channel.unsubscribe(handler); + } +} + +function runResolveCase() { + const schema = buildSchema( + `type Query { hello: String nested: Nested } type Nested { leaf: String }`, + ); + const document = parse('{ hello nested { leaf } }'); + + const events = []; + const handler = { + start: (msg) => + events.push({ + kind: 'start', + fieldName: msg.fieldName, + parentType: msg.parentType, + fieldType: msg.fieldType, + fieldPath: msg.fieldPath, + isTrivialResolver: msg.isTrivialResolver, + }), + end: () => events.push({ kind: 'end' }), + asyncStart: () => events.push({ kind: 'asyncStart' }), + asyncEnd: () => events.push({ kind: 'asyncEnd' }), + error: (msg) => events.push({ kind: 'error', error: msg.error }), + }; + + const channel = dc.tracingChannel('graphql:resolve'); + channel.subscribe(handler); + + try { + const rootValue = { hello: () => 'world', nested: { leaf: 'leaf-value' } }; + execute({ schema, document, rootValue }); + + const starts = events.filter((e) => e.kind === 'start'); + const paths = starts.map((e) => e.fieldPath); + assert.deepEqual(paths, ['hello', 'nested', 'nested.leaf']); + + const hello = starts.find((e) => e.fieldName === 'hello'); + assert.equal(hello.parentType, 'Query'); + assert.equal(hello.fieldType, 'String'); + // buildSchema never attaches field.resolve; all fields report as trivial. + assert.equal(hello.isTrivialResolver, true); + } finally { + channel.unsubscribe(handler); + } +} + +function runNoSubscriberCase() { + const doc = parse('{ field }'); + assert.equal(doc.kind, 'Document'); +} + +async function runAlsPropagationCase() { + // A subscriber that binds a store on the `start` sub-channel should be able + // to read it in every lifecycle handler (start, end, asyncStart, asyncEnd). + // This is what APMs use to parent child spans to the current operation + // without threading state through the ctx object. + const als = new AsyncLocalStorage(); + const channel = dc.tracingChannel('graphql:execute'); + channel.start.bindStore(als, (ctx) => ({ operationName: ctx.operationName })); + + const seen = {}; + const handler = { + start: () => (seen.start = als.getStore()), + end: () => (seen.end = als.getStore()), + asyncStart: () => (seen.asyncStart = als.getStore()), + asyncEnd: () => (seen.asyncEnd = als.getStore()), + }; + channel.subscribe(handler); + + try { + const schema = buildSchema(`type Query { slow: String }`); + const document = parse('query Slow { slow }'); + const rootValue = { slow: () => Promise.resolve('done') }; + + await execute({ schema, document, rootValue }); + + assert.deepEqual(seen.start, { operationName: 'Slow' }); + assert.deepEqual(seen.end, { operationName: 'Slow' }); + assert.deepEqual(seen.asyncStart, { operationName: 'Slow' }); + assert.deepEqual(seen.asyncEnd, { operationName: 'Slow' }); + } finally { + channel.unsubscribe(handler); + channel.start.unbindStore(als); + } +} + +async function main() { + runParseCases(); + runValidateCase(); + runExecuteCase(); + await runSubscribeCase(); + runResolveCase(); + await runAlsPropagationCase(); + runNoSubscriberCase(); + console.log('diagnostics integration test passed'); +} + +main(); diff --git a/resources/integration-test.ts b/resources/integration-test.ts index 1eb240d5d5..0e584726b0 100644 --- a/resources/integration-test.ts +++ b/resources/integration-test.ts @@ -55,6 +55,9 @@ describe('Integration Tests', () => { testOnNodeProject('node'); testOnNodeProject('webpack'); + // Tracing channel tests + testOnNodeProject('diagnostics'); + // Conditional export tests testOnNodeProject('conditions'); diff --git a/src/__testUtils__/diagnosticsTestUtils.ts b/src/__testUtils__/diagnosticsTestUtils.ts new file mode 100644 index 0000000000..e7b92edab9 --- /dev/null +++ b/src/__testUtils__/diagnosticsTestUtils.ts @@ -0,0 +1,54 @@ +/* eslint-disable n/no-unsupported-features/node-builtins, import/no-nodejs-modules */ +import dc from 'node:diagnostics_channel'; + +import type { MinimalTracingChannel } from '../diagnostics.js'; + +export interface CollectedEvent { + kind: 'start' | 'end' | 'asyncStart' | 'asyncEnd' | 'error'; + ctx: { [key: string]: unknown }; +} + +/** + * Subscribe to every lifecycle sub-channel on a TracingChannel and collect + * events in order. Returns the event buffer plus an unsubscribe hook. + */ +export function collectEvents(channel: MinimalTracingChannel): { + events: Array; + unsubscribe: () => void; +} { + const events: Array = []; + const handler = { + start: (ctx: unknown) => + events.push({ kind: 'start', ctx: ctx as { [key: string]: unknown } }), + end: (ctx: unknown) => + events.push({ kind: 'end', ctx: ctx as { [key: string]: unknown } }), + asyncStart: (ctx: unknown) => + events.push({ + kind: 'asyncStart', + ctx: ctx as { [key: string]: unknown }, + }), + asyncEnd: (ctx: unknown) => + events.push({ + kind: 'asyncEnd', + ctx: ctx as { [key: string]: unknown }, + }), + error: (ctx: unknown) => + events.push({ kind: 'error', ctx: ctx as { [key: string]: unknown } }), + }; + (channel as unknown as dc.TracingChannel).subscribe(handler); + return { + events, + unsubscribe() { + (channel as unknown as dc.TracingChannel).unsubscribe(handler); + }, + }; +} + +/** + * Resolve a graphql tracing channel by name on the real + * `node:diagnostics_channel`. graphql-js publishes on the same channels at + * module load. + */ +export function getTracingChannel(name: string): MinimalTracingChannel { + return dc.tracingChannel(name) as unknown as MinimalTracingChannel; +} diff --git a/src/__tests__/diagnostics-test.ts b/src/__tests__/diagnostics-test.ts new file mode 100644 index 0000000000..c7c97b0c60 --- /dev/null +++ b/src/__tests__/diagnostics-test.ts @@ -0,0 +1,43 @@ +/* eslint-disable import/no-nodejs-modules */ +import dc from 'node:diagnostics_channel'; + +import { expect } from 'chai'; +import { describe, it } from 'mocha'; + +import { invariant } from '../jsutils/invariant.js'; + +import { + executeChannel, + parseChannel, + resolveChannel, + subscribeChannel, + validateChannel, +} from '../diagnostics.js'; + +describe('diagnostics', () => { + it('auto-registers the five graphql tracing channels', () => { + invariant(parseChannel !== undefined); + invariant(validateChannel !== undefined); + invariant(executeChannel !== undefined); + invariant(subscribeChannel !== undefined); + invariant(resolveChannel !== undefined); + + // Node's `tracingChannel(name)` returns a fresh wrapper per call but + // the underlying sub-channels are cached by name, so compare those. + expect(parseChannel.start).to.equal( + dc.channel('tracing:graphql:parse:start'), + ); + expect(validateChannel.start).to.equal( + dc.channel('tracing:graphql:validate:start'), + ); + expect(executeChannel.start).to.equal( + dc.channel('tracing:graphql:execute:start'), + ); + expect(subscribeChannel.start).to.equal( + dc.channel('tracing:graphql:subscribe:start'), + ); + expect(resolveChannel.start).to.equal( + dc.channel('tracing:graphql:resolve:start'), + ); + }); +}); diff --git a/src/diagnostics.ts b/src/diagnostics.ts new file mode 100644 index 0000000000..de11c758cf --- /dev/null +++ b/src/diagnostics.ts @@ -0,0 +1,186 @@ +/* eslint-disable no-undef, import/no-nodejs-modules, n/global-require, @typescript-eslint/no-require-imports */ +/** + * TracingChannel integration. + * + * graphql-js publishes lifecycle events on a set of named tracing channels + * that APM tools can subscribe to in order to observe parse, validate, + * execute, subscribe, and resolver behavior. At module load time graphql-js + * resolves `node:diagnostics_channel` itself so APMs do not need to interact + * with the graphql API to enable tracing. On runtimes that do not expose + * `node:diagnostics_channel` (e.g., browsers) the load silently no-ops and + * emission sites short-circuit. + */ + +import { isPromise } from './jsutils/isPromise.js'; + +/** + * Structural subset of `DiagnosticsChannel` sufficient for publishing and + * subscriber gating. `node:diagnostics_channel`'s `Channel` satisfies this. + * + * @internal + */ +export interface MinimalChannel { + readonly hasSubscribers: boolean; + publish: (message: unknown) => void; + runStores: ( + context: ContextType, + fn: (this: ContextType, ...args: Array) => T, + thisArg?: unknown, + ...args: Array + ) => T; +} + +/** + * Structural subset of Node's `TracingChannel`. The `node:diagnostics_channel` + * `TracingChannel` satisfies this by duck typing, so graphql-js does not need + * a dependency on `@types/node` or on the runtime itself. + * + * @internal + */ +export interface MinimalTracingChannel { + readonly hasSubscribers: boolean; + readonly start: MinimalChannel; + readonly end: MinimalChannel; + readonly asyncStart: MinimalChannel; + readonly asyncEnd: MinimalChannel; + readonly error: MinimalChannel; + + traceSync: ( + fn: (...args: Array) => T, + ctx: object, + thisArg?: unknown, + ...args: Array + ) => T; +} + +interface DiagnosticsChannelModule { + tracingChannel: (name: string) => MinimalTracingChannel; +} + +/** + * The collection of tracing channels graphql-js emits on. APMs subscribe to + * these by name on their own `node:diagnostics_channel` import; both paths + * land on the same channel instance because `tracingChannel(name)` is cached + * by name. + */ +export interface GraphQLChannels { + execute: MinimalTracingChannel; + parse: MinimalTracingChannel; + validate: MinimalTracingChannel; + resolve: MinimalTracingChannel; + subscribe: MinimalTracingChannel; +} + +function resolveDiagnosticsChannel(): DiagnosticsChannelModule | undefined { + let dc: DiagnosticsChannelModule | undefined; + try { + if ( + typeof process !== 'undefined' && + typeof (process as { getBuiltinModule?: (id: string) => unknown }) + .getBuiltinModule === 'function' + ) { + dc = ( + process as { + getBuiltinModule: (id: string) => DiagnosticsChannelModule; + } + ).getBuiltinModule('node:diagnostics_channel'); + } + /* c8 ignore next 6 */ + if (!dc && typeof require === 'function') { + // CJS fallback for runtimes that lack `process.getBuiltinModule` + // (e.g. Node 20.0 - 20.15). ESM builds skip this branch because + // `require` is undeclared there. + dc = require('node:diagnostics_channel') as DiagnosticsChannelModule; + } + /* c8 ignore next 3 */ + } catch { + // diagnostics_channel not available on this runtime; tracing is a no-op. + } + return dc; +} + +const dc = resolveDiagnosticsChannel(); + +/** + * Per-channel handles, resolved once at module load. `undefined` when + * `node:diagnostics_channel` isn't available. Emission sites read these + * directly to keep the no-subscriber fast path to a single property access + * plus a `hasSubscribers` check (no function calls, no closures). + * + * @internal + */ +export const parseChannel: MinimalTracingChannel | undefined = + dc?.tracingChannel('graphql:parse'); +/** @internal */ +export const validateChannel: MinimalTracingChannel | undefined = + dc?.tracingChannel('graphql:validate'); +/** @internal */ +export const executeChannel: MinimalTracingChannel | undefined = + dc?.tracingChannel('graphql:execute'); +/** @internal */ +export const subscribeChannel: MinimalTracingChannel | undefined = + dc?.tracingChannel('graphql:subscribe'); +/** @internal */ +export const resolveChannel: MinimalTracingChannel | undefined = + dc?.tracingChannel('graphql:resolve'); + +/** + * Publish a mixed sync-or-promise operation through `channel`. Caller has + * already verified that a subscriber is attached. + * + * @internal + */ +export function traceMixed( + channel: MinimalTracingChannel, + ctxInput: object, + fn: () => T | Promise, +): T | Promise { + const ctx = ctxInput as { error?: unknown; result?: unknown }; + + return channel.start.runStores(ctx, () => { + let result: T | Promise; + try { + result = fn(); + } catch (err) { + ctx.error = err; + channel.error.publish(ctx); + channel.end.publish(ctx); + throw err; + } + + if (!isPromise(result)) { + ctx.result = result; + channel.end.publish(ctx); + return result; + } + + channel.end.publish(ctx); + channel.asyncStart.publish(ctx); + + return result + .then( + (value) => { + ctx.result = value; + return value; + }, + (err: unknown) => { + ctx.error = err; + channel.error.publish(ctx); + throw err; + }, + ) + .finally(() => { + channel.asyncEnd.publish(ctx); + }); + }); +} + +/** + * Check if a channel is defined and has subscribers. + */ +export function shouldTrace( + channel: MinimalTracingChannel | undefined, +): channel is MinimalTracingChannel { + // eslint-disable-next-line @typescript-eslint/no-unnecessary-boolean-literal-compare + return channel !== undefined && channel.hasSubscribers !== false; +} diff --git a/src/execution/Executor.ts b/src/execution/Executor.ts index 15d88de6b9..08c4d27c1a 100644 --- a/src/execution/Executor.ts +++ b/src/execution/Executor.ts @@ -44,6 +44,8 @@ import { } from '../type/definition.js'; import type { GraphQLSchema } from '../type/schema.js'; +import { resolveChannel, shouldTrace, traceMixed } from '../diagnostics.js'; + import { AbortedGraphQLExecutionError } from './AbortedGraphQLExecutionError.js'; import { withCancellation } from './cancellablePromise.js'; import type { @@ -613,7 +615,13 @@ export class Executor< // The resolve function's optional third argument is a context value that // is provided to every resolve function within an execution. It is commonly // used to represent an authenticated user, or request-specific caches. - const result = resolveFn(source, args, contextValue, info); + const result = shouldTrace(resolveChannel) + ? traceMixed( + resolveChannel, + buildResolveCtx(info, args, fieldDef.resolve === undefined), + () => resolveFn(source, args, contextValue, info), + ) + : resolveFn(source, args, contextValue, info); if (isPromiseLike(result)) { return this.completePromisedValue( @@ -1396,3 +1404,29 @@ export class Executor< function toNodes(fieldDetailsList: FieldDetailsList): ReadonlyArray { return fieldDetailsList.map((fieldDetails) => fieldDetails.node); } + +/** + * Build a graphql:resolve channel context for a single field invocation. + * + * `fieldPath` is exposed as a lazy getter because serializing the response + * path is O(depth) and APMs that depth-filter or skip trivial resolvers + * often never read it. `args` is passed through by reference. + */ +function buildResolveCtx( + info: GraphQLResolveInfo, + args: { readonly [argument: string]: unknown }, + isTrivialResolver: boolean, +): object { + let cachedFieldPath: string | undefined; + return { + fieldName: info.fieldName, + parentType: info.parentType.name, + fieldType: String(info.returnType), + args, + isTrivialResolver, + get fieldPath() { + cachedFieldPath ??= pathToArray(info.path).join('.'); + return cachedFieldPath; + }, + }; +} diff --git a/src/execution/__tests__/execute-diagnostics-test.ts b/src/execution/__tests__/execute-diagnostics-test.ts new file mode 100644 index 0000000000..896189c7a3 --- /dev/null +++ b/src/execution/__tests__/execute-diagnostics-test.ts @@ -0,0 +1,144 @@ +import { expect } from 'chai'; +import { afterEach, describe, it } from 'mocha'; + +import { + collectEvents, + getTracingChannel, +} from '../../__testUtils__/diagnosticsTestUtils.js'; + +import { parse } from '../../language/parser.js'; + +import { buildSchema } from '../../utilities/buildASTSchema.js'; + +import type { ExecutionArgs } from '../execute.js'; +import { + execute, + executeIgnoringIncremental, + executeSubscriptionEvent, + executeSync, + validateExecutionArgs, +} from '../execute.js'; + +const schema = buildSchema(` + type Query { + sync: String + async: String + } +`); + +const rootValue = { + sync: () => 'hello', + async: () => Promise.resolve('hello-async'), +}; + +const executeChannel = getTracingChannel('graphql:execute'); + +describe('execute diagnostics channel', () => { + let active: ReturnType | undefined; + + afterEach(() => { + active?.unsubscribe(); + active = undefined; + }); + + it('emits start and end around a synchronous execute', () => { + active = collectEvents(executeChannel); + + const document = parse('query Q { sync }'); + const result = execute({ schema, document, rootValue }); + + expect(result).to.deep.equal({ data: { sync: 'hello' } }); + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + expect(active.events[0].ctx.operationType).to.equal('query'); + expect(active.events[0].ctx.operationName).to.equal('Q'); + expect(active.events[0].ctx.document).to.equal(document); + expect(active.events[0].ctx.schema).to.equal(schema); + }); + + it('emits start, end, and async lifecycle when execute returns a promise', async () => { + active = collectEvents(executeChannel); + + const document = parse('query { async }'); + const result = await execute({ schema, document, rootValue }); + + expect(result).to.deep.equal({ data: { async: 'hello-async' } }); + expect(active.events.map((e) => e.kind)).to.deep.equal([ + 'start', + 'end', + 'asyncStart', + 'asyncEnd', + ]); + }); + + it('emits once for executeSync via experimentalExecuteIncrementally', () => { + active = collectEvents(executeChannel); + + const document = parse('{ sync }'); + executeSync({ schema, document, rootValue }); + + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + }); + + it('emits start and end around executeIgnoringIncremental', () => { + active = collectEvents(executeChannel); + + const document = parse('query Q { sync }'); + // eslint-disable-next-line @typescript-eslint/no-floating-promises + executeIgnoringIncremental({ schema, document, rootValue }); + + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + expect(active.events[0].ctx.operationName).to.equal('Q'); + }); + + it('emits start, error, and end when execute throws synchronously', () => { + active = collectEvents(executeChannel); + + const schemaWithDefer = buildSchema(` + directive @defer on FIELD + type Query { sync: String } + `); + const document = parse('{ sync }'); + expect(() => + execute({ schema: schemaWithDefer, document, rootValue }), + ).to.throw(); + + expect(active.events.map((e) => e.kind)).to.deep.equal([ + 'start', + 'error', + 'end', + ]); + }); + + it('emits for each executeSubscriptionEvent call with resolved operation ctx', () => { + const args: ExecutionArgs = { + schema, + document: parse('query Q { sync }'), + rootValue, + }; + const validated = validateExecutionArgs(args); + if (!('schema' in validated)) { + throw new Error('unexpected validation failure'); + } + + active = collectEvents(executeChannel); + + // eslint-disable-next-line @typescript-eslint/no-floating-promises + executeSubscriptionEvent(validated); + // eslint-disable-next-line @typescript-eslint/no-floating-promises + executeSubscriptionEvent(validated); + + const starts = active.events.filter((e) => e.kind === 'start'); + expect(starts.length).to.equal(2); + for (const ev of starts) { + expect(ev.ctx.operationType).to.equal('query'); + expect(ev.ctx.operationName).to.equal('Q'); + expect(ev.ctx.schema).to.equal(schema); + } + }); + + it('does nothing when no subscribers are attached', () => { + const document = parse('{ sync }'); + const result = execute({ schema, document, rootValue }); + expect(result).to.deep.equal({ data: { sync: 'hello' } }); + }); +}); diff --git a/src/execution/__tests__/resolve-diagnostics-test.ts b/src/execution/__tests__/resolve-diagnostics-test.ts new file mode 100644 index 0000000000..fc6a53cc17 --- /dev/null +++ b/src/execution/__tests__/resolve-diagnostics-test.ts @@ -0,0 +1,191 @@ +import { expect } from 'chai'; +import { afterEach, describe, it } from 'mocha'; + +import { + collectEvents, + getTracingChannel, +} from '../../__testUtils__/diagnosticsTestUtils.js'; + +import { isPromise } from '../../jsutils/isPromise.js'; + +import { parse } from '../../language/parser.js'; + +import { GraphQLObjectType } from '../../type/definition.js'; +import { GraphQLString } from '../../type/scalars.js'; +import { GraphQLSchema } from '../../type/schema.js'; + +import { buildSchema } from '../../utilities/buildASTSchema.js'; + +import { execute } from '../execute.js'; + +const schema = buildSchema(` + type Query { + sync: String + async: String + fail: String + asyncFail: String + plain: String + nested: Nested + } + type Nested { + leaf: String + } +`); + +const rootValue = { + sync: () => 'hello', + async: () => Promise.resolve('hello-async'), + fail: () => { + throw new Error('boom'); + }, + asyncFail: () => Promise.reject(new Error('async-boom')), + // no `plain` resolver, default property-access is used. + plain: 'plain-value', + nested: { leaf: 'leaf-value' }, +}; + +const resolveChannel = getTracingChannel('graphql:resolve'); + +describe('resolve diagnostics channel', () => { + let active: ReturnType | undefined; + + afterEach(() => { + active?.unsubscribe(); + active = undefined; + }); + + it('emits start and end around a synchronous resolver', () => { + active = collectEvents(resolveChannel); + + const result = execute({ schema, document: parse('{ sync }'), rootValue }); + if (isPromise(result)) { + throw new Error('expected sync'); + } + + const starts = active.events.filter((e) => e.kind === 'start'); + expect(starts.length).to.equal(1); + expect(starts[0].ctx.fieldName).to.equal('sync'); + expect(starts[0].ctx.parentType).to.equal('Query'); + expect(starts[0].ctx.fieldType).to.equal('String'); + expect(starts[0].ctx.fieldPath).to.equal('sync'); + + const kinds = active.events.map((e) => e.kind); + expect(kinds).to.deep.equal(['start', 'end']); + }); + + it('emits the full async lifecycle when a resolver returns a promise', async () => { + active = collectEvents(resolveChannel); + + const result = execute({ schema, document: parse('{ async }'), rootValue }); + await result; + + const kinds = active.events.map((e) => e.kind); + expect(kinds).to.deep.equal(['start', 'end', 'asyncStart', 'asyncEnd']); + }); + + it('emits start, error, end when a sync resolver throws', () => { + active = collectEvents(resolveChannel); + + // eslint-disable-next-line @typescript-eslint/no-floating-promises + execute({ schema, document: parse('{ fail }'), rootValue }); + + const kinds = active.events.map((e) => e.kind); + expect(kinds).to.deep.equal(['start', 'error', 'end']); + }); + + it('emits full async lifecycle with error when a resolver rejects', async () => { + active = collectEvents(resolveChannel); + + await execute({ + schema, + document: parse('{ asyncFail }'), + rootValue, + }); + + const kinds = active.events.map((e) => e.kind); + expect(kinds).to.deep.equal([ + 'start', + 'end', + 'asyncStart', + 'error', + 'asyncEnd', + ]); + const errorEvent = active.events.find((e) => e.kind === 'error'); + expect((errorEvent?.ctx as { error?: Error }).error?.message).to.equal( + 'async-boom', + ); + }); + + it('reports isTrivialResolver based on field.resolve presence', () => { + const trivialSchema = new GraphQLSchema({ + query: new GraphQLObjectType({ + name: 'Query', + fields: { + trivial: { type: GraphQLString }, + custom: { + type: GraphQLString, + resolve: () => 'explicit', + }, + }, + }), + }); + + active = collectEvents(resolveChannel); + + // eslint-disable-next-line @typescript-eslint/no-floating-promises + execute({ + schema: trivialSchema, + document: parse('{ trivial custom }'), + rootValue: { trivial: 'value' }, + }); + + const starts = active.events.filter((e) => e.kind === 'start'); + const byField = new Map( + starts.map((e) => [e.ctx.fieldName, e.ctx.isTrivialResolver]), + ); + expect(byField.get('trivial')).to.equal(true); + expect(byField.get('custom')).to.equal(false); + }); + + it('serializes fieldPath lazily, joining path keys with dots', () => { + active = collectEvents(resolveChannel); + + // eslint-disable-next-line @typescript-eslint/no-floating-promises + execute({ + schema, + document: parse('{ nested { leaf } }'), + rootValue, + }); + + const starts = active.events.filter((e) => e.kind === 'start'); + const paths = starts.map((e) => e.ctx.fieldPath); + expect(paths).to.deep.equal(['nested', 'nested.leaf']); + }); + + it('fires once per field, not per schema walk', () => { + active = collectEvents(resolveChannel); + + // eslint-disable-next-line @typescript-eslint/no-floating-promises + execute({ + schema, + document: parse('{ sync plain nested { leaf } }'), + rootValue, + }); + + const starts = active.events.filter((e) => e.kind === 'start'); + const endsSync = active.events.filter((e) => e.kind === 'end'); + expect(starts.length).to.equal(4); // sync, plain, nested, nested.leaf + expect(endsSync.length).to.equal(4); + }); + + it('does nothing when no subscribers are attached', () => { + const result = execute({ + schema, + document: parse('{ sync }'), + rootValue, + }); + if (isPromise(result)) { + throw new Error('expected sync'); + } + }); +}); diff --git a/src/execution/__tests__/subscribe-diagnostics-test.ts b/src/execution/__tests__/subscribe-diagnostics-test.ts new file mode 100644 index 0000000000..7ea78d6836 --- /dev/null +++ b/src/execution/__tests__/subscribe-diagnostics-test.ts @@ -0,0 +1,123 @@ +import { expect } from 'chai'; +import { afterEach, describe, it } from 'mocha'; + +import { + collectEvents, + getTracingChannel, +} from '../../__testUtils__/diagnosticsTestUtils.js'; + +import { isPromise } from '../../jsutils/isPromise.js'; + +import { parse } from '../../language/parser.js'; + +import { GraphQLObjectType } from '../../type/definition.js'; +import { GraphQLString } from '../../type/scalars.js'; +import { GraphQLSchema } from '../../type/schema.js'; + +import { subscribe } from '../execute.js'; + +function buildSubscriptionSchema( + subscribeFn: () => AsyncIterable<{ tick: string }>, +): GraphQLSchema { + return new GraphQLSchema({ + query: new GraphQLObjectType({ + name: 'Query', + fields: { dummy: { type: GraphQLString } }, + }), + subscription: new GraphQLObjectType({ + name: 'Subscription', + fields: { + tick: { + type: GraphQLString, + subscribe: subscribeFn, + }, + }, + }), + }); +} + +async function* twoTicks(): AsyncIterable<{ tick: string }> { + await Promise.resolve(); + yield { tick: 'one' }; + yield { tick: 'two' }; +} + +const subscribeChannel = getTracingChannel('graphql:subscribe'); + +describe('subscribe diagnostics channel', () => { + let active: ReturnType | undefined; + + afterEach(() => { + active?.unsubscribe(); + active = undefined; + }); + + it('emits start and end for a synchronous subscription setup', async () => { + active = collectEvents(subscribeChannel); + + const schema = buildSubscriptionSchema(twoTicks); + const document = parse('subscription S { tick }'); + + const result = subscribe({ schema, document }); + const resolved = isPromise(result) ? await result : result; + if (!(Symbol.asyncIterator in resolved)) { + throw new Error('Expected an async iterator'); + } + await resolved.return?.(); + + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + expect(active.events[0].ctx.operationType).to.equal('subscription'); + expect(active.events[0].ctx.operationName).to.equal('S'); + expect(active.events[0].ctx.document).to.equal(document); + expect(active.events[0].ctx.schema).to.equal(schema); + }); + + it('emits the full async lifecycle when subscribe resolver returns a promise', async () => { + active = collectEvents(subscribeChannel); + + const asyncResolver = (): Promise> => + Promise.resolve(twoTicks()); + const schema = buildSubscriptionSchema( + asyncResolver as unknown as () => AsyncIterable<{ tick: string }>, + ); + const document = parse('subscription { tick }'); + + const result = subscribe({ schema, document }); + const resolved = isPromise(result) ? await result : result; + if (!(Symbol.asyncIterator in resolved)) { + throw new Error('Expected an async iterator'); + } + await resolved.return?.(); + + expect(active.events.map((e) => e.kind)).to.deep.equal([ + 'start', + 'end', + 'asyncStart', + 'asyncEnd', + ]); + }); + + it('emits only start and end for a synchronous validation failure', () => { + active = collectEvents(subscribeChannel); + + const schema = buildSubscriptionSchema(twoTicks); + // Invalid: no operation. + const document = parse('fragment F on Subscription { tick }'); + + // eslint-disable-next-line @typescript-eslint/no-floating-promises + subscribe({ schema, document }); + + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + }); + + it('does nothing when no subscribers are attached', async () => { + const schema = buildSubscriptionSchema(twoTicks); + const document = parse('subscription { tick }'); + + const result = subscribe({ schema, document }); + const resolved = isPromise(result) ? await result : result; + if (Symbol.asyncIterator in resolved) { + await resolved.return?.(); + } + }); +}); diff --git a/src/execution/execute.ts b/src/execution/execute.ts index 4d71b30e85..9ce5bb54b0 100644 --- a/src/execution/execute.ts +++ b/src/execution/execute.ts @@ -32,6 +32,14 @@ import type { import { assertValidSchema } from '../type/index.js'; import type { GraphQLSchema } from '../type/schema.js'; +import { getOperationAST } from '../utilities/getOperationAST.js'; + +import { + executeChannel, + subscribeChannel, + traceMixed, +} from '../diagnostics.js'; + import { cancellablePromise } from './cancellablePromise.js'; import type { FieldDetailsList, FragmentDetails } from './collectFields.js'; import { collectFields } from './collectFields.js'; @@ -49,6 +57,51 @@ import { getArgumentValues, getVariableValues } from './values.js'; const UNEXPECTED_EXPERIMENTAL_DIRECTIVES = 'The provided schema unexpectedly contains experimental directives (@defer or @stream). These directives may only be utilized if experimental execution features are explicitly enabled.'; +/** + * Build a graphql:execute channel context from raw ExecutionArgs. Defers + * resolution of the operation AST to a lazy getter so the cost of walking + * the document is only paid if a subscriber reads it. + */ +function buildExecuteCtxFromArgs(args: ExecutionArgs): object { + let operation: OperationDefinitionNode | null | undefined; + const resolveOperation = (): OperationDefinitionNode | null | undefined => { + if (operation === undefined) { + operation = getOperationAST(args.document, args.operationName); + } + return operation; + }; + return { + document: args.document, + schema: args.schema, + variableValues: args.variableValues, + get operationName() { + return args.operationName ?? resolveOperation()?.name?.value; + }, + get operationType() { + return resolveOperation()?.operation; + }, + }; +} + +/** + * Build a graphql:execute channel context from ValidatedExecutionArgs. + * Used by executeSubscriptionEvent, where the operation has already been + * resolved during argument validation. The original document is not + * available at this point, only the resolved operation; subscribers that + * need the document should read it from the graphql:subscribe context. + */ +function buildExecuteCtxFromValidatedArgs( + args: ValidatedExecutionArgs, +): object { + return { + operation: args.operation, + schema: args.schema, + variableValues: args.variableValues, + operationName: args.operation.name?.value, + operationType: args.operation.operation, + }; +} + /** * Implements the "Executing requests" section of the GraphQL specification. * @@ -66,6 +119,15 @@ const UNEXPECTED_EXPERIMENTAL_DIRECTIVES = * delivery. */ export function execute(args: ExecutionArgs): PromiseOrValue { + if (!executeChannel?.hasSubscribers) { + return executeImpl(args); + } + return traceMixed(executeChannel, buildExecuteCtxFromArgs(args), () => + executeImpl(args), + ); +} + +function executeImpl(args: ExecutionArgs): PromiseOrValue { if (args.schema.getDirective('defer') || args.schema.getDirective('stream')) { throw new Error(UNEXPECTED_EXPERIMENTAL_DIRECTIVES); } @@ -95,8 +157,19 @@ export function execute(args: ExecutionArgs): PromiseOrValue { export function experimentalExecuteIncrementally( args: ExecutionArgs, ): PromiseOrValue { - // If a valid execution context cannot be created due to incorrect arguments, - // a "Response" with only errors is returned. + if (!executeChannel?.hasSubscribers) { + return experimentalExecuteIncrementallyImpl(args); + } + return traceMixed(executeChannel, buildExecuteCtxFromArgs(args), () => + experimentalExecuteIncrementallyImpl(args), + ); +} + +function experimentalExecuteIncrementallyImpl( + args: ExecutionArgs, +): PromiseOrValue { + // If a valid execution context cannot be created due to incorrect + // arguments, a "Response" with only errors is returned. const validatedExecutionArgs = validateExecutionArgs(args); // Return early errors if execution context failed. @@ -112,8 +185,19 @@ export function experimentalExecuteIncrementally( export function executeIgnoringIncremental( args: ExecutionArgs, ): PromiseOrValue { - // If a valid execution context cannot be created due to incorrect arguments, - // a "Response" with only errors is returned. + if (!executeChannel?.hasSubscribers) { + return executeIgnoringIncrementalImpl(args); + } + return traceMixed(executeChannel, buildExecuteCtxFromArgs(args), () => + executeIgnoringIncrementalImpl(args), + ); +} + +function executeIgnoringIncrementalImpl( + args: ExecutionArgs, +): PromiseOrValue { + // If a valid execution context cannot be created due to incorrect + // arguments, a "Response" with only errors is returned. const validatedExecutionArgs = validateExecutionArgs(args); // Return early errors if execution context failed. @@ -184,7 +268,14 @@ export function executeSync(args: ExecutionArgs): ExecutionResult { export function executeSubscriptionEvent( validatedExecutionArgs: ValidatedExecutionArgs, ): PromiseOrValue { - return executeQueryOrMutationOrSubscriptionEvent(validatedExecutionArgs); + if (!executeChannel?.hasSubscribers) { + return executeQueryOrMutationOrSubscriptionEvent(validatedExecutionArgs); + } + return traceMixed( + executeChannel, + buildExecuteCtxFromValidatedArgs(validatedExecutionArgs), + () => executeQueryOrMutationOrSubscriptionEvent(validatedExecutionArgs), + ); } /** @@ -218,8 +309,21 @@ export function subscribe( ): PromiseOrValue< AsyncGenerator | ExecutionResult > { - // If a valid execution context cannot be created due to incorrect arguments, - // a "Response" with only errors is returned. + if (!subscribeChannel?.hasSubscribers) { + return subscribeImpl(args); + } + return traceMixed(subscribeChannel, buildExecuteCtxFromArgs(args), () => + subscribeImpl(args), + ); +} + +function subscribeImpl( + args: ExecutionArgs, +): PromiseOrValue< + AsyncGenerator | ExecutionResult +> { + // If a valid execution context cannot be created due to incorrect + // arguments, a "Response" with only errors is returned. const validatedExecutionArgs = validateExecutionArgs(args); // Return early errors if execution context failed. diff --git a/src/index.ts b/src/index.ts index f19286f4bb..15564f2b50 100644 --- a/src/index.ts +++ b/src/index.ts @@ -32,6 +32,11 @@ export { version, versionInfo } from './version.js'; // Enable development mode for additional checks. export { enableDevMode, isDevModeEnabled } from './devMode.js'; +// Tracing channel types for subscribers that want to strongly type the +// `graphql:*` channel context payloads. Channels are auto-registered on +// `node:diagnostics_channel` at module load. +export type { GraphQLChannels } from './diagnostics.js'; + // The primary entry point into fulfilling a GraphQL request. export type { GraphQLArgs } from './graphql.js'; export { graphql, graphqlSync } from './graphql.js'; diff --git a/src/language/__tests__/parser-diagnostics-test.ts b/src/language/__tests__/parser-diagnostics-test.ts new file mode 100644 index 0000000000..49535dacc7 --- /dev/null +++ b/src/language/__tests__/parser-diagnostics-test.ts @@ -0,0 +1,46 @@ +import { expect } from 'chai'; +import { afterEach, describe, it } from 'mocha'; + +import { + collectEvents, + getTracingChannel, +} from '../../__testUtils__/diagnosticsTestUtils.js'; + +import { parse } from '../parser.js'; + +const parseChannel = getTracingChannel('graphql:parse'); + +describe('parse diagnostics channel', () => { + let active: ReturnType | undefined; + + afterEach(() => { + active?.unsubscribe(); + active = undefined; + }); + + it('emits start and end around a successful parse', () => { + active = collectEvents(parseChannel); + + const doc = parse('{ field }'); + + expect(doc.kind).to.equal('Document'); + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + expect(active.events[0].ctx.source).to.equal('{ field }'); + expect(active.events[1].ctx.source).to.equal('{ field }'); + }); + + it('emits start, error, and end when the parser throws', () => { + active = collectEvents(parseChannel); + + expect(() => parse('{ ')).to.throw(); + + const kinds = active.events.map((e) => e.kind); + expect(kinds).to.deep.equal(['start', 'error', 'end']); + expect(active.events[1].ctx.error).to.be.instanceOf(Error); + }); + + it('does nothing when no subscribers are attached', () => { + const doc = parse('{ field }'); + expect(doc.kind).to.equal('Document'); + }); +}); diff --git a/src/language/parser.ts b/src/language/parser.ts index d9e6dd8ba2..9439a32b9f 100644 --- a/src/language/parser.ts +++ b/src/language/parser.ts @@ -3,6 +3,8 @@ import type { Maybe } from '../jsutils/Maybe.js'; import type { GraphQLError } from '../error/GraphQLError.js'; import { syntaxError } from '../error/syntaxError.js'; +import { parseChannel, shouldTrace } from '../diagnostics.js'; + import type { ArgumentCoordinateNode, ArgumentNode, @@ -131,6 +133,15 @@ export interface ParseOptions { export function parse( source: string | Source, options?: ParseOptions, +): DocumentNode { + return shouldTrace(parseChannel) + ? parseChannel.traceSync(() => parseImpl(source, options), { source }) + : parseImpl(source, options); +} + +function parseImpl( + source: string | Source, + options: ParseOptions | undefined, ): DocumentNode { const parser = new Parser(source, options); const document = parser.parseDocument(); diff --git a/src/validation/__tests__/validate-diagnostics-test.ts b/src/validation/__tests__/validate-diagnostics-test.ts new file mode 100644 index 0000000000..85c308ab6a --- /dev/null +++ b/src/validation/__tests__/validate-diagnostics-test.ts @@ -0,0 +1,71 @@ +import { expect } from 'chai'; +import { afterEach, describe, it } from 'mocha'; + +import { + collectEvents, + getTracingChannel, +} from '../../__testUtils__/diagnosticsTestUtils.js'; + +import { parse } from '../../language/parser.js'; + +import { buildSchema } from '../../utilities/buildASTSchema.js'; + +import { validate } from '../validate.js'; + +const schema = buildSchema(` + type Query { + field: String + } +`); + +const validateChannel = getTracingChannel('graphql:validate'); + +describe('validate diagnostics channel', () => { + let active: ReturnType | undefined; + + afterEach(() => { + active?.unsubscribe(); + active = undefined; + }); + + it('emits start and end around a successful validate', () => { + active = collectEvents(validateChannel); + + const doc = parse('{ field }'); + const errors = validate(schema, doc); + + expect(errors).to.deep.equal([]); + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + expect(active.events[0].ctx.schema).to.equal(schema); + expect(active.events[0].ctx.document).to.equal(doc); + }); + + it('emits start and end for a document with validation errors', () => { + active = collectEvents(validateChannel); + + const doc = parse('{ missingField }'); + const errors = validate(schema, doc); + + expect(errors).to.have.length.greaterThan(0); + // Validation errors are collected, not thrown, so we still see start/end. + expect(active.events.map((e) => e.kind)).to.deep.equal(['start', 'end']); + }); + + it('emits start, error, and end when validate throws on an invalid schema', () => { + active = collectEvents(validateChannel); + + expect(() => validate({} as typeof schema, parse('{ field }'))).to.throw(); + + expect(active.events.map((e) => e.kind)).to.deep.equal([ + 'start', + 'error', + 'end', + ]); + expect(active.events[1].ctx.error).to.be.instanceOf(Error); + }); + + it('does nothing when no subscribers are attached', () => { + const errors = validate(schema, parse('{ field }')); + expect(errors).to.deep.equal([]); + }); +}); diff --git a/src/validation/validate.ts b/src/validation/validate.ts index 544f8bc3aa..48b79a4b72 100644 --- a/src/validation/validate.ts +++ b/src/validation/validate.ts @@ -12,6 +12,8 @@ import { assertValidSchema } from '../type/validate.js'; import { TypeInfo, visitWithTypeInfo } from '../utilities/TypeInfo.js'; +import { shouldTrace, validateChannel } from '../diagnostics.js'; + import { specifiedRules, specifiedSDLRules } from './specifiedRules.js'; import type { SDLValidationRule, ValidationRule } from './ValidationContext.js'; import { @@ -60,6 +62,20 @@ export function validate( documentAST: DocumentNode, rules: ReadonlyArray = specifiedRules, options?: ValidationOptions, +): ReadonlyArray { + return shouldTrace(validateChannel) + ? validateChannel.traceSync( + () => validateImpl(schema, documentAST, rules, options), + { schema, document: documentAST }, + ) + : validateImpl(schema, documentAST, rules, options); +} + +function validateImpl( + schema: GraphQLSchema, + documentAST: DocumentNode, + rules: ReadonlyArray, + options: ValidationOptions | undefined, ): ReadonlyArray { const maxErrors = options?.maxErrors ?? 100; const hideSuggestions = options?.hideSuggestions ?? false; @@ -82,8 +98,8 @@ export function validate( hideSuggestions, ); - // This uses a specialized visitor which runs multiple visitors in parallel, - // while maintaining the visitor skip and break API. + // This uses a specialized visitor which runs multiple visitors in + // parallel, while maintaining the visitor skip and break API. const visitor = visitInParallel(rules.map((rule) => rule(context))); // Visit the whole document with each instance of all provided rules.