Skip to content

Propose wide-event logging as a replacement for ad-hoc log calls (PoC) - #172

Open
scurth wants to merge 1 commit into
FreeCol:masterfrom
scurth:wide-event-logging
Open

Propose wide-event logging as a replacement for ad-hoc log calls (PoC)#172
scurth wants to merge 1 commit into
FreeCol:masterfrom
scurth:wide-event-logging

Conversation

@scurth

@scurth scurth commented Aug 23, 2026

Copy link
Copy Markdown

FreeCol's logging has grown organically into hundreds of independent logger.info/warning/fine calls with free-text messages and no shared structure. A single player action (a unit move, an AI player's turn) routinely produces several unrelated log lines that have to be correlated by hand via matching timestamps, and there is no way to query the resulting log beyond grepping text.

This introduces a small, additive logging facility -- WideEvent -- and applies it to two representative, unrelated subsystems to prove the approach before committing to a wider rollout:

  • EuropeanAIPlayer.startWorking(): one record per AI player's turn
  • InGameController.moveDirection(): one record per unit move

WideEvent (common/logging/WideEvent.java):

  • begin(name)/end(logger, level): marks a bounded unit of work and emits one structured record for it, with duration.
  • A thread-local context stack lets code with no direct reference to the enclosing event still contribute via note()/noteOrLog(), so call sites deep in the model or GUI (WorkLocation, InfoPanel) don't need the event threaded through their signatures.
  • noteOrLog() degrades gracefully to today's plain logging when no event is active, so adoption can proceed file by file without ever changing behaviour on paths that haven't been migrated yet.
  • Output format is a runtime choice, not a call-site one: default is human-readable key=value text (unchanged from what the log already looked like); passing -Dfreecol.wideEvents.json=true switches every emitted event to a single JSON object instead, with no code changes required anywhere.

WideEventFields (common/logging/WideEventFields.java):

  • A registry of the field and note-category names in use (PLAYER, TURN, UNIT, NOTE_MISSION_COLLAPSE, ...). Wide event keys are plain strings with no compiler-enforced schema, so as more call sites adopt this pattern it becomes easy for the same concept to drift into multiple spellings. Declaring every key once here and having call sites reference the constant is the starting point for keeping that vocabulary consistent as this scales beyond these two subsystems.

Demonstrated value (verified against the running client, not just unit tests):

  • Correlation: a single unit move previously produced 3+ independent, uncorrelated log lines (InfoPanel updates, WorkLocation production changes). It now produces one line carrying all of them as fields on the same record, e.g.: event=client.moveUnit duration_ms=429 unit=unit:7317 unitType=freeColonist direction=W moveType=MOVE interactive=true infoPanel="[...]" result=true

  • Performance data for free: because the event already brackets the unit of work, duration_ms falls out of the mechanism itself with no extra instrumentation -- every wrapped event now reports how long it took.

  • Queryable output: with JSON mode enabled, the same event becomes a single JSON object per line, e.g.: {"event":"client.moveUnit","duration_ms":429,"unit":"unit:7317", "unitType":"freeColonist","direction":"W","moveType":"MOVE", "interactive":true,"infoPanel":["..."],"result":true} letting the log be queried directly with jq once the JSON message is extracted from the surrounding log record, e.g.: grep -oE 'FINE: {.*}$' FreeCol.log | sed 's/^FINE: //' \ | jq 'select(.event=="client.moveUnit") | .duration_ms'

Explicitly out of scope for this proposal: this does not touch the ~215 other files that still log via plain java.util.logging calls, and it is not meant to. The intent is to get agreement on the mechanism and its trade-offs on a small, reviewable slice before proposing a wider, incremental rollout -- one bounded subsystem at a time, following the same begin/note/end pattern, guided by WideEventFields as the growing schema.

Not every log call site is a good candidate: MapViewer's verifyAndMarkAsClean repaint warning was evaluated and deliberately left alone, since it fires on the hot Swing repaint path with no natural request boundary and is already a self-contained, actionable warning on its own.

