diff --git a/docs/documentation/debugging.md b/docs/documentation/debugging.md index d27eb4e4e..e68c4202b 100644 --- a/docs/documentation/debugging.md +++ b/docs/documentation/debugging.md @@ -36,8 +36,8 @@ const client = Client({ ### Custom metadata in game logs -It can sometimes be helpful to surface some metadata during a move. -You can do this by using the log plugin. For example, +It can sometimes be helpful to surface metadata during a move or a lifecycle +hook. You can do this by using the log plugin. For example, ```js const move = ({ log }) => { @@ -46,7 +46,9 @@ const move = ({ log }) => { ``` This metadata is stored in the `log` client property and displayed -in the Log section of the debug panel. +in the Log section of the debug panel. Metadata set in `onBegin`, `onEnd`, or +`onMove` is attached to the log entry for the move or event that triggered the +hook. If multiple hooks update the same entry, the last metadata set is used. ### Redux diff --git a/src/core/flow.ts b/src/core/flow.ts index 56ac9c865..7f2d94d70 100644 --- a/src/core/flow.ts +++ b/src/core/flow.ts @@ -34,6 +34,7 @@ import type { } from '../types'; import { GameMethod } from './game-methods'; import { supportDeprecatedMoveLimit } from './backwards-compatibility'; +import { consumeLogMetadata } from '../plugins/plugin-log'; /** * Flow @@ -110,8 +111,40 @@ export function Flow({ }; }; - const appendLogEntry = (state: State, logEntry: LogEntry): LogEntry[] => - disableLog ? state.deltalog || [] : [...(state.deltalog || []), logEntry]; + const appendLogEntry = (state: State, logEntry: LogEntry): LogEntry[] => { + if (disableLog) return state.deltalog || []; + + const metadata = consumeLogMetadata(state.plugins?.log?.data); + if (metadata !== undefined) logEntry = { ...logEntry, metadata }; + + return [...(state.deltalog || []), logEntry]; + }; + + const isPhaseTransitionLogEntry = (entry: LogEntry) => + entry.action.type === 'GAME_EVENT' && + (entry.action.payload.type === 'endPhase' || + entry.action.payload.type === 'setPhase'); + + const updateLogEntry = ( + state: State, + predicate: (entry: LogEntry) => boolean = () => true, + ): State => { + if (disableLog) return state; + + const { deltalog = [] } = state; + for (let index = deltalog.length - 1; index >= 0; index--) { + if (!predicate(deltalog[index])) continue; + + const metadata = consumeLogMetadata(state.plugins?.log?.data); + if (metadata === undefined) return state; + + const updatedDeltalog = [...deltalog]; + updatedDeltalog[index] = { ...updatedDeltalog[index], metadata }; + return { ...state, deltalog: updatedDeltalog }; + } + + return state; + }; const wrapped = { onEnd: HookWrapper(onEnd, GameMethod.GAME_ON_END), @@ -214,6 +247,7 @@ export function Flow({ automatic?: boolean; playerID?: PlayerID; force?: boolean; + logAction?: ActionShape.GameEvent; }[], ): State { const phasesEnded = new Set(); @@ -314,7 +348,7 @@ export function Flow({ next.push({ fn: StartTurn }); - return { ...state, G, ctx }; + return updateLogEntry({ ...state, G, ctx }, isPhaseTransitionLogEntry); } function StartTurn(state: State, { currentPlayer }): State { @@ -338,7 +372,14 @@ export function Flow({ const G = phaseConfig.turn.wrapped.onBegin({ ...state, ctx }); - return { ...state, G, ctx, _undo: [], _redo: [] } as State; + const stateWithTurn = { ...state, G, ctx, _undo: [], _redo: [] } as State; + const hasPhaseTransition = (stateWithTurn.deltalog || []).some((entry) => + isPhaseTransitionLogEntry(entry), + ); + return updateLogEntry( + stateWithTurn, + hasPhaseTransition ? isPhaseTransitionLogEntry : () => true, + ); } //////////// @@ -480,7 +521,8 @@ export function Flow({ // End // ///////// - function EndGame(state: State, { arg, phase }): State { + function EndGame(state: State, { arg, phase, automatic, logAction }): State { + const { turn } = state.ctx; state = EndPhase(state, { phase }); if (arg === undefined) { @@ -492,7 +534,23 @@ export function Flow({ // Run game end hook. const G = wrapped.onEnd(state); - return { ...state, G }; + // Automatic game endings historically do not add a separate endGame log + // entry. Attach their hook metadata to the canonical event that triggered + // the ending instead. + if (automatic) { + return updateLogEntry({ ...state, G }); + } + + const action = logAction || gameEvent('endGame', arg); + const { _stateID } = state; + const logEntry: LogEntry = { + action, + _stateID, + turn, + phase, + }; + const deltalog = appendLogEntry(state, logEntry); + return { ...state, G, deltalog }; } function EndPhase( @@ -759,7 +817,10 @@ export function Flow({ playerID, move: { name: type, args }, }); - state = { ...state, G }; + state = updateLogEntry( + { ...state, G }, + (entry) => entry.action.type === 'MAKE_MOVE', + ); const events = [{ fn: OnMove }]; @@ -793,10 +854,22 @@ export function Flow({ function SetPhaseEvent( state: State, - _playerID: PlayerID, + playerID: PlayerID, newPhase: string, + logAction?: ActionShape.GameEvent, ): State { - return Process(state, [ + const startsFirstPhase = state.ctx.phase === null && newPhase in phaseMap; + if (startsFirstPhase) { + const logEntry: LogEntry = { + action: logAction || gameEvent('setPhase', [newPhase], playerID), + _stateID: state._stateID, + turn: state.ctx.turn, + phase: state.ctx.phase, + }; + state = { ...state, deltalog: appendLogEntry(state, logEntry) }; + } + + state = Process(state, [ { fn: EndPhase, phase: state.ctx.phase, @@ -804,6 +877,31 @@ export function Flow({ arg: { next: newPhase }, }, ]); + + // The implicit initial endTurn is logged after setPhase. Keep the public + // log order consistent with other events, where the triggering event is + // the final entry. + if (startsFirstPhase) { + const { deltalog = [] } = state; + const index = deltalog.findIndex( + (entry) => + entry.action.type === 'GAME_EVENT' && + entry.action.payload.type === 'setPhase', + ); + if (index !== -1) { + const logEntry = deltalog[index]; + state = { + ...state, + deltalog: [ + ...deltalog.slice(0, index), + ...deltalog.slice(index + 1), + logEntry, + ], + }; + } + } + + return state; } function EndPhaseEvent(state: State): State { @@ -830,9 +928,21 @@ export function Flow({ ]); } - function EndGameEvent(state: State, _playerID: PlayerID, arg: any): State { + function EndGameEvent( + state: State, + _playerID: PlayerID, + args: any, + logAction?: ActionShape.GameEvent, + ): State { + const arg = Array.isArray(args) ? args[0] : args; return Process(state, [ - { fn: EndGame, turn: state.ctx.turn, phase: state.ctx.phase, arg }, + { + fn: EndGame, + turn: state.ctx.turn, + phase: state.ctx.phase, + arg, + logAction, + }, ]); } @@ -878,6 +988,18 @@ export function Flow({ function ProcessEvent(state: State, action: ActionShape.GameEvent): State { const { type, playerID, args } = action.payload; if (typeof eventHandlers[type] !== 'function') return state; + + // Preserve the original argument shape and player ID in synthetic log + // entries, while ensuring credentials are never persisted. + const logAction = gameEvent(type, args, playerID); + if (type === 'endGame') { + return EndGameEvent(state, playerID, args, logAction); + } + if (type === 'setPhase') { + const newPhase = Array.isArray(args) ? args[0] : args; + return SetPhaseEvent(state, playerID, newPhase, logAction); + } + return eventHandlers[type]( state, playerID, diff --git a/src/core/reducer.ts b/src/core/reducer.ts index f1b1600d1..03ecb640b 100644 --- a/src/core/reducer.ts +++ b/src/core/reducer.ts @@ -26,10 +26,11 @@ import type { TransientState, Undo, } from '../types'; -import { gameEvent, stripTransients } from './action-creators'; +import { stripTransients } from './action-creators'; import { ActionErrorType, UpdateErrorType } from './errors'; import { applyPatch } from 'rfc6902'; import { RemovePlayer } from './turn-order'; +import { consumeLogMetadata } from '../plugins/plugin-log'; /** * Check if the payload for the passed action contains a playerID. @@ -155,7 +156,7 @@ function initializeDeltalog( phase: state.ctx.phase, }; - const pluginLogMetadata = state.plugins.log.data.metadata; + const pluginLogMetadata = consumeLogMetadata(state.plugins.log.data); if (pluginLogMetadata !== undefined) { logEntry.metadata = pluginLogMetadata; } @@ -172,89 +173,6 @@ function initializeDeltalog( }; } -/** - * Get the event type used in the log for a directly dispatched game event. - */ -function getLogEventType(eventType: string): string | undefined { - switch (eventType) { - case 'endTurn': - case 'pass': { - return 'endTurn'; - } - case 'endPhase': - case 'setPhase': { - return 'endPhase'; - } - case 'endStage': - case 'setStage': { - return 'endStage'; - } - case 'endGame': { - return 'endGame'; - } - } -} - -/** - * Events whose flow implementation never appends a log entry even though their - * hooks run: `endGame` is never logged, and `setPhase` starting a phase from - * `ctx.phase === null` returns before `EndPhase` reaches its log entry. - * Other events either produce a canonical entry or run no hooks at all. - */ -const EVENTS_WITHOUT_LOG_ENTRY = new Set(['endGame', 'setPhase']); - -/** - * Add metadata set by the log plugin to the canonical log entry for an event. - * If the event never produces an entry of its own, add one for the dispatched - * event, whether or not metadata was set, so the log shape doesn’t depend on - * what a hook happened to do. - */ -function addLogMetadata( - state: State, - action: ActionShape.GameEvent, - actionState: State, - game: Game, -): State { - const metadata = state.plugins.log?.data.metadata; - const eventType = getLogEventType(action.payload.type); - - if (game.disableLog || eventType === undefined) { - return state; - } - - // GAME_EVENT processing initializes deltalog before running the flow. - const { deltalog } = state; - const eventEntry = deltalog.findIndex( - (entry) => - entry.action.type === Actions.GAME_EVENT && - entry.action.payload.type === eventType, - ); - - if (eventEntry === -1) { - if (!EVENTS_WITHOUT_LOG_ENTRY.has(action.payload.type)) return state; - // Recreate the action without credentials so they are never persisted. - const { type, args, playerID } = action.payload; - const logEntry: LogEntry = { - action: gameEvent(type, args, playerID), - _stateID: actionState._stateID, - turn: actionState.ctx.turn, - phase: actionState.ctx.phase, - }; - if (metadata !== undefined) logEntry.metadata = metadata; - return { ...state, deltalog: [...deltalog, logEntry] }; - } - - if (metadata === undefined) return state; - - const updatedDeltalog = [...deltalog]; - updatedDeltalog[eventEntry] = { - ...updatedDeltalog[eventEntry], - metadata, - }; - - return { ...state, deltalog: updatedDeltalog }; -} - /** * Remove metadata set during an action that was rejected. */ @@ -441,7 +359,6 @@ export function CreateGameReducer({ // Process event. let newState = game.flow.processEvent(state, action); - newState = addLogMetadata(newState, action, oldState, game); // Execute plugins. let stateWithError: TransientState | undefined; diff --git a/src/plugins/plugin-log.test.ts b/src/plugins/plugin-log.test.ts index beca1da5f..d7d14ba7a 100644 --- a/src/plugins/plugin-log.test.ts +++ b/src/plugins/plugin-log.test.ts @@ -11,7 +11,132 @@ import { TurnOrder } from '../core/turn-order'; import type { Game } from '../types'; describe('log-metadata', () => { - test.todo('preserves metadata from hooks triggered by moves'); + test('preserves metadata from a hook triggered by a move-queued event', () => { + const game: Game = { + moves: { + finish: ({ events }) => events.endTurn(), + }, + turn: { + onEnd: ({ log }) => { + log.setMetadata({ message: 'turn ended' }); + }, + }, + }; + const client = Client({ game }); + + client.moves.finish(); + + const log = client.getState().log; + const move = log.find((entry) => entry.action.type === 'MAKE_MOVE'); + const endTurn = log.find( + (entry) => + entry.action.type === 'GAME_EVENT' && + entry.action.payload.type === 'endTurn', + ); + + expect(move.metadata).toBeUndefined(); + expect(endTurn.metadata).toEqual({ message: 'turn ended' }); + expect(client.getState().plugins.log.data).toEqual({}); + }); + + test('attaches onMove metadata to the move that triggered it', () => { + const game: Game = { + moves: { + play: () => {}, + }, + turn: { + onMove: ({ log }) => { + log.setMetadata({ message: 'move processed' }); + }, + }, + }; + const client = Client({ game }); + + client.moves.play(); + + expect(client.getState().log.at(-1).metadata).toEqual({ + message: 'move processed', + }); + }); + + test('preserves metadata from hooks triggered by automatic turn and phase endings', () => { + const game: Game<{ endPhase: boolean }> = { + setup: () => ({ endPhase: false }), + phases: { + A: { + start: true, + next: 'B', + endIf: ({ G }) => G.endPhase, + onEnd: ({ log }) => { + log.setMetadata({ message: 'phase A ended' }); + }, + turn: { + maxMoves: 1, + onEnd: ({ log }) => { + log.setMetadata({ message: 'turn ended' }); + }, + }, + moves: { + play: ({ G }) => { + G.endPhase = true; + }, + }, + }, + B: { + onBegin: ({ log }) => { + log.setMetadata({ message: 'phase B began' }); + }, + }, + }, + }; + const client = Client({ game }); + + client.moves.play(); + + const log = client.getState().log; + const endTurn = log.find( + (entry) => + entry.action.type === 'GAME_EVENT' && + entry.action.payload.type === 'endTurn', + ); + const endPhase = log.find( + (entry) => + entry.action.type === 'GAME_EVENT' && + entry.action.payload.type === 'endPhase', + ); + + expect(endTurn.metadata).toEqual({ message: 'turn ended' }); + expect(endPhase.metadata).toEqual({ message: 'phase B began' }); + }); + + test('preserves game-end metadata when endIf ends the game', () => { + const game: Game<{ won: boolean }> = { + setup: () => ({ won: false }), + moves: { + win: ({ G }) => { + G.won = true; + }, + }, + endIf: ({ G }) => G.won && 'winner', + onEnd: ({ log }) => { + log.setMetadata({ message: 'game ended' }); + }, + }; + const client = Client({ game }); + + client.moves.win(); + + const log = client.getState().log; + + expect( + log.find( + (entry) => + entry.action.type === 'GAME_EVENT' && + entry.action.payload.type === 'endGame', + ), + ).toBeUndefined(); + expect(log.at(-1).metadata).toEqual({ message: 'game ended' }); + }); test('It sets metadata in a move and then clears the metadata', () => { const game: Game = { @@ -123,7 +248,7 @@ describe('log-metadata', () => { log.setMetadata({ message: 'game ended' }); }, }; - const client = Client({ game }); + const client = Client({ game, credentials: 'secret' }); client.events.endGame('winner'); @@ -136,9 +261,29 @@ describe('log-metadata', () => { expect(client.getState().ctx.gameover).toBe('winner'); expect(endGame.metadata).toEqual({ message: 'game ended' }); + expect(endGame.action.payload).toEqual({ + type: 'endGame', + args: ['winner'], + playerID: '0', + credentials: undefined, + }); expect(log).toHaveLength(1); }); + test('It preserves empty endGame arguments in the log', () => { + const client = Client({ game: {} }); + + client.events.endGame(); + + const endGame = client.getState().log.at(-1); + expect(endGame.action.payload).toEqual({ + type: 'endGame', + args: [], + playerID: '0', + credentials: undefined, + }); + }); + test('It logs events without a canonical entry when no metadata is set', () => { const game: Game = { phases: { @@ -160,6 +305,12 @@ describe('log-metadata', () => { expect(client.getState().ctx.phase).toBe('B'); expect(setPhase).toBeDefined(); expect(setPhase.metadata).toBeUndefined(); + expect(setPhase.action.payload).toEqual({ + type: 'setPhase', + args: ['B'], + playerID: '0', + credentials: undefined, + }); client.events.endGame('winner'); diff --git a/src/plugins/plugin-log.ts b/src/plugins/plugin-log.ts index b3944a253..78e1bb3f5 100644 --- a/src/plugins/plugin-log.ts +++ b/src/plugins/plugin-log.ts @@ -8,18 +8,30 @@ import type { Plugin } from '../types'; -interface LogData { +export interface LogData { metadata?: any; } +/** + * Return metadata set by the current move or hook and clear it from the + * mutable plugin data object used by the log API. + */ +export function consumeLogMetadata(data: LogData | undefined): any { + const metadata = data?.metadata; + if (metadata !== undefined) { + delete data.metadata; + } + return metadata; +} + export interface LogAPI { setMetadata(metadata: any): void; } /** * Plugin that makes it possible to add metadata to log entries. - * Metadata set during a move, or during hooks triggered by a directly - * dispatched game event, is attached to that action's log entry. + * Metadata set during a move or a lifecycle hook is attached to the log + * entry for the move or event that triggered it. */ const LogPlugin: Plugin = { name: 'log',