refactor: logs and tracings (#313)

Author: TextC0de

src/authn/index.ts

@@ -140,8 +140,6 @@ export const upsertUserFromRequest = async ({
     throw new Error("Could not parse profile info", profileInfo.error);
   }
 
-  logger.info(`Updating profile Info for user ID: ${sub}`);
-
   return upsertUserProfileInfo(DB, profileInfo.data, logger);
 };
 

src/builder.ts

@@ -1,15 +1,12 @@
 import SchemaBuilder from "@pothos/core";
 import AuthzPlugin from "@pothos/plugin-authz";
 import DataloaderPlugin from "@pothos/plugin-dataloader";
-import TracingPlugin, { wrapResolver } from "@pothos/plugin-tracing";
+import TracingPlugin, { isRootField } from "@pothos/plugin-tracing";
 import { DateResolver, DateTimeResolver } from "graphql-scalars";
 
 import * as rules from "~/authz";
-import { createLogger } from "~/logging";
 import { Context } from "~/types";
 
-const tracingLogger = createLogger("tracing");
-
 export const builder = new SchemaBuilder<{
   Context: Context;
   AuthZRule: keyof typeof rules;
@@ -26,13 +23,22 @@ export const builder = new SchemaBuilder<{
 }>({
   plugins: [TracingPlugin, AuthzPlugin, DataloaderPlugin],
   tracing: {
-    default: () => true,
-    wrap: (resolver, options, config) =>
-      wrapResolver(resolver, (error, duration) => {
-        tracingLogger.debug(
-          `[TRACING] ${config.parentType}.${config.name} in ${duration}ms`,
-        );
-      }),
+    default: (config) => isRootField(config),
+    wrap: (resolver) => {
+      return async (parent, args, context, info) => {
+        const start = Date.now();
+        const result = await resolver(parent, args, context, info);
+        const duration = Date.now() - start;
+
+        context.logger.debug("[TRACING]", {
+          path: info.path,
+          duration,
+          operation: info.operation?.operation,
+        });
+
+        return result;
+      };
+    },
   },
 });
 

src/context.ts

@@ -34,7 +34,7 @@ export const createGraphqlContext = async ({
   Env & {
     logger: Logger;
   }): Promise<Context> => {
-  logger.info("graphql-params", params);
+  logger.info("graphql-params", JSON.stringify(params, null, 2));
 
   if (!MAIL_QUEUE) {
     throw new Error("Missing MAIL_QUEUE");

src/datasources/queries/users.ts

@@ -63,8 +63,6 @@ export const upsertUserProfileInfo = async (
       throw new Error("User operation failed");
     }
 
-    logger.info(result.length > 1 ? "User updated" : "New user created");
-
     return selectUsersSchema.parse(updatedUser);
   } catch (error) {
     logger.error("Error in user operation", { error });

src/index.ts

@@ -1,6 +1,7 @@
 import { useMaskedErrors } from "@envelop/core";
 import { useImmediateIntrospection } from "@envelop/immediate-introspection";
 import { authZEnvelopPlugin } from "@graphql-authz/envelop-plugin";
+import { format } from "date-fns";
 import { createYoga, maskError } from "graphql-yoga";
 
 import { Env } from "worker-configuration";
@@ -78,6 +79,10 @@ export default {
       traceId,
     });
 
+    const start = Date.now();
+
+    logger.info(`⛳️ — Start Request ${format(start, "HH:mm:ss.SSS")}`);
+
     logTraceId(req, logger);
 
     logPossibleUserIdFromJWT(req, logger);
@@ -94,7 +99,11 @@ export default {
 
     response.headers.set("x-api-trace-id", traceId);
 
-    logger.info("🏁 — End Request");
+    const end = Date.now();
+
+    logger.info(
+      `🏁 — End Request ${format(end, "HH:mm:ss.SSS")} (${end - start}ms)`,
+    );
 
     return response;
   },