From 8d5192d0fabb3681744ad0cb94844a63b48322b7 Mon Sep 17 00:00:00 2001 From: Sarah Shader Date: Thu, 2 May 2024 15:44:57 -0700 Subject: [PATCH] Add logger --- convex/_generated/api.d.ts | 2 + convex/lib/functions.ts | 135 +++++++++++++++++++++++-------------- convex/lib/logger.ts | 93 +++++++++++++++++++++++++ convex/model/cards.ts | 82 +++++++++++++--------- convex/model/game.ts | 89 ++++++++++-------------- convex/model/player.ts | 14 ++-- convex/model/user.ts | 3 + 7 files changed, 274 insertions(+), 144 deletions(-) create mode 100644 convex/lib/logger.ts diff --git a/convex/_generated/api.d.ts b/convex/_generated/api.d.ts index 9d478a9..4f56516 100644 --- a/convex/_generated/api.d.ts +++ b/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; diff --git a/convex/lib/functions.ts b/convex/lib/functions.ts index a977a69..cdfa743 100644 --- a/convex/lib/functions.ts +++ b/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 export type MutationCtx = CustomCtx export type BaseQueryCtx = CustomCtx export type BaseMutationCtx = CustomCtx -export type TableName = TableNamesInDataModel> -export type Ent = GenericEnt - +export type TableName = TableNamesInDataModel< + DataModelFromSchemaDefinition +> +export type Ent
= GenericEnt< + typeof entDefinitions, + Table +> type RequiredContext = BaseQueryCtx type TransformedContext = { @@ -36,7 +52,7 @@ const addGameInfo = async ( ctx: RequiredContext, args: ObjectType ): Promise => { - 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: {} } + }, +}) diff --git a/convex/lib/logger.ts b/convex/lib/logger.ts new file mode 100644 index 0000000..e738cc4 --- /dev/null +++ b/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> = { + log: ( + kind: K, + metadata: LogMetadataMap[K], + message: string + ) => void + logVerbose: ( + kind: K, + metadata: LogMetadataMap[K], + message: string + ) => void +} + +type Logger> = { + 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 + +/** + * 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 { + 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) + } + }, + } +} diff --git a/convex/model/cards.ts b/convex/model/cards.ts index 986cf92..343d4e3 100644 --- a/convex/model/cards.ts +++ b/convex/model/cards.ts @@ -1,6 +1,7 @@ import { internal } from '../_generated/api' import { Id } from '../_generated/dataModel' -import { MutationCtx, Ent, BaseMutationCtx } from '../lib/functions' +import { BaseMutationCtx, Ent, MutationCtx } from '../lib/functions' +import { LOG_TOPICS } from '../lib/logger' import { findProset, isProset } from '../prosetHelpers' import * as Message from './message' import * as Player from './player' @@ -9,38 +10,48 @@ export const claimSet = async ( ctx: BaseMutationCtx, { game, player }: { game: Ent<'Games'>; player: Ent<'Players'> } ) => { - const currentlySelected = (await game.edge("PlayingCards")).filter(p => p.selectedBy === player._id) + const currentlySelected = (await game.edge('PlayingCards')).filter( + (p) => p.selectedBy === player._id + ) if (isProset(currentlySelected)) { - const prosetId = await ctx.table("Prosets").insert({ - PlayingCards: currentlySelected.map(p => p._id), - PlayerId: player._id + const prosetId = await ctx.table('Prosets').insert({ + PlayingCards: currentlySelected.map((p) => p._id), + PlayerId: player._id, }) await Promise.all( currentlySelected.map(async (card) => { - return ctx.table("PlayingCards").getX(card._id).patch({ + return ctx.table('PlayingCards').getX(card._id).patch({ selectedBy: null, - proset: prosetId + proset: prosetId, }) }) ) await clearSelectSet(ctx, game) - await ctx.table("Players").getX(player._id).patch({ - score: player.score + 1, - }) + await ctx + .table('Players') + .getX(player._id) + .patch({ + score: player.score + 1, + }) } } -export const clearSelectSet = async (ctx: BaseMutationCtx, game: Ent<'Games'>) => { +export const clearSelectSet = async ( + ctx: BaseMutationCtx, + game: Ent<'Games'> +) => { const selectingPlayer = game.selectingPlayer - await ctx.table("Games").getX(game._id).patch({ + await ctx.table('Games').getX(game._id).patch({ selectingPlayer: null, selectionStartTime: null, }) if (selectingPlayer != null) { - const currentlySelected = (await game.edge("PlayingCards")).filter(p => p.selectedBy === selectingPlayer) + const currentlySelected = (await game.edge('PlayingCards')).filter( + (p) => p.selectedBy === selectingPlayer + ) await Promise.all( currentlySelected.map(async (card) => { - return ctx.table("PlayingCards").getX(card._id).patch({ + return ctx.table('PlayingCards').getX(card._id).patch({ selectedBy: null, }) }) @@ -57,7 +68,7 @@ export const maybeClearSelectSet = async ( } if (Date.now() - game.selectionStartTime! > 20 * 1000) { await clearSelectSet(ctx, game) - const player = await ctx.table("Players").getX(game.selectingPlayer) + const player = await ctx.table('Players').getX(game.selectingPlayer) await player.patch({ score: player!.score - 1, }) @@ -68,17 +79,16 @@ export const startSelectSet = async ( ctx: MutationCtx, { game, player }: { game: Ent<'Games'>; player: Ent<'Players'> } ) => { - if (game.selectingPlayer !== null) { return { reason: 'Another player is already selecting!', selectedBy: game.selectingPlayer, } } - await ctx.table("Users").getX(player.UserId).patch({ + await ctx.table('Users').getX(player.UserId).patch({ showOnboarding: false, }) - await ctx.table("Games").getX(game._id).patch({ + await ctx.table('Games').getX(game._id).patch({ selectingPlayer: player._id, selectionStartTime: Date.now(), }) @@ -90,18 +100,18 @@ export const startSelectSet = async ( export const select = async ( ctx: MutationCtx, - { - cardId, - }: { cardId: Id<'PlayingCards'> } + { cardId }: { cardId: Id<'PlayingCards'> } ) => { - const { game, user, player } = ctx; - let currentlySelected = (await game.edge("PlayingCards")).filter(p => p.selectedBy === player._id) + const { game, user, player } = ctx + let currentlySelected = (await game.edge('PlayingCards')).filter( + (p) => p.selectedBy === player._id + ) if (isProset(currentlySelected)) { // don't allow selecting more cards return } - const card = await ctx.table("PlayingCards").getX(cardId); + const card = await ctx.table('PlayingCards').getX(cardId) if (card.selectedBy !== null) { await card.patch({ @@ -113,9 +123,16 @@ export const select = async ( }) } - currentlySelected = (await game.edge("PlayingCards")).filter(p => p.selectedBy === player._id) + currentlySelected = (await game.edge('PlayingCards')).filter( + (p) => p.selectedBy === player._id + ) if (isProset(currentlySelected)) { + ctx.logger.log( + LOG_TOPICS.Game, + { gameId: game._id, userId: user._id }, + 'Found a set' + ) await Message.send(ctx, { content: `⭐️ ${user.name} found a set!`, isPrivate: false, @@ -128,18 +145,21 @@ export const select = async ( } } -export const reveal = async ( - ctx: MutationCtx, -) => { - const { player, user } = ctx +export const reveal = async (ctx: MutationCtx) => { + const { player, user, game } = ctx const systemPlayer = await Player.getSystemPlayer(ctx, player.GameId) + ctx.logger.log( + LOG_TOPICS.Game, + { gameId: game._id, userId: user._id }, + 'Revealing set' + ) await Message.send(ctx, { content: `👀 ${user.name} is revealing a set`, isPrivate: false, }) - await ctx.table("Games").getX(player.GameId).patch({ + await ctx.table('Games').getX(player.GameId).patch({ selectingPlayer: systemPlayer._id, selectionStartTime: Date.now(), }) @@ -153,7 +173,7 @@ export const reveal = async ( const prosetCards = findProset(cards) await Promise.all( prosetCards!.map(async (card) => { - return await ctx.table("PlayingCards").getX(card._id).patch({ + return await ctx.table('PlayingCards').getX(card._id).patch({ selectedBy: systemPlayer._id, }) }) diff --git a/convex/model/game.ts b/convex/model/game.ts index a1ba4fa..a4b38f9 100644 --- a/convex/model/game.ts +++ b/convex/model/game.ts @@ -1,14 +1,24 @@ import { Doc } from '../_generated/dataModel' -import { Ent, QueryCtx, MutationCtx, BaseMutationCtx, BaseQueryCtx } from '../lib/functions' +import { + BaseMutationCtx, + BaseQueryCtx, + Ent, + MutationCtx, + QueryCtx, +} from '../lib/functions' import { GameInfo } from '../types/game_info' import * as Players from './player' export const getInfo = async ( ctx: QueryCtx, - args: { currentPlayer: Ent<'Players'>; game: Ent<'Games'>; user: Ent<'Users'> } + args: { + currentPlayer: Ent<'Players'> + game: Ent<'Games'> + user: Ent<'Users'> + } ): Promise => { const { currentPlayer, game } = args - const allPlayers = await ctx.game.edge("Players") + const allPlayers = await ctx.game.edge('Players') const playerToProsets: Record[][]> = {} for (const player of allPlayers) { if (player.isSystemPlayer) { @@ -17,7 +27,9 @@ export const getInfo = async ( const prosets = await getProsets(ctx, player) playerToProsets[player._id] = prosets } - const otherPlayers = allPlayers.filter((p) => p._id !== currentPlayer._id && !p.isSystemPlayer) + const otherPlayers = allPlayers.filter( + (p) => p._id !== currentPlayer._id && !p.isSystemPlayer + ) return { game, currentPlayer: { @@ -31,87 +43,54 @@ export const getInfo = async ( } } -// export const cleanup = async ( -// { db }: MutationCtx, -// { gameId }: { gameId: Id<'Games'> } -// ) => { -// const allPlayers = await db -// .query('Player') -// .withIndex('ByGame', (q) => q.eq('game', gameId)) -// .collect() -// for (const player of allPlayers) { -// const prosets = await db -// .query('Proset') -// .withIndex('ByPlayer', (q) => q.eq('player', player._id)) -// .collect() -// for (const p of prosets) { -// await db.delete(p._id) -// } -// await db.delete(player._id) -// } -// const cards = await db -// .query('PlayingCard') -// .withIndex('ByGameAndProsetAndRank', (q) => q.eq('game', gameId)) -// .collect() -// for (const c of cards) { -// await db.delete(c._id) -// } -// const game = await db.get(gameId) -// if (game !== null) { -// await db.delete(game._id) -// } -// return null -// } - export const end = async (ctx: MutationCtx, game: Ent<'Games'>) => { if (game.deletionTime !== undefined) { return null } - await ctx.table("Games").getX(game._id).delete() + await ctx.table('Games').getX(game._id).delete() if (game.isPublic) { await createGame(ctx, { isPublic: true }) } - // await ctx.scheduler.runAfter(2000, internal.games.cleanup, { gameId: game._id }) return null } const getProsets = async ( ctx: QueryCtx, - player: Ent<"Players"> + player: Ent<'Players'> ): Promise>>> => { - return player.edge("Prosets").map((proset) => proset.edge("PlayingCards")) + return player.edge('Prosets').map((proset) => proset.edge('PlayingCards')) } export const createGame = async ( ctx: BaseMutationCtx, args: { isPublic: boolean } ) => { - console.time("createGame") - const gameId = await ctx.table("Games").insert({ + ctx.logger.time('createGame') + const gameId = await ctx.table('Games').insert({ name: '', selectingPlayer: null, selectionStartTime: null, inProgress: true, isPublic: args.isPublic, }) - console.timeEnd("createGame") + ctx.logger.timeEndVerbose('createGame') - console.time("createPlayer") + ctx.logger.timeVerbose('createPlayer') await Players.createSystemPlayer(ctx, { gameId }) - console.timeEnd("createPlayer") + ctx.logger.timeEndVerbose('createPlayer') - console.time("createCards") + ctx.logger.timeVerbose('createCards') const cardNumbers = [] for (let i = 1; i <= 63; i += 1) { cardNumbers.push(i) } shuffleArray(cardNumbers) - console.timeLog("createCards", "after shuffle") + ctx.logger.timeLogVerbose('createCards', 'after shuffle') await Promise.all( cardNumbers.map((cardNumber, cardIndex) => { - return ctx.table("PlayingCards").insert({ + return ctx.table('PlayingCards').insert({ GameId: gameId, rank: cardIndex, proset: null, @@ -125,31 +104,31 @@ export const createGame = async ( }) }) ) - console.timeEnd("createCards") + ctx.logger.timeEndVerbose('createCards') return gameId } export const getPublicGame = async (ctx: BaseQueryCtx) => { - const game = await ctx.table('Games', 'ByInProgressPublic', (q) => + const game = await ctx + .table('Games', 'ByInProgressPublic', (q) => q.eq('deletionTime', undefined).eq('isPublic', true) ) .unique() if (game === null) { throw new Error("Couldn't find public game") } - return ctx.table("Games").getX(game._id) + return ctx.table('Games').getX(game._id) } export const getOrCreate = async ( ctx: BaseMutationCtx, { user }: { user: Ent<'Users'> } ) => { - - const players = await ctx.table("Users").getX(user._id).edge("Players"); + const players = await ctx.table('Users').getX(user._id).edge('Players') if (players.length !== 0) { - const player = players[0]; - const game = await player.edge("Game") + const player = players[0] + const game = await player.edge('Game') if (game !== null) { return { gameId: player.GameId, playerId: player._id } } diff --git a/convex/model/player.ts b/convex/model/player.ts index fdbb692..750b147 100644 --- a/convex/model/player.ts +++ b/convex/model/player.ts @@ -8,16 +8,16 @@ export const joinGame = async ( ctx: BaseMutationCtx, { gameId, user }: { gameId: Id<'Games'>; user: Ent<'Users'> } ) => { - console.time("joinGame") - console.time("getPlayer") + ctx.logger.time("joinGame") + ctx.logger.timeVerbose("getPlayer") const allPlayers = await ctx.table("Games").getX(gameId).edgeX("Players") const player = allPlayers.find(p => p.UserId === user._id) ?? null - console.timeEnd("getPlayer") + ctx.logger.timeEndVerbose("getPlayer") if (player !== null) { - console.timeEnd("joinGame") + ctx.logger.timeEndVerbose("joinGame") return { playerId: player._id, gameId: player.GameId } } - console.time("createPlayer") + ctx.logger.timeVerbose("createPlayer") const playerId = await ctx.table("Players").insert({ UserId: user._id, GameId: gameId, @@ -26,8 +26,8 @@ export const joinGame = async ( color: PLAYER_COLORS[Math.floor(Math.random() * PLAYER_COLORS.length)], isSystemPlayer: false, }) - console.timeEnd("createPlayer") - console.timeEnd("joinGame") + ctx.logger.timeEndVerbose("createPlayer") + ctx.logger.timeEnd("joinGame") return { playerId, gameId } } diff --git a/convex/model/user.ts b/convex/model/user.ts index 924509e..de40aeb 100644 --- a/convex/model/user.ts +++ b/convex/model/user.ts @@ -6,6 +6,7 @@ import { } from 'unique-names-generator' import { Id } from '../_generated/dataModel' import { BaseMutationCtx, BaseQueryCtx, Ent } from '../lib/functions' +import { LOG_TOPICS } from '../lib/logger' const customConfig: Config = { dictionaries: [adjectives, animals], @@ -38,6 +39,7 @@ export const getOrCreate = async ( identifier: identity.tokenIdentifier, isGuest: false, }) + ctx.logger.log(LOG_TOPICS.User, { userId }, "New user created") return { userId } } const userId = await db.insert('Users', { @@ -80,6 +82,7 @@ export const completeOnboarding = async ( ctx: BaseMutationCtx, user: Ent<"Users"> ) => { + ctx.logger.log(LOG_TOPICS.User, { userId: user._id }, "Onboarding completed") await ctx.table("Users").getX(user._id).patch({ showOnboarding: false, })