Different levels for child loggers (#328)

* Different levels for child loggers

* Use createChildLogger

* Fix tests

* E2E test for child logger level

* More logs for policies

* Docs

* More child loggers

* Child logger level in blackbox tests

docs/logging.md

@@ -1,5 +1,7 @@
 # Logging
 
+## Configuration
+
 Stitch uses [`pino`](https://github.com/pinojs/pino) logger. The logger default configuration can be found [here](../services/src/modules/logger.ts).
 
 Custom configuration can be provided using `LOGGER_CONFIGURATION` environment variable.
@@ -16,3 +18,31 @@ LOGGER_CONFIGURATION: |
     ]
   }
 ```
+
+## Logging levels
+
+Stitch log level can be set using `LOG_LEVEL` environment variable. The levels are `trace`, `debug`, `info`, `warn`, `error`, and `fatal`. The default log level is `warn`.
+
+Additionally there is option to set different log levels for every module. It can be done using `CHILD_LOGGERS_LEVELS` environment variable.
+
+In the example:
+
+```json
+{
+  "policies-directive": "debug"
+}
+```
+
+In this case the logger in the [`policies.ts`](../services/src/modules/directives/policy/policies.ts) module will log all that is `debug` level or above. All other modules will log on the level defined by `LOG_LEVEL` environment variable.
+
+### Existing module loggers
+
+- request
+- opa-rego-compiler
+- auth-strategy-api-key
+- auth-strategy-jwt
+- policies-directive
+- policy-directive
+- policy-query-directive
+- policy-executor
+- policy-argument-evaluator

services/src/gateway.ts

@@ -4,15 +4,17 @@ import * as fastifyMetrics from 'fastify-metrics';
 import * as jwtPlugin from 'fastify-jwt';
 import * as authPlugin from 'fastify-auth';
 import * as config from './modules/config';
-import logger from './modules/logger';
+import logger, { createChildLogger } from './modules/logger';
 import { handleSignals, handleUncaughtErrors } from './modules/shutdown-handler';
 import createStitchGateway from './modules/apollo-server';
 import { getSecret, anonymousPlugin, jwtDecoderPlugin, authStrategies } from './modules/authentication';
 import { loadPlugins } from './modules/plugins';
 import { initializeMetrics } from './modules/apollo-server-plugins/metrics';
 
+const sLogger = createChildLogger(logger, 'http-server');
+
 export async function createServer() {
-  logger.info('Stitch gateway booting up...');
+  sLogger.info('Stitch gateway booting up...');
 
   await loadPlugins();
 
@@ -52,16 +54,16 @@ export async function createServer() {
     replay.status(200).send('OK');
   });
 
-  logger.info('Stitch gateway is ready to start');
+  sLogger.info('Stitch gateway is ready to start');
   return app;
 }
 
 async function runServer(app: fastify.FastifyInstance) {
   const address = await app.listen(config.httpPort, '0.0.0.0');
   initializeMetrics(app.metrics.client);
-  logger.info({ address }, 'Stitch gateway started');
+  sLogger.info({ address }, 'Stitch gateway started');
 
-  handleSignals(() => app.close(() => logger.info('Stitch gateway stopped successfully')));
+  handleSignals(() => app.close(() => sLogger.info('Stitch gateway stopped successfully')));
   handleUncaughtErrors();
 }
 

services/src/modules/apollo-server-plugins/base-policy.ts

@@ -4,6 +4,7 @@ import { GraphQLFieldResolverParams } from 'apollo-server-types';
 import { RequestContext } from '../context';
 import { Policy } from '../directives/policy/types';
 import { getPolicyDefinition } from '../directives/policy/policy-executor';
+import PolicyExecutionFailedError from '../directives/policy/policy-execution-failed-error';
 
 export function createBasicPolicyPlugin(): ApolloServerPlugin {
   return {
@@ -26,6 +27,14 @@ export function createBasicPolicyPlugin(): ApolloServerPlugin {
               {}
             ) as Policy;
             const policyDefinition = getPolicyDefinition(policies, args.namespace, args.name);
+            if (!policyDefinition) {
+              throw new PolicyExecutionFailedError(
+                { namespace: args.namespace, name: args.name },
+                `The base policy definition was not found`,
+                info.parentType.name,
+                info.fieldName
+              );
+            }
             return policyDefinition.shouldOverrideBasePolicy ?? false;
           });
 

services/src/modules/apollo-server-plugins/logging.ts

@@ -3,7 +3,7 @@ import {
   GraphQLRequestContext,
   GraphQLRequestContextWillSendResponse,
 } from 'apollo-server-plugin-base';
-import logger from '../logger';
+import logger, { createChildLogger } from '../logger';
 
 const isIntrospectionQuery = (operationName?: string) => operationName === 'IntrospectionQuery';
 
@@ -14,7 +14,7 @@ export function createLoggingPlugin(): ApolloServerPlugin {
         request: { query, operationName, variables },
       } = requestDidStartContext;
       const startHrTime = process.hrtime.bigint();
-      const reqLogger = logger.child({ query, operationName });
+      const reqLogger = createChildLogger(logger, 'request', { query, operationName });
       if (!isIntrospectionQuery(operationName)) {
         reqLogger.debug('Started to handle request');
         variables && reqLogger.trace({ variables }, 'request query variables');

services/src/modules/apollo-server/build-federated-schema.ts

@@ -24,7 +24,7 @@ import { composeAndValidate } from '@apollo/federation';
 import { ApolloError } from 'apollo-server-core';
 import createTypeResolvers from '../implicit-type-resolver';
 import { knownApolloDirectives } from '../config';
-import logger from '../logger';
+import logger, { createChildLogger } from '../logger';
 interface DirectiveVisitors {
   [directiveName: string]: typeof SchemaDirectiveVisitor;
 }
@@ -49,6 +49,7 @@ export function buildSchemaFromFederatedTypeDefs({
   schemaDirectives,
   schemaDirectivesContext,
 }: FederatedSchemaBase) {
+  const fLogger = createChildLogger(logger, 'federated-schema-builder');
   // Federation throws away non federation/builtin directives, so we need to do some shenanigans here
 
   // Remove non-federation directives from SDL, save them aside
@@ -76,7 +77,7 @@ export function buildSchemaFromFederatedTypeDefs({
   const compositionResult = composeAndValidate(serviceDefinitions);
   const compositionErrors = compositionResult.errors ?? [];
   if (compositionErrors.length > 0) {
-    logger.error({ compositionErrors }, 'Schema federation validation failed');
+    fLogger.error({ compositionErrors }, 'Schema federation validation failed');
     throw new ApolloError('Schema federation validation failed', 'FEDERATION_VALIDATION_FAILURE', {
       errors: compositionErrors.map(err => (err instanceof GraphQLError ? err : new GraphQLError(err!.message))),
     });

services/src/modules/apollo-server/create-graphql-service.ts

@@ -6,7 +6,7 @@ import { getResourceRepository, ResourceGroup } from '../resource-repository';
 import { ActiveDirectoryAuth } from '../upstreams';
 import { PolicyExecutor } from '../directives/policy';
 import { RequestContext } from '../context';
-import logger from '../logger';
+import logger, { createChildLogger } from '../logger';
 import { resourceUpdateInterval } from '../config';
 import createGatewaySchema from './create-gateway-schema';
 
@@ -17,7 +17,8 @@ interface LocalFederationGateway extends GraphQLService {
 const SCHEMA_UPDATE_EVENT = 'schema_update';
 const eventEmitter = new EventEmitter();
 const onSchemaChange = (callback: SchemaChangeCallback) => {
-  logger.info('Schema was changed');
+  const uLogger = createChildLogger(logger, 'graphql-schema-changed');
+  uLogger.info('Schema was changed');
   eventEmitter.on(SCHEMA_UPDATE_EVENT, callback);
   return () => eventEmitter.off(SCHEMA_UPDATE_EVENT, callback);
 };
@@ -32,19 +33,20 @@ let schema: GraphQLSchema | undefined;
 
 const executor = async <TContext>(requestContext: GraphQLRequestContextExecutionDidStart<TContext>) => {
   const { operationName } = requestContext;
-  logger.trace({ operationName }, 'Enriching request context...');
+  const eLogger = createChildLogger(logger, 'request-executor', { operationName });
+  eLogger.trace('Enriching request context...');
   ((requestContext.context as unknown) as RequestContext).resourceGroup = _resourceGroup!;
   ((requestContext.context as unknown) as RequestContext).activeDirectoryAuth = activeDirectoryAuth;
   ((requestContext.context as unknown) as RequestContext).policyExecutor = policyExecutor;
-  logger.trace('Executing request...');
+  eLogger.trace('Executing request...');
   const result = await execute({
     document: requestContext.document,
     schema: schema!,
     contextValue: requestContext.context,
     operationName: requestContext.operationName ?? requestContext.request.operationName,
     variableValues: requestContext.request.variables,
   });
-  logger.trace('Executed.');
+  eLogger.trace('Executed.');
   return result;
 };
 
@@ -56,7 +58,8 @@ export default function createGraphQLService(): LocalFederationGateway {
   const resourceRepository = getResourceRepository();
 
   const load = async () => {
-    logger.debug('Graphql service is loading...');
+    const cLogger = createChildLogger(logger, 'graphql-service-loading');
+    cLogger.debug('Graphql service is loading...');
     const { resourceGroup } = await resourceRepository.fetchLatest();
     _resourceGroup = resourceGroup;
     schema = await createGatewaySchema(_resourceGroup);
@@ -66,18 +69,19 @@ export default function createGraphQLService(): LocalFederationGateway {
     // executor property of return value of load method is not in use anymore in apollo-server-core v2.22.2
     // instead the executor property is in use.
     // eslint-disable-next-line prettier/prettier
-    return { schema, executor: undefined as unknown as GraphQLExecutor };
+    return { schema, executor: (undefined as unknown) as GraphQLExecutor };
   };
 
   const updateSchema = async () => {
     const { isNew, resourceGroup } = await resourceRepository.fetchLatest();
     if (!isNew) return;
 
-    logger.info('Loading new resources');
+    const uLogger = createChildLogger(logger, 'graphql-schema-update');
+    uLogger.info('Loading new resources');
     _resourceGroup = resourceGroup;
     schema = await createGatewaySchema(_resourceGroup);
     eventEmitter.emit(SCHEMA_UPDATE_EVENT, schema);
-    logger.info('New resources loaded');
+    uLogger.info('New resources loaded');
   };
 
   return {

services/src/modules/authentication/strategies/api-key.ts

@@ -1,5 +1,5 @@
 import * as fastify from 'fastify';
-import logger from '../../logger';
+import logger, { createChildLogger } from '../../logger';
 import { authenticationConfig } from '../../config';
 
 export interface ApiKeyAuthPartialRequest {
@@ -19,7 +19,9 @@ export default async function (request: ApiKeyAuthPartialRequest) {
     (config.queryParam && request.query[config.queryParam])) as string;
   if (!apiKey) throw new Error('Unauthorized');
 
-  const reqLogger = logger.child({ apiKey: apiKey.replace(/(.{2}).+(.{2})/, '$1***$2') });
+  const reqLogger = createChildLogger(logger, 'auth-strategy-api-key', {
+    apiKey: apiKey.replace(/(.{2}).+(.{2})/, '$1***$2'),
+  });
   reqLogger.trace('Api key found in request');
 
   const apiKeyConfig = apiKeys[apiKey];

services/src/modules/authentication/strategies/jwt.ts

@@ -1,5 +1,5 @@
 import * as _ from 'lodash';
-import logger from '../../logger';
+import logger, { createChildLogger } from '../../logger';
 import { authenticationConfig } from '../../config';
 import { DecodedJWT } from '../jwt-decoder-plugin';
 
@@ -20,7 +20,7 @@ export default async function (request: JWTAuthPartialRequest): Promise<void> {
 
   // Verify issuer
   const issuer = String(decodedJWT.payload.iss);
-  const reqLogger = logger.child({ issuer });
+  const reqLogger = createChildLogger(logger, 'auth-strategy-jwt', { issuer });
 
   const issuerConfig = config[issuer];
   if (!issuerConfig) {

services/src/modules/config.ts

@@ -1,6 +1,6 @@
 import * as path from 'path';
 import * as envVar from 'env-var';
-import { LoggerOptions } from 'pino';
+import { LoggerOptions, LevelWithSilent } from 'pino';
 import { PlaygroundConfig } from 'apollo-server-core';
 import { AuthenticationConfig } from './authentication/types';
 import { CorsConfiguration } from './cors';
@@ -10,9 +10,15 @@ const envVarExt = envVar.from(process.env, {
 });
 
 // General
+export const nodeEnv = envVarExt.get('NODE_ENV').default('development').asString();
+
 export const httpPort = envVarExt.get('PORT').default('8080').asIntPositive();
+
+// Logging
+export type ChildLoggersLevels = Record<string, LevelWithSilent>;
 export const logLevel = envVarExt.get('LOG_LEVEL').default('WARN').asString();
-export const nodeEnv = envVarExt.get('NODE_ENV').default('development').asString();
+export const childLoggerLevels = envVarExt.get('CHILD_LOGGERS_LEVELS').default({}).asJsonObject() as ChildLoggersLevels;
+export const loggerConfiguration = envVar.get('LOGGER_CONFIGURATION').default({}).asJsonObject() as LoggerOptions;
 
 // Repositories
 export const useS3ResourceRepository = envVarExt.get('USE_S3_RESOURCE_REPOSITORY').default('false').asBoolStrict();
@@ -62,6 +68,4 @@ export const knownApolloDirectives = envVarExt
   .default(defaultKnownApolloDirectives)
   .asSet();
 
-export const loggerConfiguration = envVar.get('LOGGER_CONFIGURATION').default({}).asJsonObject() as LoggerOptions;
-
 export const corsConfiguration = envVar.get('CORS_CONFIGURATION').default({}).asJsonObject() as CorsConfiguration;

services/src/modules/directives/policy/__snapshots__/policy-executor.spec.ts.snap

@@ -1,7 +1,7 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
-exports[`Policy Executor One required arg. Has no value 1`] = `[PolicyExecutionFailedError: Policy "policy" in namespace "policy-executor-test" execution failed: Missing argument "arg1"]`;
+exports[`Policy Executor One required arg. Has no value 1`] = `[PolicyExecutionFailedError: Policy "policy" in namespace "policy-executor-test" on Foo.bar execution failed: Missing argument "arg1"]`;
 
-exports[`Policy Executor One required arg. Has null value 1`] = `[PolicyExecutionFailedError: Policy "policy" in namespace "policy-executor-test" execution failed: Non-nullable argument "arg1" got value "null"]`;
+exports[`Policy Executor One required arg. Has null value 1`] = `[PolicyExecutionFailedError: Policy "policy" in namespace "policy-executor-test" on Foo.bar execution failed: Non-nullable argument "arg1" got value "null"]`;
 
-exports[`Policy Executor One required arg. Has undefined value 1`] = `[PolicyExecutionFailedError: Policy "policy" in namespace "policy-executor-test" execution failed: Missing argument "arg1"]`;
+exports[`Policy Executor One required arg. Has undefined value 1`] = `[PolicyExecutionFailedError: Policy "policy" in namespace "policy-executor-test" on Foo.bar execution failed: Missing argument "arg1"]`;

services/src/modules/directives/policy/__snapshots__/unauthorized-by-policy-error.spec.ts.snap

@@ -1,5 +1,5 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
-exports[`Unauthorized by policy For @policies directive 1`] = `[UnauthorizedByPolicyError: Unauthorized by policies: policy-1 (ns-1), policy-2 (ns-2)]`;
+exports[`Unauthorized by policy For @policies directive 1`] = `[UnauthorizedByPolicyError: Access to Foo.bar is unauthorized by policies: policy-1 (ns-1), policy-2 (ns-2)]`;
 
-exports[`Unauthorized by policy For @policy directive 1`] = `[UnauthorizedByPolicyError: Unauthorized by policy "policy" in namespace "ns"]`;
+exports[`Unauthorized by policy For @policy directive 1`] = `[UnauthorizedByPolicyError: Access to Foo.bar is unauthorized by policy "policy" in namespace "ns"]`;

services/src/modules/directives/policy/policies.ts

@@ -15,7 +15,7 @@ import { SchemaDirectiveVisitor } from 'graphql-tools';
 import { gql } from 'apollo-server-core';
 import { GraphQLJSONObject } from 'graphql-type-json';
 import { RequestContext } from '../../context';
-import logger from '../../logger';
+import logger, { createChildLogger } from '../../logger';
 import { GraphQLArguments, Policy } from './types';
 import { UnauthorizedByPolicyError } from '.';
 
@@ -30,33 +30,25 @@ const validatePolicies = async (
 ) => {
   if (context.ignorePolicies) return;
 
-  const policiesLogger = logger.child({
-    name: 'policies',
-    type: info.parentType.name,
-    field: info.fieldName,
-    policies: policies.map(({ namespace, name }) => ({ namespace, name })),
-  });
-  policiesLogger.trace('Validating policies...');
   const results = await Promise.allSettled(
     policies.map((p: Policy) => context.policyExecutor.validatePolicy(p, source, args, context, info, result))
   );
 
   const allApproved = results.every(r => r.status === 'fulfilled');
   const someApproved = results.some(r => r.status === 'fulfilled');
 
-  if ((relation === 'AND' && allApproved) || (relation === 'OR' && someApproved)) {
-    policiesLogger.trace('Authorized');
-    return;
-  }
+  if ((relation === 'AND' && allApproved) || (relation === 'OR' && someApproved)) return;
 
   const rejectedPolicies = results.filter(r => r.status === 'rejected').map(r => (r as PromiseRejectedResult).reason);
   const failedPolicies = rejectedPolicies.filter(pe => pe.name !== 'UnauthorizedByPolicyError');
   if (failedPolicies.length > 0) {
-    policiesLogger.trace({ failedPolicies }, 'Policies validation failed');
     throw new GraphQLError(failedPolicies.join(', '));
   }
-  policiesLogger.trace({ rejectedPolicies }, 'Unauthorized');
-  throw new UnauthorizedByPolicyError(rejectedPolicies as UnauthorizedByPolicyError[]);
+  throw new UnauthorizedByPolicyError(
+    rejectedPolicies as UnauthorizedByPolicyError[],
+    info.parentType.name,
+    info.fieldName
+  );
 };
 
 export class PoliciesDirective extends SchemaDirectiveVisitor {
@@ -71,13 +63,20 @@ export class PoliciesDirective extends SchemaDirectiveVisitor {
       context: RequestContext,
       info: GraphQLResolveInfo
     ) => {
+      const pLogger = createChildLogger(logger, 'policies-directive', {
+        policies,
+        type: info.parentType.name,
+        field: info.fieldName,
+      });
       if (!postResolve) {
+        pLogger.trace('Pre resolve validation');
         await validatePolicies(policies, relation, source, {}, context, info);
       }
 
       const result = originalResolveObject ? await originalResolveObject(source, fields, context, info) : source;
 
       if (postResolve) {
+        pLogger.trace({ result }, 'Post resolve validation');
         await validatePolicies(policies, relation, source, {}, context, info, result);
       }
 
@@ -95,13 +94,20 @@ export class PoliciesDirective extends SchemaDirectiveVisitor {
       context: RequestContext,
       info: GraphQLResolveInfo
     ) => {
+      const pLogger = createChildLogger(logger, 'policies-directive', {
+        policies,
+        type: info.parentType.name,
+        field: info.fieldName,
+      });
       if (!postResolve) {
+        pLogger.trace('Pre resolve validation');
         await validatePolicies(policies, relation, source, args, context, info);
       }
 
       const result = await originalResolve.call(field, source, args, context, info);
 
       if (postResolve) {
+        pLogger.trace({ result }, 'Post resolve validation');
         await validatePolicies(policies, relation, source, args, context, info, result);
       }