Skip to content

Logging, diagnostics and performance tracking for error reporting - #590

Merged
freezy merged 8 commits into
masterfrom
feat/error-reporting
Oct 15, 2026
Merged

freezy merged 8 commits into
masterfrom
feat/error-reporting

Conversation

@freezy

@freezy freezy commented Oct 15, 2026

Copy link
Copy Markdown
Owner

The engine part of the logging and error reporting work: a cleaned-up NLog setup, diagnostics that describe the session for bug reports, performance tracking, and the building blocks the player's Sentry integration uses. Sentry itself lives in the player (VisualPinball/VisualPinball.Engine.Player); the engine has no dependency on it.

Logging

  • Setup: NLog is configured at SubsystemRegistration. All targets except the editor console sit behind our own queue, so the logging thread only enqueues and rendering and file I/O happen on a writer thread. NLog's AsyncTargetWrapper renders events with exceptions on the logging thread, which the simulation thread can't afford.
  • Session log: one file per session (newest 10 kept), flushed per batch, plus an in-memory tail of the last 2000 lines for reports. -vpe-log-level overrides the level.
  • Bridges and hooks: UnityLogBridge forwards Debug.Log from Unity and third-party code into NLog. CrashHooks log unhandled and unobserved exceptions. UnityTarget renders exceptions as text instead of Debug.LogException.
  • Simulation thread: catches what kills it, logs it after the no-GC region ends, and SimulationThreadComponent raises SimulationFaulted.
  • Level policy, applied across the runtime: Error is for VPE bugs. Problems a table author or user can cause (unmapped coils, switches, lamps, missing sounds, unknown component types, invalid table files) are warnings. Per-item and per-frame lines are Debug/Trace, and hot paths go through LogThrottle/LogOncePerKey. Errors use message templates, so reports group by template. LoggingRulesTests scans the runtime code of every swept package and enforces this.
  • Bugs fixed on the way:
    • a hit event for an item without a hit handler threw KeyNotFoundException;
    • PackagedRefs threw on a missing component;
    • the trough logged an error on every drain.

Diagnostics

DiagnosticsContext holds named sections, logged when they change and attached to reports:

  • System: OS, CPU and cores, RAM, GPU, driver, VRAM, displays, Unity, render pipeline, command line with secrets removed.
  • Build: the app version, the commit of every VPE repository and the version of every VPE package.
  • Table: a LoadAttempt tracks phase, package format, metadata and a fingerprint. It survives a failed load.
  • Gamelogic and plugins: what engines and plugins report through the new IDiagnosticsSource.

Redaction removes the home folder and user name from paths, including inside JSON (RedactJson). DiagnosticsWriter never writes values of settings that look like secrets.

Plugins

IPluginLog (levelled, with exceptions) is added next to the old text log. It is written to NLog as Plugin.<id>. An error callback receives exceptions from plugin hooks with their stack trace.

IGamelogicStartupStatus lets engines report what the user can fix (missing ROM, emulator not installed) instead of throwing from OnInit.

Performance

