Logging more data for development (#297)

* Request and response logging

* Log level warning

* Log level convention

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

@@ -9,25 +9,27 @@ export function createLoggingPlugin(): ApolloServerPlugin {
   return {
     requestDidStart(requestDidStartContext: GraphQLRequestContext<unknown>) {
       const {
-        request: { query, operationName },
+        request: { query, operationName, variables },
       } = requestDidStartContext;
       const startHrTime = process.hrtime.bigint();
-      logger.trace({ query, operationName }, 'Started to handle request');
+      const reqLogger = logger.child({ query, operationName });
+      reqLogger.debug('Started to handle request');
+      variables && reqLogger.trace({ variables }, 'request query variables');
       return {
         willSendResponse(willSendResponseContext: GraphQLRequestContextWillSendResponse<unknown>) {
           const {
-            request: { query, operationName },
-            response: { errors },
+            response: { errors, data },
           } = willSendResponseContext;
 
           const endHrTime = process.hrtime.bigint();
           const durationMs = Number(endHrTime - startHrTime) / 1000000;
-          const logData = { query, operationName, errors, durationMs };
+          const logData = { errors, durationMs };
           if (errors) {
-            logger.warn(logData, 'The server encountered errors while proceeding request');
+            reqLogger.warn(logData, 'The server encountered errors while proceeding request');
             return;
           }
-          logger.trace(logData, 'Finished to handle request');
+          reqLogger.debug(logData, 'Finished to handle request');
+          data && reqLogger.trace({ data }, 'response data');
         },
       };
     },

services/src/modules/authentication/get-secret.ts

@@ -70,7 +70,7 @@ export default async function getSecret(
         cb(err, undefined);
         return;
       }
-      logger.trace({ authority }, 'JWK found');
+      logger.debug({ authority }, 'JWK found');
       cb(null, key.getPublicKey());
     });
   } catch (err) {

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

@@ -8,9 +8,11 @@ export default async function (request: fastify.FastifyRequest): Promise<void> {
 
   // Verify issuer
   const issuer = String(decodedJWT.payload.iss);
+  const reqLogger = logger.child({ issuer });
+
   const issuerConfig = authenticationConfig?.jwt?.[issuer];
   if (!issuerConfig) {
-    logger.debug({ issuer }, 'Unknown issuer');
+    reqLogger.debug('Unknown issuer');
     throw new Error('Unauthorized');
   }
 
@@ -20,7 +22,7 @@ export default async function (request: fastify.FastifyRequest): Promise<void> {
       ? decodedJWT.payload.aud.map(a => String(a))
       : Array.of(String(decodedJWT.payload.aud));
     if (!audience.includes(issuerConfig.audience)) {
-      logger.debug({ issuer, audience: decodedJWT.payload.aud }, 'Unexpected audience');
+      reqLogger.debug({ audience: decodedJWT.payload.aud }, 'Unexpected audience');
       throw new Error('Unauthorized');
     }
   }
@@ -30,9 +32,9 @@ export default async function (request: fastify.FastifyRequest): Promise<void> {
     try {
       // Verify JWT signing, expiration and more
       await request.jwtVerify();
-      logger.trace({ issuer }, 'JWT verified');
+      reqLogger.trace('JWT verified');
     } catch (err) {
-      logger.debug({ err, issuer }, 'Failed to verify request JWT');
+      reqLogger.debug({ err }, 'Failed to verify request JWT');
       throw new Error('Unauthorized');
     }
   }

services/src/modules/directives/policy/policy-executor.ts

@@ -1,4 +1,5 @@
 import { GraphQLResolveInfo } from 'graphql';
+import logger from '../../logger';
 import { RequestContext } from '../../context';
 import { PolicyDefinition, PolicyArgsObject } from '../../resource-repository';
 import { inject } from '../../arguments-injection';
@@ -98,13 +99,18 @@ export default class PolicyExecutor {
     const evaluate = typeEvaluators[ctx.policyDefinition.type];
     if (!evaluate) throw new Error(`Unsupported policy type ${ctx.policyDefinition.type}`);
 
+    const logData = { metadata: ctx.policyDefinition.metadata, args, query };
+    logger.trace(logData, 'Executing policy...');
+
     const { done, allow } = evaluate({
       ...ctx.policy,
       args,
       query,
       policyAttachments: ctx.requestContext.resourceGroup.policyAttachments!,
     });
     if (!done) throw new Error('in-line query evaluation not yet supported');
+
+    logger.trace(logData, `Policy executed. The resolver execution is ${allow ? 'allowed' : 'denied'}`);
     return allow || false;
   }
 

services/src/modules/logger.ts

@@ -17,8 +17,19 @@ const devLoggerConfig: pino.LoggerOptions = {
   },
 };
 
-export default pino({
+const logger = pino({
   ...loggerConfig,
   ...(nodeEnv !== 'production' ? devLoggerConfig : {}),
   ...loggerConfiguration,
 });
+
+const level = logger.level;
+if (level === 'trace' || level === 'debug') {
+  logger.warn(`
+    ************************************************************************
+      !!!LOGGER LEVEL IS "${level}" - SOME SENSITIVE DATA MIGHT BE PRINTED!!!
+    ************************************************************************
+  `);
+}
+
+export default logger;

services/src/modules/opa-helper.ts

@@ -28,10 +28,12 @@ export async function prepareCompiledRegoFile(resourceMetadata: ResourceMetadata
   await fs.writeFile(uncompiledPath, regoCode);
 
   const compileCommand = getOpaBuildWasmCommand(uncompiledPath, compiledPath);
+  const regoLogger = logger.child({ policy: resourceMetadata });
   try {
     await exec(compileCommand);
+    regoLogger.debug('Rego compilation succeeded');
   } catch (err) {
-    logger.warn(
+    regoLogger.warn(
       { err, cmd: err.cmd, stdout: err.stdout },
       'Rego compilation failed (normally means invalid user input)'
     );
@@ -42,7 +44,7 @@ export async function prepareCompiledRegoFile(resourceMetadata: ResourceMetadata
     try {
       await deleteLocalRegoFile(uncompiledPath);
     } catch (err) {
-      logger.warn({ err }, 'Failed cleanup of uncompiled rego file, this did not affect the request outcome');
+      regoLogger.warn({ err }, 'Failed cleanup of uncompiled rego file, this did not affect the request outcome');
     }
   }
 

services/src/modules/plugins/apply-plugins.ts

@@ -46,18 +46,19 @@ export async function loadPlugins() {
 }
 
 export async function buildArgumentInjectionGlobals(): Promise<Record<string, unknown>> {
+  logger.info('Building argument injection globals');
   const globals = await plugins
     .filter(p => p.addArgumentInjectionGlobals)
     .reduce(async (resultPromise, curPlugin) => {
       try {
-        logger.trace(
+        logger.debug(
           { plugin: curPlugin.name, method: 'addArgumentInjectionGlobals' },
           `Applying addArgumentInjectionGlobals of ${curPlugin.name} plugin...`
         );
         const resultGlobals = await resultPromise;
         const curPluginGlobals = await curPlugin.addArgumentInjectionGlobals!();
 
-        logger.trace(
+        logger.debug(
           { plugin: curPlugin.name, method: 'addArgumentInjectionGlobals' },
           `addArgumentInjectionGlobals of ${curPlugin.name} plugin was applied successfully.`
         );
@@ -69,20 +70,22 @@ export async function buildArgumentInjectionGlobals(): Promise<Record<string, un
         throw new Error(message);
       }
     }, Promise.resolve({}));
+  logger.debug({ globals: Object.keys(globals) }, 'Argument injection globals were built');
   return globals;
 }
 
 export async function transformResourceGroup(resourceGroup: ResourceGroup): Promise<ResourceGroup> {
+  logger.info('Applying plugins on resource group.');
   let rg: ResourceGroup = { ...resourceGroup, pluginsData: {} };
   const pluginsToApply = plugins.filter(p => p.transformResourceGroup);
   for (const curPlugin of pluginsToApply) {
     try {
-      logger.trace(
+      logger.debug(
         { plugin: curPlugin.name, method: 'transformResourceGroup' },
         `Applying transformResourceGroup of ${curPlugin.name} plugin...`
       );
       rg = await curPlugin.transformResourceGroup!(rg);
-      logger.trace(
+      logger.debug(
         { plugin: curPlugin.name, method: 'transformResourceGroup' },
         `transformResourceGroup of ${curPlugin.name} plugin was applied successfully.`
       );
@@ -96,16 +99,17 @@ export async function transformResourceGroup(resourceGroup: ResourceGroup): Prom
 }
 
 export async function transformBaseSchema(baseSchema: BaseSchema): Promise<BaseSchema> {
+  logger.info('Applying plugins on base schema.');
   let bs: BaseSchema = baseSchema;
   const pluginsToApply = plugins.filter(p => p.transformBaseSchema);
   for (const curPlugin of pluginsToApply) {
     try {
-      logger.trace(
+      logger.debug(
         { plugin: curPlugin.name, method: 'transformBaseSchema' },
         `Applying transformBaseSchema of ${curPlugin.name} plugin...`
       );
       bs = await curPlugin.transformBaseSchema!(bs);
-      logger.trace(
+      logger.debug(
         { plugin: curPlugin.name, method: 'transformBaseSchema' },
         `transformBaseSchema of ${curPlugin.name} plugin was applied successfully.`
       );
@@ -119,16 +123,17 @@ export async function transformBaseSchema(baseSchema: BaseSchema): Promise<BaseS
 }
 
 export function transformApolloServerPlugins(baseApolloServerPlugins: PluginDefinition[]): PluginDefinition[] {
+  logger.info('Applying plugins on apollo server plugin.');
   let apolloServerPlugins: PluginDefinition[] = baseApolloServerPlugins;
   const pluginsToApply = plugins.filter(p => p.transformApolloServerPlugins);
   for (const curPlugin of pluginsToApply) {
     try {
-      logger.trace(
+      logger.debug(
         { plugin: curPlugin.name, method: 'transformApolloServerPlugins' },
         `Applying transformApolloServerPlugins of ${curPlugin.name} plugin...`
       );
       apolloServerPlugins = curPlugin.transformApolloServerPlugins!(apolloServerPlugins);
-      logger.trace(
+      logger.debug(
         { plugin: curPlugin.name, method: 'transformApolloServerPlugins' },
         `transformApolloServerPlugins of ${curPlugin.name} plugin was applied successfully.`
       );

services/src/modules/registry-schema/resolvers/delete-resources.ts

@@ -20,35 +20,35 @@ export default async function (deletions: ResourceGroupMetadataInput, context: R
     const resourceRepository = getResourceRepository();
 
     try {
-      logger.trace('Fetching latest resource group...');
+      logger.debug('Fetching latest resource group...');
       const { resourceGroup } = await resourceRepository.fetchLatest();
       const existingPolicies = _.cloneDeep(resourceGroup.policies);
 
-      logger.trace('Applying resource group updates...');
+      logger.debug('Applying resource group updates...');
       const newRg = applyResourceGroupDeletions(resourceGroup, deletions);
 
       // TODO: In case of upstream deletion we should force refresh of remote schemas
-      logger.trace('Updating remote gql schemas...');
+      logger.debug('Updating remote gql schemas...');
       updateRemoteGqlSchemas(newRg, context);
 
       const registryRg = _.cloneDeep(newRg);
 
-      logger.trace('Applying plugins for resource group...');
+      logger.debug('Applying plugins for resource group...');
       const gatewayRg = await applyPluginForResourceGroup(newRg);
 
-      logger.trace('Validating resource group...');
+      logger.debug('Validating resource group...');
       validateResourceGroupOrThrow(gatewayRg);
 
-      logger.trace('Creating schema config...');
+      logger.debug('Creating schema config...');
       await createSchemaConfig(gatewayRg);
 
-      logger.trace('Synchronizing policy attachments...');
+      logger.debug('Synchronizing policy attachments...');
       await policyAttachments.sync(existingPolicies, gatewayRg.policies);
 
-      logger.trace('Saving policy attachments...');
+      logger.debug('Saving policy attachments...');
       await policyAttachments.writeToRepo();
 
-      logger.trace('Saving resource group...');
+      logger.debug('Saving resource group...');
       await Promise.all([
         resourceRepository.update(registryRg, { registry: true }),
         resourceRepository.update(gatewayRg),
@@ -58,7 +58,7 @@ export default async function (deletions: ResourceGroupMetadataInput, context: R
       logger.error({ err }, message);
       throw new GraphQLError(message);
     } finally {
-      logger.trace('Removing policy attachments temporary files...');
+      logger.debug('Removing policy attachments temporary files...');
       await policyAttachments.cleanup();
     }
 

services/src/modules/registry-schema/resolvers/rebuild-resource-group.ts

@@ -18,32 +18,32 @@ export default async function (context: RegistryRequestContext, dryRun = false)
     const resourceRepository = getResourceRepository();
 
     try {
-      logger.trace('Fetching latest resource group...');
+      logger.debug('Fetching latest resource group...');
       const { resourceGroup } = await resourceRepository.fetchLatest();
 
       const existingPolicies = _.cloneDeep(resourceGroup.policies);
 
-      logger.trace('Updating remote gql schemas...');
+      logger.debug('Updating remote gql schemas...');
       await updateRemoteGqlSchemas(resourceGroup, context);
 
       const registryRg = _.cloneDeep(resourceGroup);
 
-      logger.trace('Applying plugins for resource group...');
+      logger.debug('Applying plugins for resource group...');
       const gatewayRg = await applyPluginsForResourceGroup(resourceGroup);
 
-      logger.trace('Validating resource group...');
+      logger.debug('Validating resource group...');
       validateResourceGroupOrThrow(gatewayRg);
 
-      logger.trace('Creating schema config...');
+      logger.debug('Creating schema config...');
       await createSchemaConfig(gatewayRg);
 
-      logger.trace('Synchronizing policy attachments...');
+      logger.debug('Synchronizing policy attachments...');
       await policyAttachments.sync(existingPolicies, gatewayRg.policies);
 
       if (!dryRun) {
-        logger.trace('Saving policy attachments...');
+        logger.debug('Saving policy attachments...');
         await policyAttachments.writeToRepo();
-        logger.trace('Saving resource group...');
+        logger.debug('Saving resource group...');
         await Promise.all([
           resourceRepository.update(registryRg, { registry: true }),
           resourceRepository.update(gatewayRg),
@@ -54,7 +54,7 @@ export default async function (context: RegistryRequestContext, dryRun = false)
       logger.error({ err }, message);
       throw err;
     } finally {
-      logger.trace('Removing policy attachments temporary files...');
+      logger.debug('Removing policy attachments temporary files...');
       await policyAttachments.cleanup();
     }
     logger.info(`All resources were ${dryRun ? 'validated' : 'rebuilt'}`);

services/src/modules/registry-schema/resolvers/refresh-remote-schema.ts

@@ -13,7 +13,7 @@ export default async function (url: string, context: RegistryRequestContext) {
   return singleton(async () => {
     logger.info(`Proceeding remote schema refresh request...`);
     try {
-      logger.trace('Fetching latest resource group...');
+      logger.debug('Fetching latest resource group...');
       const { resourceGroup: registryRg } = await registryResourceRepository.fetchLatest();
 
       if (!registryRg.remoteSchemas) {
@@ -30,7 +30,7 @@ export default async function (url: string, context: RegistryRequestContext) {
       const { resourceGroup: gatewayRg } = await gatewayResourceRepository.fetchLatest();
       gatewayRg.remoteSchemas = registryRg.remoteSchemas;
 
-      logger.trace('Saving resource group...');
+      logger.debug('Saving resource group...');
       await Promise.all([
         registryResourceRepository.update(registryRg, { registry: true }),
         registryResourceRepository.update(gatewayRg),