[CORL-540] Logging improvements (#2565)

* fix: enhanced errors around story creation

* feat: enhanced child loggers

* feat: logging enhancements

src/core/server/graph/common/context.ts

@@ -4,6 +4,7 @@ import uuid from "uuid";
 import { LanguageCode } from "coral-common/helpers/i18n/locales";
 import { Config } from "coral-server/config";
 import logger, { Logger } from "coral-server/logger";
+import { PersistedQuery } from "coral-server/models/queries";
 import { User } from "coral-server/models/user";
 import { I18n } from "coral-server/services/i18n";
 import { AugmentedRedis } from "coral-server/services/redis";
@@ -18,6 +19,7 @@ export interface CommonContextOptions {
   logger?: Logger;
   lang?: LanguageCode;
   disableCaching?: boolean;
+  persisted?: PersistedQuery;
   config: Config;
   i18n: I18n;
   pubsub: RedisPubSub;
@@ -28,6 +30,7 @@ export interface CommonContextOptions {
 export default class CommonContext {
   public readonly user?: User;
   public readonly req?: Request;
+  public readonly persisted?: PersistedQuery;
   public readonly id: string;
   public readonly config: Config;
   public readonly i18n: I18n;
@@ -45,6 +48,7 @@ export default class CommonContext {
     logger: log = logger,
     user,
     req,
+    persisted,
     config,
     i18n,
     lang = i18n.getDefaultLang(),
@@ -54,13 +58,17 @@ export default class CommonContext {
     disableCaching = false,
   }: CommonContextOptions) {
     this.id = id;
-    this.logger = log.child({
-      context: "graph",
-      contextID: id,
-    });
+    this.logger = log.child(
+      {
+        context: "graph",
+        contextID: id,
+      },
+      true
+    );
     this.now = now;
     this.user = user;
     this.req = req;
+    this.persisted = persisted;
     this.config = config;
     this.i18n = i18n;
     this.lang = lang;

src/core/server/graph/common/extensions/LoggerExtension.ts

@@ -7,7 +7,8 @@ import {
 import now from "performance-now";
 
 import CommonContext from "coral-server/graph/common/context";
-import { getOperationMetadata } from "./helpers";
+
+import { getOperationMetadata, getPersistedQueryMetadata } from "./helpers";
 
 export function logError(ctx: CommonContext, err: GraphQLError) {
   ctx.logger.error({ err }, "graphql query error");
@@ -16,12 +17,20 @@ export function logError(ctx: CommonContext, err: GraphQLError) {
 export function logQuery(
   ctx: CommonContext,
   document: DocumentNode,
+  persisted = ctx.persisted,
   responseTime?: number
 ) {
-  ctx.logger.debug(
+  ctx.logger.info(
     {
       responseTime,
-      ...getOperationMetadata(document),
+      authenticated: ctx.user ? true : false,
+      ...(persisted
+        ? // A persisted query was provided, we can pull the operation metadata
+          // out from the persisted object.
+          getPersistedQueryMetadata(persisted)
+        : // A persisted query was not provided, parse the operation metadata
+          // out from the document.
+          getOperationMetadata(document)),
     },
     "graphql query"
   );
@@ -44,6 +53,7 @@ export class LoggerExtension implements GraphQLExtension<CommonContext> {
         logQuery(
           o.executionArgs.contextValue,
           o.executionArgs.document,
+          undefined,
           responseTime
         );
       };

src/core/server/graph/common/extensions/helpers.ts

@@ -1,6 +1,26 @@
-import { DocumentNode, OperationDefinitionNode } from "graphql";
+import {
+  DocumentNode,
+  OperationDefinitionNode,
+  OperationTypeNode,
+} from "graphql";
 
-export function getOperationMetadata(doc: DocumentNode) {
+import { PersistedQuery } from "coral-server/models/queries";
+
+export interface OperationMetadata {
+  operationName: string;
+  operation: OperationTypeNode;
+}
+
+/**
+ * getOperationMetadata will extract the operation metadata from the document
+ * node.
+ *
+ * @param doc the document node that can be used to extract operation metadata
+ *            from
+ */
+export const getOperationMetadata = (
+  doc: DocumentNode
+): Partial<OperationMetadata> => {
   if (doc.kind === "Document") {
     const operationDefinition = doc.definitions.find(
       ({ kind }) => kind === "OperationDefinition"
@@ -19,4 +39,30 @@ export function getOperationMetadata(doc: DocumentNode) {
   }
 
   return {};
+};
+
+interface PersistedQueryOperationMetadata extends OperationMetadata {
+  persistedQueryID: string;
+  persistedQueryBundle: string;
+  persistedQueryVersion: string;
 }
+
+/**
+ * getPersistedQueryMetadata will remap the persisted query to the operation
+ * metadata.
+ *
+ * @param persisted persisted query to remap to operation metadata
+ */
+export const getPersistedQueryMetadata = ({
+  id: persistedQueryID,
+  operation,
+  operationName,
+  bundle: persistedQueryBundle,
+  version: persistedQueryVersion,
+}: PersistedQuery): PersistedQueryOperationMetadata => ({
+  persistedQueryID,
+  persistedQueryBundle,
+  persistedQueryVersion,
+  operation,
+  operationName,
+});

src/core/server/graph/common/persisted/mapper.ts

@@ -29,7 +29,7 @@ export async function getPersistedQuery(
     // empty.
     !(payload.query === "PERSISTED_QUERY" || payload.query === "")
   ) {
-    return null;
+    return undefined;
   }
 
   const query = await cache.get(payload.id);

src/core/server/graph/tenant/context.ts

@@ -49,7 +49,7 @@ export default class TenantContext extends CommonContext {
     super({
       ...options,
       lang: tenant.locale,
-      logger: logger.child({ tenantID: tenant.id }),
+      logger: logger.child({ tenantID: tenant.id }, true),
     });
 
     this.tenant = tenant;

src/core/server/graph/tenant/subscriptions/server.ts

@@ -35,9 +35,10 @@ import {
   logQuery,
 } from "coral-server/graph/common/extensions";
 import { getOperationMetadata } from "coral-server/graph/common/extensions/helpers";
-import { getPersistedQuery } from "coral-server/graph/tenant/persisted";
+import { getPersistedQuery } from "coral-server/graph/common/persisted";
 import { GQLUSER_ROLE } from "coral-server/graph/tenant/schema/__generated__/types";
 import logger from "coral-server/logger";
+import { PersistedQuery } from "coral-server/models/queries";
 import { hasStaffRole } from "coral-server/models/user/helpers";
 import { extractTokenFromRequest } from "coral-server/services/jwt";
 
@@ -166,7 +167,10 @@ export function onConnect(options: OnConnectOptions): OnConnectFn {
 
 export type FormatResponseOptions = Pick<AppOptions, "metrics">;
 
-export function formatResponse({ metrics }: FormatResponseOptions) {
+export function formatResponse(
+  { metrics }: FormatResponseOptions,
+  persisted?: PersistedQuery
+) {
   return (
     value: ExecutionResult,
     { context, query }: ExecutionParams<TenantContext>
@@ -177,7 +181,7 @@ export function formatResponse({ metrics }: FormatResponseOptions) {
     }
 
     // Log out the query.
-    logQuery(context, query);
+    logQuery(context, query, persisted);
 
     // Increment the metrics if enabled.
     if (metrics) {
@@ -217,15 +221,12 @@ export function onOperation(options: OnOperationOptions) {
     message: OperationMessage,
     params: ExecutionParams<TenantContext>
   ) => {
-    // Attach the response formatter.
-    params.formatResponse = formatResponse(options);
-
     // Handle the payload if it is a persisted query.
-    const query = await getPersistedQuery(
+    const persisted = await getPersistedQuery(
       options.persistedQueryCache,
       message.payload
     );
-    if (!query) {
+    if (!persisted) {
       // Check to see if this is from an ADMIN token which is allowed to run
       // un-persisted queries.
       if (
@@ -241,9 +242,12 @@ export function onOperation(options: OnOperationOptions) {
     } else {
       // The query was found for this operation, replace the query with the one
       // provided.
-      params.query = query.query;
+      params.query = persisted.query;
     }
 
+    // Attach the response formatter.
+    params.formatResponse = formatResponse(options, persisted);
+
     return params;
   };
 }