PerformanceMonitor is a PlayerLoop system and the only frame timing capturer; FramePacingGraph and the player's overlay read from it.

  • Classification: it closes 1 s windows and decides what bounds the frame (capped, gpu, cpu-main, cpu-render), with hysteresis.
  • Logging: a line when FPS moves by 20 % or the bound changes, at most every 10 s, with a 5-minute heartbeat. Hitches and a nearly full GPU budget warn, throttled.
  • Memory: RAM comes from the OS (Unity's counter on macOS), VRAM usage and budget from DXGI on Windows.
  • Session summary: written when the table ends; it includes average FPS, worst 1 %, bound shares and peaks.

Error reporting building blocks

  • ReportDedupe: the first automatic report of each kind per session, at most ten, fatal ones always.
  • Diagnostics snapshot file next to each session log, for the crash follow-up.
  • DiagnosticsContext.Removed, so the report scope forgets a closed table.
  • InvalidPackageException: a file that isn't a loadable .vpe package is the user's problem, not a bug. The reader also only starts its background reads once the file passed these checks.

Testing

  • EditMode tests: logging, diagnostics, redaction, logging rules, frame-bound classifier, report dedupe and invalid packages, all passing in VisualPinball.Unity.Project.Hdrp.
  • Player sessions: verified in the player editor and in a Windows release build against Sentry.

Merge order

Merge this first. The plugin PRs depend on the new plugin API (IPluginLog, IDiagnosticsSource, IGamelogicStartupStatus).

Logging is configured at SubsystemRegistration, so the first scene's Awake no
longer logs into the void. All targets except the editor console sit behind a
queue of our own: the logging thread only enqueues, everything else (rendering,
file I/O) happens on a writer thread. NLog's AsyncTargetWrapper renders events
with exceptions on the logging thread, which the simulation thread can't afford.

- VpeLog: install once, begin a session per play mode/player start (new session
  id, cleared tail, reset throttles), host settings via Configure() (log folder,
  level), extra targets via AddTarget(), -vpe-log-level override.
- Session log file per session, newest 10 kept, flushed per batch so a native
  crash loses at most 50 ms.
- LogTail: the last 2000 lines in memory, for error reports.
- LogThrottle / LogOncePerKey for hot paths.
- UnityLogBridge forwards Debug.Log from Unity and third-party code into NLog.
- CrashHooks log unhandled and unobserved exceptions.
- UnityTarget renders exceptions as text instead of Debug.LogException, which
  would turn every logged exception into an unhandled one.
- The simulation thread catches what kills it, logs it after the no-GC region
  ends, and SimulationThreadComponent raises SimulationFaulted.
DiagnosticsContext holds what a developer needs to reproduce a problem, in named
sections that are written when something changes and logged at the same time:

- System: OS, CPU with logical and physical cores, RAM, GPU with driver
  version and VRAM, displays, Unity version, render pipeline, scripting
  backend, and the command line with secrets removed.
- Build: app version, the commit of every VPE repository, and the version of
  every VPE package.
- Table: a LoadAttempt is created before a table is read. It tracks the load
  phase, package format and writer, metadata and a cheap fingerprint, and it
  keeps describing the table after a failed load.
- Gamelogic: the engine, ROM and game id, plus whatever the engine reports
  through the new IDiagnosticsSource.

Player.Start logs the gamelogic engine's start and duration. An exception from
OnInit, which previously escaped the async void, is now logged as an error and
fails the load attempt.

Redaction removes the home folder and user name from paths. DiagnosticsWriter
never writes the value of a setting whose name suggests a secret.
Every runtime UnityEngine.Debug.Log call now goes through NLog, and every log
call follows the level policy in VpeLog:

- Problems a table author or user can cause (unmapped coils, switches, wires
  and lamps, missing players, missing sounds, unknown component types) are
  warnings, not errors. Errors are left for VPE bugs.
- Per-item, per-event, per-frame and teardown lines move to Debug or Trace.
  Load-phase timings are Debug; one Info line per table load remains.
- Hot paths check a LogThrottle or LogOncePerKey before logging, so a broken
  mapping logs once instead of on every event.
- Error and Fatal take message templates, so reports group by template.
  Exceptions are passed as exceptions.
- Swallowed exceptions are logged where the user loses something.
- The async void methods log their exceptions, and the texture cache's
  background write logs a failure.

Bugs fixed on the way: a hit event for an item without a hit handler threw a
KeyNotFoundException, PackagedRefs threw on a missing component, and the
trough logged an error on every drain.

LoggingRulesTests scans the runtime code of the packages that follow these
rules for Debug.Log calls, interpolated errors and stringified exceptions.
- IPluginLog (Debug/Info/Warn/Error with exceptions) as PluginApplicationContext.Logger,
  next to the old text Log. The host takes an optional factory for it, and an error
  callback that receives exceptions from plugin hooks with their stack trace.
  Invalid plugin settings stay a warning.
- NLogPluginLog writes a plugin's log to NLog as "Plugin.<id>".
- IGamelogicStartupStatus: engines report what the user can fix (missing ROM,
  emulator not installed) instead of throwing from OnInit. The player logs it,
  fails the load attempt and keeps the table playable.
- Player.RefreshGamelogicDiagnostics() for engines that learn more after OnInit.
- DiagnosticsContext logs only what changed after a section's first appearance,
  and Retain() drops what describes a previous table.
- LoggingRulesTests now covers every swept package.
…nes.

PerformanceMonitor runs as a PlayerLoop system and is the only frame
timing capturer. It closes 1 s windows, classifies what bounds the frame
(capped, gpu, cpu-main, cpu-render) with hysteresis, and logs a line when
the frame rate moves by 20 % or the bound changes, at most every 10 s
with a 5 minute heartbeat. Hitches and a nearly full GPU budget warn,
throttled. Process RAM comes from the OS (Unity's counter on macOS), VRAM
usage and budget from DXGI on Windows. The Performance diagnostics
section holds the session's totals and the latest window, and the table
end logs a summary.
ReportDedupe decides which automatic reports of a session are sent: the
first of each kind, at most ten, fatal ones always. Redaction.RedactJson
redacts JSON string values as the text they stand for, so escaped
backslashes don't hide the home folder. DiagnosticsContext raises Removed
for dropped sections, VpeLog names a diagnostics snapshot next to each
log and rotates it with it, and the performance section says whether the
game is paused.
…kageException.

A file that can't be opened as a package, has no manifest, comes from a
newer format version or has no scene is a problem with the file, not
with VPE. The reader now says so with its own exception, and only starts
its background reads once the file passed these checks.
@greptile-apps

greptile-apps Bot commented Oct 15, 2026 •

Copy link
Copy Markdown

RetriggerView in GreptileConfidence Score: 5/5

[Medium impact] The changes appear safe to merge; both previous findings are fixed and no new actionable issues were found.

Summary

Adds queued session logging, diagnostics, plugin logging APIs, performance tracking, and error-reporting helpers.

  • Reports can include redacted details about the session.
  • Runtime logs now use clearer levels and avoid repeating noisy messages.

Diagram

%%{init: {'theme': 'neutral'}}%%
flowchart LR
  A[Engine and plugin logs] --> Q[Shared log queue]
  U[Unity logs] --> B[UnityLogBridge]
  B --> Q
  Q --> W[Writer thread]
  W --> F[Session file]
  W --> T[In-memory tail]
  W --> R[Host reporting targets]
Loading

Reviews (2) · Last reviewed commit: "logging: Send the first fatal report of ..." · Reviewed by Greptile

Comment thread VisualPinball.Unity/VisualPinball.Unity/Diagnostics/ReportDedupe.cs Outdated
…ult handler, throttle per instance.

A fatal report is sent even if the same kind came before as an error
that wasn't sent. Update stops when a SimulationFaulted handler stopped
the simulation. Once-per-id warnings of per-table players and the
throttles of components that exist several at a time belong to their
instance, so one table or one failing instance doesn't hide another's.
@freezy
freezy merged commit 18161fb into master Oct 15, 2026
18 checks passed
@freezy
freezy deleted the feat/error-reporting branch October 15, 2026 19:22
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