Add logger

convex/_generated/api.d.ts

@@ -19,6 +19,7 @@ import type * as dealCards from "../dealCards.js";
 import type * as functions from "../functions.js";
 import type * as games from "../games.js";
 import type * as lib_functions from "../lib/functions.js";
+import type * as lib_logger from "../lib/logger.js";
 import type * as lib_middlewareUtils from "../lib/middlewareUtils.js";
 import type * as message from "../message.js";
 import type * as model_cards from "../model/cards.js";
@@ -48,6 +49,7 @@ declare const fullApi: ApiFromModules<{
   functions: typeof functions;
   games: typeof games;
   "lib/functions": typeof lib_functions;
+  "lib/logger": typeof lib_logger;
   "lib/middlewareUtils": typeof lib_middlewareUtils;
   message: typeof message;
   "model/cards": typeof model_cards;

convex/lib/functions.ts

@@ -1,13 +1,25 @@
+import { GenericEnt, entsTableFactory } from 'convex-ents'
+import {
+  CustomCtx,
+  customCtx,
+  customMutation,
+  customQuery,
+} from 'convex-helpers/server/customFunctions'
+import {
+  DataModelFromSchemaDefinition,
+  TableNamesInDataModel,
+} from 'convex/server'
 import { ObjectType, v } from 'convex/values'
-import { Doc } from '../_generated/dataModel'
-import { internalMutation, internalQuery, mutation, query } from '../_generated/server'
+import {
+  internalMutation,
+  internalQuery,
+  mutation,
+  query,
+} from '../_generated/server'
 import * as Player from '../model/player'
 import * as User from '../model/user'
-import { customQuery, customMutation, customCtx } from "convex-helpers/server/customFunctions"
-import { GenericEnt, entsTableFactory,  } from "convex-ents";
-import { entDefinitions, default as schema }from "../schema";
-import { CustomCtx } from "convex-helpers/server/customFunctions";
-import { DataModelFromSchemaDefinition, TableNamesInDataModel } from 'convex/server'
+import { entDefinitions, default as schema } from '../schema'
+import { setupLogger } from './logger'
 
 // ----------------------------------------------------------------------
 // Fill these in:
@@ -16,9 +28,13 @@ export type QueryCtx = CustomCtx<typeof queryWithGame>
 export type MutationCtx = CustomCtx<typeof mutationWithGame>
 export type BaseQueryCtx = CustomCtx<typeof queryWithEnt>
 export type BaseMutationCtx = CustomCtx<typeof mutationWithEnt>
-export type TableName = TableNamesInDataModel<DataModelFromSchemaDefinition<typeof schema>>
-export type Ent<Table extends TableName> = GenericEnt<typeof entDefinitions, Table>
-
+export type TableName = TableNamesInDataModel<
+  DataModelFromSchemaDefinition<typeof schema>
+>
+export type Ent<Table extends TableName> = GenericEnt<
+  typeof entDefinitions,
+  Table
+>
 
 type RequiredContext = BaseQueryCtx
 type TransformedContext = {
@@ -36,7 +52,7 @@ const addGameInfo = async (
   ctx: RequiredContext,
   args: ObjectType<typeof inGameValidator>
 ): Promise<TransformedContext> => {
-  const game = await ctx.table("Games").getX(args.gameId);
+  const game = await ctx.table('Games').getX(args.gameId)
   const user = await User.get(ctx, { sessionId: args.sessionId })
   const player = await Player.getPlayer(ctx, { user, gameId: args.gameId })
   if (game === null) {
@@ -45,62 +61,79 @@ const addGameInfo = async (
   return { player, game, user }
 }
 
-export const internalQueryWithEnt = customQuery(internalQuery, customCtx((ctx) => {
-  return { table: entsTableFactory(ctx, entDefinitions) }
-}))
-
-export const internalMutationWithEnt = customMutation(internalMutation, customCtx((ctx) => {
-  return { table: entsTableFactory(ctx, entDefinitions) }
-}))
+export const internalQueryWithEnt = customQuery(
+  internalQuery,
+  customCtx((ctx) => {
+    const logger = setupLogger()
+    return { table: entsTableFactory(ctx, entDefinitions), logger }
+  })
+)
 
-export const queryWithEnt = customQuery(query, customCtx((ctx) => {
-  return { table: entsTableFactory(ctx, entDefinitions) }
-}))
+export const internalMutationWithEnt = customMutation(
+  internalMutation,
+  customCtx((ctx) => {
+    const logger = setupLogger()
+    return { table: entsTableFactory(ctx, entDefinitions), logger }
+  })
+)
 
-export const mutationWithEnt = customMutation(mutation, customCtx((ctx) => {
-  console.time("middleware")
-  const result = { table: entsTableFactory(ctx, entDefinitions) }
-  console.timeEnd("middleware")
-  return result
-}))
+export const queryWithEnt = customQuery(
+  query,
+  customCtx((ctx) => {
+    const logger = setupLogger()
+    return { table: entsTableFactory(ctx, entDefinitions), logger }
+  })
+)
 
+export const mutationWithEnt = customMutation(
+  mutation,
+  customCtx((ctx) => {
+    const logger = setupLogger()
+    logger.timeVerbose('middleware')
+    const result = { table: entsTableFactory(ctx, entDefinitions), logger }
+    logger.timeEndVerbose('middleware')
+    return result
+  })
+)
 
 export const queryWithGame = customQuery(query, {
   args: inGameValidator,
   input: async (ctx, args) => {
-    console.time("middleware")
-    const table = entsTableFactory(ctx, entDefinitions);
-    const gameInfo = await addGameInfo({...ctx, table}, args);
-    console.timeEnd("middleware")
-    return { ctx: {...gameInfo, table} , args: {} };
-  }
-});
+    const table = entsTableFactory(ctx, entDefinitions)
+    const logger = setupLogger()
+    const gameInfo = await addGameInfo({ ...ctx, table, logger }, args)
+    return { ctx: { ...gameInfo, table, logger }, args: {} }
+  },
+})
 
 export const mutationWithGame = customMutation(mutation, {
   args: inGameValidator,
   input: async (ctx, args) => {
-    console.time("middleware")
-    const table = entsTableFactory(ctx, entDefinitions);
-    const gameInfo = await addGameInfo({...ctx, table}, args);
-    console.timeEnd("middleware")
-    return { ctx: {...gameInfo, table} , args: {} };
-  }
-});
+    const logger = setupLogger()
+    logger.timeVerbose('middleware')
+    const table = entsTableFactory(ctx, entDefinitions)
+    const gameInfo = await addGameInfo({ ...ctx, table, logger }, args)
+    logger.timeEndVerbose('middleware')
+    return { ctx: { ...gameInfo, table, logger }, args: {} }
+  },
+})
 
 export const internalQueryWithGame = customQuery(internalQuery, {
   args: inGameValidator,
   input: async (ctx, args) => {
-    const table = entsTableFactory(ctx, entDefinitions);
-    const gameInfo = await addGameInfo({...ctx, table}, args);
-    return { ctx: {...gameInfo, table} , args: {} };
-  }
-});
+    const table = entsTableFactory(ctx, entDefinitions)
+    const logger = setupLogger()
+    const gameInfo = await addGameInfo({ ...ctx, table, logger }, args)
+    return { ctx: { ...gameInfo, table, logger }, args: {} }
+  },
+})
 
 export const internalMutationWithGame = customMutation(internalMutation, {
   args: inGameValidator,
   input: async (ctx, args) => {
-    const table = entsTableFactory(ctx, entDefinitions);
-    const gameInfo = await addGameInfo({...ctx, table}, args);
-    return { ctx: {...gameInfo, table} , args: {} };
-  }
-});
+    const table = entsTableFactory(ctx, entDefinitions)
+    const logger = setupLogger()
+    const gameInfo = await addGameInfo({ ...ctx, table, logger }, args)
+    return { ctx: { ...gameInfo, table, logger }, args: {} }
+  },
+})