All 439 upstream unit tests pass unchanged.

FreeCol's logging has grown organically into hundreds of independent
logger.info/warning/fine calls with free-text messages and no shared
structure. A single player action (a unit move, an AI player's turn)
routinely produces several unrelated log lines that have to be
correlated by hand via matching timestamps, and there is no way to
query the resulting log beyond grepping text.

This introduces a small, additive logging facility -- WideEvent -- and
applies it to two representative, unrelated subsystems to prove the
approach before committing to a wider rollout:

  - EuropeanAIPlayer.startWorking(): one record per AI player's turn
  - InGameController.moveDirection(): one record per unit move

WideEvent (common/logging/WideEvent.java):
  - begin(name)/end(logger, level): marks a bounded unit of work and
    emits one structured record for it, with duration.
  - A thread-local context stack lets code with no direct reference
    to the enclosing event still contribute via note()/noteOrLog(),
    so call sites deep in the model or GUI (WorkLocation,
    InfoPanel) don't need the event threaded through their
    signatures.
  - noteOrLog() degrades gracefully to today's plain logging when no
    event is active, so adoption can proceed file by file without
    ever changing behaviour on paths that haven't been migrated yet.
  - Output format is a runtime choice, not a call-site one: default
    is human-readable key=value text (unchanged from what the log
    already looked like); passing -Dfreecol.wideEvents.json=true
    switches every emitted event to a single JSON object instead,
    with no code changes required anywhere.

WideEventFields (common/logging/WideEventFields.java):
  - A registry of the field and note-category names in use
    (PLAYER, TURN, UNIT, NOTE_MISSION_COLLAPSE, ...). Wide event keys
    are plain strings with no compiler-enforced schema, so as more
    call sites adopt this pattern it becomes easy for the same
    concept to drift into multiple spellings. Declaring every key
    once here and having call sites reference the constant is the
    starting point for keeping that vocabulary consistent as this
    scales beyond these two subsystems.

Demonstrated value (verified against the running client, not just
unit tests):

  - Correlation: a single unit move previously produced 3+
    independent, uncorrelated log lines (InfoPanel updates,
    WorkLocation production changes). It now produces one line
    carrying all of them as fields on the same record, e.g.:
      event=client.moveUnit duration_ms=429 unit=unit:7317
      unitType=freeColonist direction=W moveType=MOVE
      interactive=true infoPanel="[...]" result=true

  - Performance data for free: because the event already brackets
    the unit of work, duration_ms falls out of the mechanism itself
    with no extra instrumentation -- every wrapped event now reports
    how long it took.

  - Queryable output: with JSON mode enabled, the same event becomes
    a single JSON object per line, e.g.:
      {"event":"client.moveUnit","duration_ms":429,"unit":"unit:7317",
       "unitType":"freeColonist","direction":"W","moveType":"MOVE",
       "interactive":true,"infoPanel":["..."],"result":true}
    letting the log be queried directly with jq once the JSON message
    is extracted from the surrounding log record, e.g.:
      grep -oE 'FINE: \{.*\}$' FreeCol.log | sed 's/^FINE: //' \
        | jq 'select(.event=="client.moveUnit") | .duration_ms'

Explicitly out of scope for this proposal: this does not touch the
~215 other files that still log via plain java.util.logging calls,
and it is not meant to. The intent is to get agreement on the
mechanism and its trade-offs on a small, reviewable slice before
proposing a wider, incremental rollout -- one bounded subsystem at a
time, following the same begin/note/end pattern, guided by
WideEventFields as the growing schema.

Not every log call site is a good candidate: MapViewer's
verifyAndMarkAsClean repaint warning was evaluated and deliberately
left alone, since it fires on the hot Swing repaint path with no
natural request boundary and is already a self-contained, actionable
warning on its own.

All 439 upstream unit tests pass unchanged.

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant