diff --git a/.changeset/@graphql-hive_gateway-runtime-642-dependencies.md b/.changeset/@graphql-hive_gateway-runtime-642-dependencies.md new file mode 100644 index 000000000..f8a04b275 --- /dev/null +++ b/.changeset/@graphql-hive_gateway-runtime-642-dependencies.md @@ -0,0 +1,7 @@ +--- +'@graphql-hive/gateway-runtime': patch +--- + +dependencies updates: + +- Added dependency [`@graphql-hive/logger-json@workspace:^` ↗︎](https://www.npmjs.com/package/@graphql-hive/logger-json/v/workspace:^) (to `dependencies`) diff --git a/.changeset/big-waves-prove.md b/.changeset/big-waves-prove.md new file mode 100644 index 000000000..1b9d47535 --- /dev/null +++ b/.changeset/big-waves-prove.md @@ -0,0 +1,15 @@ +--- +'@graphql-mesh/transport-http-callback': patch +'@graphql-mesh/plugin-opentelemetry': patch +'@graphql-mesh/fusion-runtime': patch +'@graphql-mesh/transport-ws': patch +'@graphql-hive/importer': patch +'@graphql-hive/gateway': patch +'@graphql-hive/gateway-runtime': patch +'@graphql-hive/logger-json': patch +--- + +New JSON-based logger + +By default, it prints pretty still to the console unless NODE_ENV is production. +For JSON output, set the `LOG_FORMAT` environment variable to `json`. \ No newline at end of file diff --git a/package.json b/package.json index 11e7b2f1b..30eabab10 100644 --- a/package.json +++ b/package.json @@ -60,6 +60,8 @@ "vitest": "^3.0.1" }, "resolutions": { + "@graphql-mesh/types": "0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a", + "@graphql-mesh/utils": "0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a", "@graphql-tools/delegate": "workspace:^", "@opentelemetry/exporter-trace-otlp-http": "patch:@opentelemetry/exporter-trace-otlp-http@npm%3A0.56.0#~/.yarn/patches/@opentelemetry-exporter-trace-otlp-http-npm-0.56.0-dddd282e41.patch", "@opentelemetry/otlp-exporter-base": "patch:@opentelemetry/otlp-exporter-base@npm%3A0.56.0#~/.yarn/patches/@opentelemetry-otlp-exporter-base-npm-0.56.0-ba3dc5f5c5.patch", diff --git a/packages/fusion-runtime/src/federation/supergraph.ts b/packages/fusion-runtime/src/federation/supergraph.ts index 8cd61802c..7589136dd 100644 --- a/packages/fusion-runtime/src/federation/supergraph.ts +++ b/packages/fusion-runtime/src/federation/supergraph.ts @@ -311,11 +311,13 @@ export const handleFederationSupergraph: UnifiedGraphHandler = function ({ if (context?.request) { requestId = requestIdByRequest.get(context.request); if (requestId) { - currentLogger = currentLogger?.child(requestId); + currentLogger = currentLogger?.child({ requestId }); } } if (sourceSubschema.name) { - currentLogger = currentLogger?.child(sourceSubschema.name); + currentLogger = currentLogger?.child({ + subgraph: sourceSubschema.name, + }); } for (const onDelegationPlan of onDelegationPlanHooks) { const onDelegationPlanDone = onDelegationPlan({ diff --git a/packages/fusion-runtime/src/utils.ts b/packages/fusion-runtime/src/utils.ts index 4c7db1c1c..e613ff348 100644 --- a/packages/fusion-runtime/src/utils.ts +++ b/packages/fusion-runtime/src/utils.ts @@ -102,7 +102,7 @@ function getTransportExecutor({ let logger = transportContext?.logger; if (logger) { if (subgraphName) { - logger = logger.child(subgraphName); + logger = logger.child({ subgraph: subgraphName }); } logger?.debug(`Loading transport "${kind}"`); } @@ -195,10 +195,10 @@ export function getOnSubgraphExecute({ executionRequest.context?.request, ); if (requestId) { - logger = logger.child(requestId); + logger = logger.child({ requestId }); } if (subgraphName) { - logger = logger.child(subgraphName); + logger = logger.child({ subgraph: subgraphName }); } logger.debug(`Initializing executor`); } @@ -287,7 +287,7 @@ export function wrapExecutorWithHooks({ let execReqLogger = transportContext?.logger; if (execReqLogger) { if (requestId) { - execReqLogger = execReqLogger.child(requestId); + execReqLogger = execReqLogger.child({ requestId }); } loggerForExecutionRequest.set(baseExecutionRequest, execReqLogger); } @@ -548,11 +548,11 @@ export function wrapMergedTypeResolver>( if (logger && context['request']) { requestId = requestIdByRequest.get(context['request']); if (requestId) { - logger = logger.child(requestId); + logger = logger.child({ requestId }); } } if (subschema.name) { - logger = logger?.child(subschema.name); + logger = logger?.child({ subgraph: subschema.name }); } let resolver = originalResolver as MergedTypeResolver; function setResolver(newResolver: MergedTypeResolver) { diff --git a/packages/fusion-runtime/tests/polling.test.ts b/packages/fusion-runtime/tests/polling.test.ts index b2d5a169a..931a8a2da 100644 --- a/packages/fusion-runtime/tests/polling.test.ts +++ b/packages/fusion-runtime/tests/polling.test.ts @@ -5,7 +5,7 @@ import { createDefaultExecutor, type DisposableExecutor, } from '@graphql-mesh/transport-common'; -import { DefaultLogger, makeDisposable } from '@graphql-mesh/utils'; +import { makeDisposable } from '@graphql-mesh/utils'; import { normalizedExecutor } from '@graphql-tools/executor'; import { createDeferred, @@ -17,6 +17,7 @@ import { DisposableSymbols } from '@whatwg-node/disposablestack'; import { ExecutionResult, GraphQLSchema, parse } from 'graphql'; import { createSchema } from 'graphql-yoga'; import { describe, expect, it, vi } from 'vitest'; +import { getDefaultLogger } from '../../runtime/src/getDefaultLogger'; import { UnifiedGraphManager } from '../src/unifiedGraphManager'; describe('Polling', () => { @@ -334,7 +335,7 @@ describe('Polling', () => { const unifiedGraphFetcher = vi.fn(() => { return graphDeferred ? graphDeferred.promise : unifiedGraph; }); - const logger = new DefaultLogger(); + const logger = getDefaultLogger(); await using executor = getExecutorForUnifiedGraph({ getUnifiedGraph: unifiedGraphFetcher, pollingInterval: 10_000, diff --git a/packages/gateway/src/bin.ts b/packages/gateway/src/bin.ts index 176940bef..5fce1be5e 100644 --- a/packages/gateway/src/bin.ts +++ b/packages/gateway/src/bin.ts @@ -3,7 +3,7 @@ import 'dotenv/config'; // inject dotenv options to process.env import module from 'node:module'; import type { InitializeData } from '@graphql-hive/importer/hooks'; -import { DefaultLogger } from '@graphql-mesh/utils'; +import { getDefaultLogger } from '../../runtime/src/getDefaultLogger'; import { enableModuleCachingIfPossible, handleNodeWarnings, run } from './cli'; // @inject-version globalThis.__VERSION__ here @@ -20,7 +20,7 @@ module.register('@graphql-hive/importer/hooks', { enableModuleCachingIfPossible(); handleNodeWarnings(); -const log = new DefaultLogger(); +const log = getDefaultLogger(); run({ log }).catch((err) => { log.error(err); diff --git a/packages/gateway/src/cli.ts b/packages/gateway/src/cli.ts index 80eb36930..fa3482202 100644 --- a/packages/gateway/src/cli.ts +++ b/packages/gateway/src/cli.ts @@ -7,13 +7,13 @@ import { InvalidArgumentError, Option, } from '@commander-js/extra-typings'; -import type { - GatewayConfigContext, - GatewayConfigProxy, - GatewayConfigSubgraph, - GatewayConfigSupergraph, - GatewayGraphOSReportingOptions, - GatewayHiveReportingOptions, +import { + type GatewayConfigContext, + type GatewayConfigProxy, + type GatewayConfigSubgraph, + type GatewayConfigSupergraph, + type GatewayGraphOSReportingOptions, + type GatewayHiveReportingOptions, } from '@graphql-hive/gateway-runtime'; import type UpstashRedisCache from '@graphql-mesh/cache-upstash-redis'; import type { JWTAuthPluginOptions } from '@graphql-mesh/plugin-jwt-auth'; @@ -26,8 +26,8 @@ import type { MeshPubSub, YamlConfig, } from '@graphql-mesh/types'; -import { DefaultLogger } from '@graphql-mesh/utils'; import parseDuration from 'parse-duration'; +import { getDefaultLogger } from '../../runtime/src/getDefaultLogger'; import { addCommands } from './commands/index'; import { createDefaultConfigPaths } from './config'; import { getMaxConcurrency } from './getMaxConcurrency'; @@ -347,7 +347,7 @@ let cli = new Command() export async function run(userCtx: Partial) { const ctx: CLIContext = { - log: userCtx.log || new DefaultLogger(), + log: userCtx.log || getDefaultLogger(), productName: 'Hive Gateway', productDescription: 'Federated GraphQL Gateway', productPackageName: '@graphql-hive/gateway', @@ -362,7 +362,7 @@ export async function run(userCtx: Partial) { cli = cli.name(binName).description(productDescription).version(version); if (cluster.worker?.id) { - ctx.log = ctx.log.child(`Worker #${cluster.worker.id}`); + ctx.log = ctx.log.child({ worker: cluster.worker.id }); } addCommands(ctx, cli); diff --git a/packages/gateway/src/commands/handleFork.ts b/packages/gateway/src/commands/handleFork.ts index 0b2004b64..735290312 100644 --- a/packages/gateway/src/commands/handleFork.ts +++ b/packages/gateway/src/commands/handleFork.ts @@ -10,25 +10,34 @@ export function handleFork(log: Logger, config: { fork?: number }): boolean { log.debug(`Forking ${config.fork} workers`); for (let i = 0; i < config.fork; i++) { const worker = cluster.fork(); + const workerLogger = log.child({ worker: worker.id }); worker.once('exit', (code, signal) => { + const logData: Record = { + signal, + }; + if (code != null) { + logData['code'] = code; + } if (expectedToExit) { - log.debug( - `Worker ${worker.process.pid} exited with code ${code} and signal ${signal}`, - ); + workerLogger.debug('exited', logData); } else { - log.warn(`Worker ${worker.process.pid} exited unexpectedly with code ${code} and signal ${signal}\n -A restart is recommended to ensure the stability of the service`); + workerLogger.error( + 'exited unexpectedly. A restart is recommended to ensure the stability of the service', + logData, + ); } workers.delete(worker); if (!expectedToExit && workers.size === 0) { - log.error(`All workers exited unexpectedly. Exiting`); + log.error(`All workers exited unexpectedly. Exiting`, logData); process.exit(1); } }); workers.add(worker); } registerTerminateHandler((signal) => { - log.info(`Killing workers with ${signal}`); + log.info('Killing workers', { + signal, + }); expectedToExit = true; workers.forEach((w) => { w.kill(signal); diff --git a/packages/gateway/src/commands/handleLoggingOption.ts b/packages/gateway/src/commands/handleLoggingOption.ts index 89c032f34..597261e57 100644 --- a/packages/gateway/src/commands/handleLoggingOption.ts +++ b/packages/gateway/src/commands/handleLoggingOption.ts @@ -1,5 +1,6 @@ import { Logger } from '@graphql-mesh/types'; -import { CLIContext, DefaultLogger, LogLevel } from '..'; +import { CLIContext, LogLevel } from '..'; +import { getDefaultLogger } from '../../../runtime/src/getDefaultLogger'; export function handleLoggingConfig( loggingConfig: boolean | Logger | LogLevel | undefined, @@ -9,17 +10,23 @@ export function handleLoggingConfig( ctx.log = loggingConfig; } else if (typeof loggingConfig === 'boolean') { if (!loggingConfig) { - if (ctx.log instanceof DefaultLogger) { + if ('logLevel' in ctx.log) { ctx.log.logLevel = LogLevel.silent; } else { - ctx.log = new DefaultLogger(ctx.log.name, LogLevel.silent); + ctx.log = getDefaultLogger({ + name: ctx.log.name, + level: LogLevel.silent, + }); } } } else if (typeof loggingConfig === 'number') { - if (ctx.log instanceof DefaultLogger) { + if ('logLevel' in ctx.log) { ctx.log.logLevel = loggingConfig; } else { - ctx.log = new DefaultLogger(ctx.log.name, loggingConfig); + ctx.log = getDefaultLogger({ + name: ctx.log.name, + level: loggingConfig, + }); } } } diff --git a/packages/gateway/src/commands/proxy.ts b/packages/gateway/src/commands/proxy.ts index 318d3b193..2b08adf97 100644 --- a/packages/gateway/src/commands/proxy.ts +++ b/packages/gateway/src/commands/proxy.ts @@ -65,11 +65,12 @@ export const addCommand: AddCommand = (ctx, cli) => const hiveCdnEndpointOpt = // TODO: take schema from optsWithGlobals once https://github.com/commander-js/extra-typings/pull/76 is merged this.opts().schema || hiveCdnEndpoint; + const hiveCdnLogger = ctx.log.child({ source: 'Hive CDN' }); if (hiveCdnEndpointOpt) { if (hiveCdnKey) { if (!isUrl(hiveCdnEndpointOpt)) { - ctx.log.error( - 'Hive CDN endpoint must be a URL when providing --hive-cdn-key but got ' + + hiveCdnLogger.error( + 'Endpoint must be a URL when providing --hive-cdn-key but got ' + hiveCdnEndpointOpt, ); process.exit(1); diff --git a/packages/importer/src/debug.ts b/packages/importer/src/debug.ts index 4b38c5a44..5c0c75327 100644 --- a/packages/importer/src/debug.ts +++ b/packages/importer/src/debug.ts @@ -1,9 +1,13 @@ -export const isDebug = ['1', 'y', 'yes', 't', 'true'].includes( - String(process.env['DEBUG']), -); +export const isDebug = ['importer'].includes(String(process.env['DEBUG'])); -export function debug(msg: string) { +export function debug(message: string) { if (isDebug) { - process.stderr.write(`[${new Date().toISOString()}] HOOKS ${msg}\n`); + process.stderr.write( + `${JSON.stringify({ + name: 'importer', + level: 'debug', + message, + })}\n`, + ); } } diff --git a/packages/logger-json/package.json b/packages/logger-json/package.json new file mode 100644 index 000000000..2f7a66220 --- /dev/null +++ b/packages/logger-json/package.json @@ -0,0 +1,56 @@ +{ + "name": "@graphql-hive/logger-json", + "version": "0.0.0", + "type": "module", + "repository": { + "type": "git", + "url": "git+https://github.com/graphql-hive/gateway.git", + "directory": "packages/logger-json" + }, + "author": { + "email": "contact@the-guild.dev", + "name": "The Guild", + "url": "https://the-guild.dev" + }, + "license": "MIT", + "engines": { + "node": ">=18.0.0" + }, + "main": "./dist/index.js", + "exports": { + ".": { + "require": { + "types": "./dist/index.d.cts", + "default": "./dist/index.cjs" + }, + "import": { + "types": "./dist/index.d.ts", + "default": "./dist/index.js" + } + }, + "./package.json": "./package.json" + }, + "types": "./dist/index.d.ts", + "files": [ + "dist" + ], + "scripts": { + "build": "pkgroll --clean-dist", + "prepack": "yarn build" + }, + "peerDependencies": { + "graphql": "^15.9.0 || ^16.9.0" + }, + "dependencies": { + "@graphql-mesh/cross-helpers": "^0.4.10", + "@graphql-mesh/types": "^0.103.16", + "@graphql-mesh/utils": "^0.103.16", + "cross-inspect": "^1.0.1", + "tslib": "^2.8.1" + }, + "devDependencies": { + "graphql": "^16.9.0", + "pkgroll": "2.8.2" + }, + "sideEffects": false +} diff --git a/packages/logger-json/src/index.ts b/packages/logger-json/src/index.ts new file mode 100644 index 000000000..ae577c0b8 --- /dev/null +++ b/packages/logger-json/src/index.ts @@ -0,0 +1,185 @@ +import { process } from '@graphql-mesh/cross-helpers'; +import type { LazyLoggerMessage, Logger } from '@graphql-mesh/types'; +import { LogLevel } from '@graphql-mesh/utils'; +import { inspect } from 'cross-inspect'; + +export interface JSONLoggerOptions { + name?: string; + meta?: Record; + level?: LogLevel; + console?: Console; +} +function truthy(val: unknown) { + return ( + val === true || + val === 1 || + ['1', 't', 'true', 'y', 'yes'].includes(String(val)) + ); +} + +declare global { + var DEBUG: string; +} + +export class JSONLogger implements Logger { + name?: string; + meta: Record; + logLevel: LogLevel; + console: Console; + constructor(opts?: JSONLoggerOptions) { + this.name = opts?.name; + this.console = opts?.console || console; + this.meta = opts?.meta || {}; + const debugStrs = [process.env['DEBUG'], globalThis.DEBUG]; + if (opts?.level != null) { + this.logLevel = opts.level; + } else { + this.logLevel = LogLevel.info; + for (const debugStr of debugStrs) { + if (debugStr) { + if (truthy(debugStr)) { + this.logLevel = LogLevel.debug; + break; + } + if (opts?.name) { + if (debugStr?.toString()?.includes(opts.name)) { + this.logLevel = LogLevel.debug; + break; + } + } + } + } + } + } + + log(...messageArgs: LazyLoggerMessage[]) { + if (this.logLevel > LogLevel.info) { + return; + } + const finalMessage = this.prepareFinalMessage('info', messageArgs); + this.console.log(finalMessage); + } + + warn(...messageArgs: LazyLoggerMessage[]) { + if (this.logLevel > LogLevel.warn) { + return; + } + const finalMessage = this.prepareFinalMessage('warn', messageArgs); + this.console.warn(finalMessage); + } + + info(...messageArgs: LazyLoggerMessage[]) { + if (this.logLevel > LogLevel.info) { + return; + } + const finalMessage = this.prepareFinalMessage('info', messageArgs); + this.console.info(finalMessage); + } + + error(...messageArgs: LazyLoggerMessage[]) { + if (this.logLevel > LogLevel.error) { + return; + } + const finalMessage = this.prepareFinalMessage('error', messageArgs); + this.console.error(finalMessage); + } + + debug(...messageArgs: LazyLoggerMessage[]) { + if (this.logLevel > LogLevel.debug) { + return; + } + const finalMessage = this.prepareFinalMessage('debug', messageArgs); + this.console.debug(finalMessage); + } + + child(nameOrMeta: string | Record) { + let newName: string | undefined; + let newMeta: Record; + if (typeof nameOrMeta === 'string') { + newName = this.name ? `${this.name}, ${nameOrMeta}` : nameOrMeta; + newMeta = this.meta; + } else if (typeof nameOrMeta === 'object') { + newName = this.name; + newMeta = { ...this.meta, ...nameOrMeta }; + } else { + throw new Error('Invalid argument type'); + } + return new JSONLogger({ + name: newName, + meta: newMeta, + level: this.logLevel, + console: this.console, + }); + } + + addPrefix(prefix: string | Record) { + if (typeof prefix === 'string') { + this.name = this.name ? `${this.name}, ${prefix}` : prefix; + } else if (typeof prefix === 'object') { + this.meta = { ...this.meta, ...prefix }; + } + return this; + } + + private prepareFinalMessage(level: string, messageArgs: LazyLoggerMessage[]) { + const flattenedMessageArgs = messageArgs + .flat(Infinity) + .flatMap((messageArg) => { + if (typeof messageArg === 'function') { + messageArg = messageArg(); + } + if (messageArg?.toJSON) { + messageArg = messageArg.toJSON(); + } + if (messageArg instanceof AggregateError) { + return messageArg.errors; + } + return messageArg; + }); + const finalMessage: Record = { + ...this.meta, + level, + time: new Date().toISOString(), + }; + if (this.name) { + finalMessage['name'] = this.name; + } + const extras: any[] = []; + for (let messageArg of flattenedMessageArgs) { + if (messageArg == null) { + continue; + } + const typeofMessageArg = typeof messageArg; + if ( + typeofMessageArg === 'string' || + typeofMessageArg === 'number' || + typeofMessageArg === 'boolean' + ) { + finalMessage['msg'] = finalMessage['msg'] + ? finalMessage['msg'] + ', ' + messageArg + : messageArg; + } else if (typeofMessageArg === 'object') { + if (messageArg instanceof Error) { + finalMessage['msg'] = finalMessage['msg'] + ? finalMessage['msg'] + ', ' + messageArg.message + : messageArg.message; + finalMessage['stack'] = messageArg.stack; + } else if ( + Object.prototype.toString.call(messageArg).startsWith('[object') + ) { + Object.assign(finalMessage, messageArg); + } else { + extras.push(messageArg); + } + } + } + if (extras.length) { + if (extras.length === 1) { + finalMessage['extras'] = inspect(extras[0]); + } else { + finalMessage['extras'] = extras.map((extra) => inspect(extra)); + } + } + return JSON.stringify(finalMessage); + } +} diff --git a/packages/plugins/opentelemetry/src/plugin.ts b/packages/plugins/opentelemetry/src/plugin.ts index cce3fe667..d6059f682 100644 --- a/packages/plugins/opentelemetry/src/plugin.ts +++ b/packages/plugins/opentelemetry/src/plugin.ts @@ -194,7 +194,7 @@ export function useOpenTelemetry( webProvider.register(); provider = webProvider; } - const pluginLogger = options.logger.child('OpenTelemetry'); + const pluginLogger = options.logger.child({ plugin: 'OpenTelemetry' }); diag.setLogger( { error: (message, ...args) => pluginLogger.error(message, ...args), diff --git a/packages/runtime/package.json b/packages/runtime/package.json index b335e8067..313117eec 100644 --- a/packages/runtime/package.json +++ b/packages/runtime/package.json @@ -54,6 +54,7 @@ "@envelop/disable-introspection": "^6.0.0", "@envelop/generic-auth": "^8.0.0", "@graphql-hive/core": "^0.9.0", + "@graphql-hive/logger-json": "workspace:^", "@graphql-mesh/cross-helpers": "^0.4.9", "@graphql-mesh/fusion-runtime": "workspace:^", "@graphql-mesh/hmac-upstream-signature": "workspace:^", diff --git a/packages/runtime/src/createGatewayRuntime.ts b/packages/runtime/src/createGatewayRuntime.ts index 718625f34..cfc65f4f8 100644 --- a/packages/runtime/src/createGatewayRuntime.ts +++ b/packages/runtime/src/createGatewayRuntime.ts @@ -26,7 +26,6 @@ import useMeshResponseCache from '@graphql-mesh/plugin-response-cache'; import { TransportContext } from '@graphql-mesh/transport-common'; import type { Logger, OnDelegateHook, OnFetchHook } from '@graphql-mesh/types'; import { - DefaultLogger, getHeadersObj, getInContextSDK, isUrl, @@ -79,6 +78,7 @@ import { } from 'graphql-yoga'; import type { GraphiQLOptions, PromiseOrValue } from 'graphql-yoga'; import { createGraphOSFetcher } from './fetchers/graphos'; +import { getDefaultLogger } from './getDefaultLogger'; import { getProxyExecutor } from './getProxyExecutor'; import { getReportingPlugin } from './getReportingPlugin'; import { @@ -137,13 +137,17 @@ export function createGatewayRuntime< let fetchAPI = config.fetchAPI; let logger: Logger; if (config.logging == null) { - logger = new DefaultLogger(); + logger = getDefaultLogger(); } else if (typeof config.logging === 'boolean') { logger = config.logging - ? new DefaultLogger() - : new DefaultLogger('', LogLevel.silent); + ? getDefaultLogger() + : getDefaultLogger({ + level: LogLevel.silent, + }); } else if (typeof config.logging === 'number') { - logger = new DefaultLogger(undefined, config.logging); + logger = getDefaultLogger({ + level: config.logging, + }); } /* if (typeof config.logging === 'object') */ else { logger = config.logging; } @@ -189,7 +193,9 @@ export function createGatewayRuntime< ) { persistedDocumentsPlugin = useMeshHive({ ...configContext, - logger: configContext.logger.child('Hive'), + logger: configContext.logger.child({ + plugin: 'Hive Persisted Documents', + }), experimental__persistedDocuments: { cdn: { endpoint: config.persistedDocuments.endpoint, @@ -253,7 +259,7 @@ export function createGatewayRuntime< const fetcher = createSchemaFetcher({ endpoint, key, - logger: configContext.logger.child('Hive CDN'), + logger: configContext.logger.child({ source: 'Hive CDN' }), }); schemaFetcher = function fetchSchemaFromCDN() { pausePolling(); @@ -611,7 +617,7 @@ export function createGatewayRuntime< const fetcher = createSupergraphSDLFetcher({ endpoint, key, - logger: configContext.logger.child('Hive CDN'), + logger: configContext.logger.child({ source: 'Hive CDN' }), }); unifiedGraphFetcher = () => fetcher().then(({ supergraphSdl }) => supergraphSdl); diff --git a/packages/runtime/src/fetchers/graphos.ts b/packages/runtime/src/fetchers/graphos.ts index fc2fba7a6..c71fc3c6e 100644 --- a/packages/runtime/src/fetchers/graphos.ts +++ b/packages/runtime/src/fetchers/graphos.ts @@ -27,7 +27,7 @@ export function createGraphOSFetcher({ graphosOpts.upLink || process.env['APOLLO_SCHEMA_CONFIG_DELIVERY_ENDPOINT']; const uplinks = uplinksParam?.split(',').map((uplink) => uplink.trim()) || DEFAULT_UPLINKS; - const graphosLogger = configContext.logger.child('GraphOS'); + const graphosLogger = configContext.logger.child({ source: 'GraphOS' }); graphosLogger.info('Using Managed Federation with uplinks: ', ...uplinks); const maxRetries = graphosOpts.maxRetries || Math.max(3, uplinks.length); let supergraphLoadedPlace = defaultLoadedPlacePrefix; @@ -57,9 +57,10 @@ export function createGraphOSFetcher({ } retries--; const uplinkToUse = uplinksToUse.pop(); - const attemptLogger = graphosLogger.child( - `Attempt ${maxRetries - retries} - UpLink: ${uplinkToUse}`, - ); + const attemptLogger = graphosLogger.child({ + attempt: maxRetries - retries, + uplink: uplinkToUse || 'none', + }); attemptLogger.debug(`Fetching supergraph`); return fetchSupergraphSdlFromManagedFederation({ graphRef: graphosOpts.graphRef, diff --git a/packages/runtime/src/getDefaultLogger.ts b/packages/runtime/src/getDefaultLogger.ts new file mode 100644 index 000000000..e45ca463c --- /dev/null +++ b/packages/runtime/src/getDefaultLogger.ts @@ -0,0 +1,19 @@ +import { JSONLogger } from '@graphql-hive/logger-json'; +import { process } from '@graphql-mesh/cross-helpers'; +import { DefaultLogger, LogLevel } from '@graphql-mesh/utils'; + +export function getDefaultLogger(opts?: { name?: string; level?: LogLevel }) { + const logFormat = process.env['LOG_FORMAT'] || (globalThis as any).LOG_FORMAT; + if (logFormat) { + if (logFormat.toLowerCase() === 'json') { + return new JSONLogger(opts); + } else if (logFormat.toLowerCase() === 'pretty') { + return new DefaultLogger(opts?.name, opts?.level); + } + } + const nodeEnv = process.env['NODE_ENV'] || (globalThis as any).NODE_ENV; + if (nodeEnv === 'production') { + return new JSONLogger(opts); + } + return new DefaultLogger(opts?.name, opts?.level); +} diff --git a/packages/runtime/src/getReportingPlugin.ts b/packages/runtime/src/getReportingPlugin.ts index 257df4639..89f68893d 100644 --- a/packages/runtime/src/getReportingPlugin.ts +++ b/packages/runtime/src/getReportingPlugin.ts @@ -18,7 +18,7 @@ export function getReportingPlugin>( name: 'Hive', plugin: useMeshHive({ ...configContext, - logger: configContext.logger.child('Hive'), + logger: configContext.logger.child({ reporting: 'Hive' }), ...config.reporting, ...(config.persistedDocuments && 'type' in config.persistedDocuments && diff --git a/packages/runtime/src/index.ts b/packages/runtime/src/index.ts index d749d7e3f..cb5cdfe8d 100644 --- a/packages/runtime/src/index.ts +++ b/packages/runtime/src/index.ts @@ -1,5 +1,6 @@ export * from './createGatewayRuntime'; export { LogLevel, DefaultLogger } from '@graphql-mesh/utils'; +export { JSONLogger } from '@graphql-hive/logger-json'; export type * from './types'; export * from './plugins/useCustomFetch'; export * from './plugins/useStaticFiles'; diff --git a/packages/runtime/src/plugins/useDelegationPlanDebug.ts b/packages/runtime/src/plugins/useDelegationPlanDebug.ts index 02e77b529..7d7684cd2 100644 --- a/packages/runtime/src/plugins/useDelegationPlanDebug.ts +++ b/packages/runtime/src/plugins/useDelegationPlanDebug.ts @@ -22,16 +22,16 @@ export function useDelegationPlanDebug< info, logger = opts.logger, }) { - logger = logger.child('delegation-plan'); const planId = fetchAPI.crypto.randomUUID(); - logger.debug('start', () => { + const delegationPlanStartLogger = logger.child('delegation-plan-start'); + delegationPlanStartLogger.debug(() => { const logObj: Record = { planId, subgraph, typeName, }; if (variables && Object.keys(variables).length) { - logObj['variables'] = JSON.stringify(variables); + logObj['variables'] = variables; } if (fragments && Object.keys(fragments).length) { logObj['fragments'] = Object.fromEntries( @@ -53,7 +53,8 @@ export function useDelegationPlanDebug< }); const start = performance.now(); return ({ delegationPlan }) => { - logger.debug('done', () => ({ + const delegationPlanDoneLogger = logger.child('delegation-plan-done'); + delegationPlanDoneLogger.debug(() => ({ planId, plan: delegationPlan.map((plan) => { const planObj: Record = {}; @@ -78,13 +79,13 @@ export function useDelegationPlanDebug< typeName, logger = opts.logger, }) { - logger = logger.child('delegation-stage-execute'); let stageId: string; let contextLog = stageExecuteLogById.get(context); if (!contextLog) { contextLog = new Set(); stageExecuteLogById.set(context, contextLog); } + const delegationStageLogger = logger.child('delegation-stage-execute'); const log = { subgraph, typeName, @@ -98,7 +99,7 @@ export function useDelegationPlanDebug< } contextLog.add(logStr); stageId = fetchAPI.crypto.randomUUID(); - logger.debug('start', () => { + delegationStageLogger.debug('start', () => { return { stageId, ...log, @@ -107,7 +108,10 @@ export function useDelegationPlanDebug< }); const start = performance.now(); return ({ result }) => { - logger.debug('result', () => ({ + const delegationStageExecuteDoneLogger = logger.child( + 'delegation-stage-execute-done', + ); + delegationStageExecuteDoneLogger.debug(() => ({ stageId, result: JSON.stringify(result, null), duration: performance.now() - start, diff --git a/packages/runtime/src/plugins/useFetchDebug.ts b/packages/runtime/src/plugins/useFetchDebug.ts index dc1f7f981..f49cde1ed 100644 --- a/packages/runtime/src/plugins/useFetchDebug.ts +++ b/packages/runtime/src/plugins/useFetchDebug.ts @@ -10,24 +10,31 @@ export function useFetchDebug>(opts: { onYogaInit({ yoga }) { fetchAPI = yoga.fetchAPI; }, - onFetch({ url, options, logger = opts.logger }) { - logger = logger.child('fetch'); + onFetch({ url, options, logger = opts.logger, requestId }) { const fetchId = fetchAPI.crypto.randomUUID(); - logger.debug('request', () => ({ + const loggerMeta: Record = { fetchId, + }; + if (requestId) { + loggerMeta['requestId'] = requestId; + } + const fetchLogger = logger.child(loggerMeta); + const httpFetchRequestLogger = fetchLogger.child('http-fetch-request'); + httpFetchRequestLogger.debug(() => ({ url, ...(options || {}), - body: options?.body && JSON.stringify(options.body), - headers: options?.headers && JSON.stringify(options.headers, null, 2), + body: options?.body, + headers: options?.headers, + signal: options?.signal?.aborted ? options?.signal?.reason : false, })); const start = performance.now(); return function onFetchDone({ response }) { - logger.debug('response', () => ({ - fetchId, + const httpFetchResponseLogger = fetchLogger.child( + 'http-fetch-response', + ); + httpFetchResponseLogger.debug(() => ({ status: response.status, - headers: JSON.stringify( - Object.fromEntries(response.headers.entries()), - ), + headers: Object.fromEntries(response.headers.entries()), duration: performance.now() - start, })); }; diff --git a/packages/runtime/src/plugins/useRequestId.ts b/packages/runtime/src/plugins/useRequestId.ts index 8f9a4705b..f89579ded 100644 --- a/packages/runtime/src/plugins/useRequestId.ts +++ b/packages/runtime/src/plugins/useRequestId.ts @@ -15,7 +15,7 @@ export function useRequestId< const requestId = requestIdByRequest.get(context.request); if (requestId && context.logger) { // @ts-expect-error - Logger is somehow read-only - context.logger = context.logger.child(requestId); + context.logger = context.logger.child({ requestId }); } } }, diff --git a/packages/runtime/src/plugins/useSubgraphExecuteDebug.ts b/packages/runtime/src/plugins/useSubgraphExecuteDebug.ts index 442051bb3..26937b940 100644 --- a/packages/runtime/src/plugins/useSubgraphExecuteDebug.ts +++ b/packages/runtime/src/plugins/useSubgraphExecuteDebug.ts @@ -11,41 +11,56 @@ export function useSubgraphExecuteDebug< onYogaInit({ yoga }) { fetchAPI = yoga.fetchAPI; }, - onSubgraphExecute({ executionRequest, logger = opts.logger }) { + onSubgraphExecute({ executionRequest, logger = opts.logger, requestId }) { const subgraphExecuteId = fetchAPI.crypto.randomUUID(); - logger = logger.child('subgraph-execute'); + const loggerMeta: Record = { + subgraphExecuteId, + }; + if (requestId) { + loggerMeta['requestId'] = requestId; + } + const subgraphExecuteHookLogger = logger.child(loggerMeta); if (executionRequest) { - logger.debug('start', () => ({ - subgraphExecuteId, - query: - executionRequest.document && - defaultPrintFn(executionRequest.document), - variables: + const subgraphExecuteStartLogger = subgraphExecuteHookLogger.child( + 'subgraph-execute-start', + ); + subgraphExecuteStartLogger.debug(() => { + const logData: Record = {}; + if (executionRequest.document) { + logData['query'] = defaultPrintFn(executionRequest.document); + } + if ( executionRequest.variables && - JSON.stringify(executionRequest.variables), - })); + Object.keys(executionRequest.variables).length + ) { + logData['variables'] = executionRequest.variables; + } + return logData; + }); } const start = performance.now(); return function onSubgraphExecuteDone({ result }) { + const subgraphExecuteEndLogger = subgraphExecuteHookLogger.child( + 'subgraph-execute-end', + ); if (isAsyncIterable(result)) { return { onNext({ result }) { - logger.debug('next', () => ({ - subgraphExecuteId, - result: JSON.stringify(result), - })); + const subgraphExecuteNextLogger = subgraphExecuteHookLogger.child( + 'subgraph-execute-next', + ); + subgraphExecuteNextLogger.debug(result); }, onEnd() { - logger.debug('end', () => ({ - subgraphExecuteId, + subgraphExecuteEndLogger.debug(() => ({ duration: performance.now() - start, })); }, }; } - logger.debug('result', () => ({ - subgraphExecuteId, - result: JSON.stringify(result), + subgraphExecuteEndLogger.debug(() => ({ + result, + duration: performance.now() - start, })); return void 0; }; diff --git a/packages/runtime/tests/graphos.test.ts b/packages/runtime/tests/graphos.test.ts index 46f06e384..e54022b63 100644 --- a/packages/runtime/tests/graphos.test.ts +++ b/packages/runtime/tests/graphos.test.ts @@ -1,6 +1,6 @@ import { setTimeout } from 'timers/promises'; import { - DefaultLogger, + JSONLogger, type GatewayConfigContext, type GatewayGraphOSManagedFederationOptions, } from '@graphql-hive/gateway-runtime'; @@ -131,7 +131,7 @@ function createTestFetcher( return createGraphOSFetcher({ configContext: { logger: process.env['DEBUG'] - ? new DefaultLogger() + ? new JSONLogger() : { child() { return this; diff --git a/packages/transports/http-callback/src/index.ts b/packages/transports/http-callback/src/index.ts index 2b0c874cb..2e3b15245 100644 --- a/packages/transports/http-callback/src/index.ts +++ b/packages/transports/http-callback/src/index.ts @@ -107,7 +107,10 @@ export default { executionRequest: ExecutionRequest, ) { const subscriptionId = crypto.randomUUID(); - const subscriptionLogger = logger?.child(subscriptionId); + const subscriptionLogger = logger?.child({ + executor: 'http-callback', + subscription: subscriptionId, + }); const callbackUrl = `${publicUrl}${callbackPath}/${subscriptionId}`; const subscriptionCallbackPath = `${callbackPath}/${subscriptionId}`; const serializedParams = serializeExecutionRequest({ diff --git a/packages/transports/ws/src/index.ts b/packages/transports/ws/src/index.ts index 8bb8dfefe..2f937b45a 100644 --- a/packages/transports/ws/src/index.ts +++ b/packages/transports/ws/src/index.ts @@ -76,7 +76,12 @@ export default { let wsExecutor = wsExecutorMap.get(hash); if (!wsExecutor) { - const executorLogger = logger?.child('GraphQL WS').child(hash); + const executorLogger = logger?.child({ + executor: 'GraphQL WS', + wsUrl, + connectionParams, + headers, + } as Record); wsExecutor = buildGraphQLWSExecutor({ headers, url: wsUrl, diff --git a/packages/transports/ws/tests/ws.spec.ts b/packages/transports/ws/tests/ws.spec.ts index 9c76aa553..0e71544ec 100644 --- a/packages/transports/ws/tests/ws.spec.ts +++ b/packages/transports/ws/tests/ws.spec.ts @@ -1,8 +1,9 @@ +import { JSONLogger } from '@graphql-hive/logger-json'; import type { TransportEntry, TransportGetSubgraphExecutorOptions, } from '@graphql-mesh/transport-common'; -import { DefaultLogger, dispose } from '@graphql-mesh/utils'; +import { dispose } from '@graphql-mesh/utils'; import { makeExecutableSchema } from '@graphql-tools/schema'; import { createDeferred } from '@graphql-tools/utils'; import { createDisposableWebSocketServer } from '@internal/testing'; @@ -78,7 +79,7 @@ async function createTServer( ...transportEntry, options, }, - logger: new DefaultLogger(), + logger: new JSONLogger(), } as unknown as TransportGetSubgraphExecutorOptions, onClient, ); diff --git a/tsconfig.json b/tsconfig.json index 012777265..102006b93 100644 --- a/tsconfig.json +++ b/tsconfig.json @@ -58,7 +58,8 @@ "./packages/stitching-directives/src/index.ts" ], "@graphql-tools/wrap": ["./packages/wrap/src/index.ts"], - "@graphql-tools/executor-*": ["./packages/executors/*/src/index.ts"] + "@graphql-tools/executor-*": ["./packages/executors/*/src/index.ts"], + "@graphql-hive/logger-json": ["./packages/logger-json/src/index.ts"] } }, "include": [ diff --git a/yarn.lock b/yarn.lock index c601070ad..b4ddd205c 100644 --- a/yarn.lock +++ b/yarn.lock @@ -3237,6 +3237,7 @@ __metadata: "@envelop/disable-introspection": "npm:^6.0.0" "@envelop/generic-auth": "npm:^8.0.0" "@graphql-hive/core": "npm:^0.9.0" + "@graphql-hive/logger-json": "workspace:^" "@graphql-mesh/cross-helpers": "npm:^0.4.9" "@graphql-mesh/fusion-composition": "npm:^0.7.0" "@graphql-mesh/fusion-runtime": "workspace:^" @@ -3367,6 +3368,22 @@ __metadata: languageName: unknown linkType: soft +"@graphql-hive/logger-json@workspace:^, @graphql-hive/logger-json@workspace:packages/logger-json": + version: 0.0.0-use.local + resolution: "@graphql-hive/logger-json@workspace:packages/logger-json" + dependencies: + "@graphql-mesh/cross-helpers": "npm:^0.4.10" + "@graphql-mesh/types": "npm:^0.103.16" + "@graphql-mesh/utils": "npm:^0.103.16" + cross-inspect: "npm:^1.0.1" + graphql: "npm:^16.9.0" + pkgroll: "npm:2.8.2" + tslib: "npm:^2.8.1" + peerDependencies: + graphql: ^15.9.0 || ^16.9.0 + languageName: unknown + linkType: soft + "@graphql-hive/yoga@npm:^0.39.2": version: 0.39.3 resolution: "@graphql-hive/yoga@npm:0.39.3" @@ -3811,19 +3828,19 @@ __metadata: languageName: node linkType: hard -"@graphql-mesh/store@npm:^0.103.15": - version: 0.103.15 - resolution: "@graphql-mesh/store@npm:0.103.15" +"@graphql-mesh/store@npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a": + version: 0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a + resolution: "@graphql-mesh/store@npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a" dependencies: "@graphql-inspector/core": "npm:6.2.1" "@graphql-mesh/cross-helpers": "npm:^0.4.10" - "@graphql-mesh/types": "npm:^0.103.15" - "@graphql-mesh/utils": "npm:^0.103.15" + "@graphql-mesh/types": "npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a" + "@graphql-mesh/utils": "npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a" "@graphql-tools/utils": "npm:^10.8.0" tslib: "npm:^2.4.0" peerDependencies: graphql: "*" - checksum: 10c0/d13e3b59f8711224215f396533d1584422cd6bbdaf8991bc4a3bda53f67a188b3c69bf81bdd5dce3bf7e6ddfd941da21175c3473bd439425087ec44cf357330c + checksum: 10c0/18289554b6ad038c1a7eadf3613c8e45195ae7e676a6d38366fdeb5ccd0af1ea2a1709f07027242583ff39d724a254cccf5766f0089e2256b478f0fed49f7f98 languageName: node linkType: hard @@ -3965,11 +3982,11 @@ __metadata: languageName: unknown linkType: soft -"@graphql-mesh/types@npm:^0.103.15, @graphql-mesh/types@npm:^0.103.6": - version: 0.103.15 - resolution: "@graphql-mesh/types@npm:0.103.15" +"@graphql-mesh/types@npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a": + version: 0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a + resolution: "@graphql-mesh/types@npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a" dependencies: - "@graphql-mesh/store": "npm:^0.103.15" + "@graphql-mesh/store": "npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a" "@graphql-tools/batch-delegate": "npm:^9.0.10" "@graphql-tools/delegate": "npm:^10.0.28" "@graphql-tools/utils": "npm:^10.8.0" @@ -3977,17 +3994,17 @@ __metadata: tslib: "npm:^2.4.0" peerDependencies: graphql: "*" - checksum: 10c0/61a010e01b2fe79a27ac7da0759bea96bcd95180c12f3bdf9c6d2bdd0798fc24cfa0a1aa5eb9bad0978c1e88272895e58b065fcdb8283e3373cc5d93b90a0203 + checksum: 10c0/bf9e5ebbe704a7b2881d5efae13db9acfaf7f2c5560196b61ae2661b41b8e0fa14342b4b0c27b99f73affe9be93652d32364ee2183a58ac0c24d0844e73b3219 languageName: node linkType: hard -"@graphql-mesh/utils@npm:^0.103.15, @graphql-mesh/utils@npm:^0.103.6": - version: 0.103.15 - resolution: "@graphql-mesh/utils@npm:0.103.15" +"@graphql-mesh/utils@npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a": + version: 0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a + resolution: "@graphql-mesh/utils@npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a" dependencies: "@graphql-mesh/cross-helpers": "npm:^0.4.10" "@graphql-mesh/string-interpolation": "npm:^0.5.8" - "@graphql-mesh/types": "npm:^0.103.15" + "@graphql-mesh/types": "npm:0.103.16-alpha-20250212125252-6167fff12fe4017202b35363ff2769aafe28f98a" "@graphql-tools/batch-delegate": "npm:^9.0.16" "@graphql-tools/delegate": "npm:^10.0.28" "@graphql-tools/utils": "npm:^10.8.0" @@ -4002,7 +4019,7 @@ __metadata: tslib: "npm:^2.4.0" peerDependencies: graphql: "*" - checksum: 10c0/aecd81e23f15a5d85221146810f8347787c338639b394b8fecde113ebde3baedef545f75090ab9ac8bb11fe41047c68679e7539f95da5a236fabea2a96c0dc1c + checksum: 10c0/16fde4724163b263927bf886eae772fa7f17a2ee3636398d5d18ebaf23959309a1e99745d4d8fd999aa00cb37a1b8d85b076b88c7e6578aec77f35c5671bed12 languageName: node linkType: hard