convex/lib/logger.ts

@@ -0,0 +1,93 @@
+import { Id } from '../_generated/dataModel'
+
+// begin specific configuration for my app
+export const LOG_TOPICS = {
+  Game: 'GAME',
+  User: 'USER',
+} as const
+
+export type LogTopicToMetadata = {
+  GAME: {
+    gameId: Id<'Games'>
+    userId: Id<'Users'>
+  }
+  USER: {
+    userId: Id<'Users'>
+  }
+}
+// end specific configuration for my app
+
+// Generic library for structured logging
+type LoggerWithTopics<LogMetadataMap extends Record<string, any>> = {
+  log: <K extends keyof LogMetadataMap>(
+    kind: K,
+    metadata: LogMetadataMap[K],
+    message: string
+  ) => void
+  logVerbose: <K extends keyof LogMetadataMap>(
+    kind: K,
+    metadata: LogMetadataMap[K],
+    message: string
+  ) => void
+}
+
+type Logger<LogMetadataMap extends Record<string, any>> = {
+  time: (label: string) => void
+  timeVerbose: (label: string) => void
+  timeLog: (label: string, message: string) => void
+  timeLogVerbose: (label: string, message: string) => void
+  timeEnd: (label: string) => void
+  timeEndVerbose: (label: string) => void
+} & LoggerWithTopics<LogMetadataMap>
+
+/**
+ * This supports type safe logging of structured messages, e.g.
+ * ctx.logger.log(LOG_TOPICS.User, { userId: user._id }, "Created")
+ *
+ * This also supports verbose logging sampled per function execution by the `VERBOSE_LOG_FRACTION`
+ * env variable, which can be overridden by setting `VERBOSE_LOG` to true.
+ * @returns
+ */
+export function setupLogger(): Logger<LogTopicToMetadata> {
+  const verboseLogFraction = parseFloat(process.env.VERBOSE_LOG_FRACTION ?? '0')
+  const verboseLogOverride =
+    process.env.VERBOSE_LOG === 'true' ? true : undefined
+  const verbose =
+    verboseLogOverride !== undefined
+      ? verboseLogOverride
+      : Math.random() < verboseLogFraction
+  return {
+    log: (kind, metadata, message) => {
+      console.log(JSON.stringify({ topic: kind, metadata, message }))
+    },
+    logVerbose: (kind, metadata, message) => {
+      if (verbose) {
+        console.log(JSON.stringify({ topic: kind, metadata, message }))
+      }
+    },
+    time: (label: string) => {
+      console.time(label)
+    },
+    timeLog: (label: string, message: string) => {
+      console.timeLog(label, message)
+    },
+    timeEnd: (label: string) => {
+      console.timeEnd(label)
+    },
+    timeVerbose: (label: string) => {
+      if (verbose) {
+        console.time(label)
+      }
+    },
+    timeEndVerbose: (label: string) => {
+      if (verbose) {
+        console.timeEnd(label)
+      }
+    },
+    timeLogVerbose: (label: string, message: string) => {
+      if (verbose) {
+        console.timeLog(label, message)
+      }
+    },
+  }
+}