fix(log): preserve metadata from lifecycle hooks

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
 

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,17 +854,54 @@ 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,
         turn: state.ctx.turn,
         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,

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;