Skip to content

Logging levels, throttles and diagnostics for the DMD plugin #3

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
freezy merged 2 commits into from
Oct 15, 2026
Merged

Logging levels, throttles and diagnostics for the DMD plugin #3

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
bc794e8
logging: Levels, throttles and diagnostics for the DMD plugin.
freezy Oct 15, 2026
d9a202d
logging: Throttle failures per pipeline and per destination.
freezy Oct 15, 2026
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
148 changes: 119 additions & 29 deletions VisualPinball.Engine.DMD.Unity/Runtime/DmdBridgePlayer.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@
using System.Collections.Generic;
using System.Globalization;
using System.IO;
using System.Reflection;
using System.Threading.Tasks;
using System.Threading;
using LibDmd;
Expand Down Expand Up @@ -37,7 +38,7 @@ namespace VisualPinball.Engine.DMD.Unity
/// Bridges VPE gamelogic display events into LibDmd's RenderGraph.
/// </summary>
[AddComponentMenu("Pinball/DMD/DMD Bridge Player")]
public class DmdBridgePlayer : MonoBehaviour
public class DmdBridgePlayer : MonoBehaviour, IDiagnosticsSource
{
[Header("Source")]
[SerializeField] private string _targetDisplayId = "dmd0";
Expand Down Expand Up @@ -124,6 +125,11 @@ public class DmdBridgePlayer : MonoBehaviour
private string _defaultAltColorPath;
private float _nextSettingsCheckTime;

// kept for diagnostics
private string _colorization = "not resolved yet";
private string _serumLibraryVersion;
private string _destinationNames = "";

private const float SettingsCheckInterval = 0.25f;

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
Expand Down Expand Up @@ -151,7 +157,8 @@ private IEnumerator Start()
_gamelogicEngine.OnDisplaysRequested += HandleDisplaysRequested;
_gamelogicEngine.OnDisplayClear += HandleDisplayClear;
_gamelogicEngine.OnDisplayUpdateFrame += HandleDisplayUpdateFrame;
Logger.Info("[DMD] Bridge connected to gamelogic display events.");
Logger.Info("[DMD] Bridge connected to the display events of {Engine}.", _gamelogicEngine.Name);
PublishDiagnostics();
}

/// <summary>Configures direct resource input; automatic GLE subscriptions and INI polling stay inactive.</summary>
Expand Down Expand Up @@ -283,10 +290,10 @@ private void HandleDisplayUpdateFrame(object sender, DisplayFrameData frame)
if (_pipeline == null) {
if (_currentDisplay == null) {
if (TryInferDisplayConfig(frame, out var inferredDisplay)) {
Logger.Info($"[DMD] Inferred display \"{inferredDisplay.Id}\" as {inferredDisplay.Width}x{inferredDisplay.Height} from frame stream.");
Logger.Info("[DMD] Inferred display {DisplayId} as {Width}x{Height} from the frame stream.", inferredDisplay.Id, inferredDisplay.Width, inferredDisplay.Height);
EnsurePipeline(inferredDisplay);
} else if (!_missingDisplayWarningLogged) {
Logger.Warn($"[DMD] Got frame for \"{frame.Id}\" before display dimensions were requested and could not infer dimensions from {frame.Data?.Length ?? 0} byte(s).");
Logger.Warn("[DMD] Got a frame for {DisplayId} before its dimensions were requested, and could not infer them from {Length} byte(s).", frame.Id, frame.Data?.Length ?? 0);
_missingDisplayWarningLogged = true;
}
}
Expand Down Expand Up @@ -365,17 +372,36 @@ private void EnsurePipeline(DisplayConfig display, bool force = false)
_pipeline?.Dispose();
CaptureAppliedSettings();
var destinations = CreateDestinations(display);
_destinationNames = DestinationNames(destinations);
if (destinations.Count == 0) {
Logger.Warn("[DMD] No DMD destinations are available; bridge will ignore frames.");
Logger.Warn("[DMD] No DMD destinations are available, the bridge will ignore frames.");
_pipeline = null;
PublishDiagnostics();
return;
}

var converter = CreateConverter();
_resolvedConverter = converter?.Name ?? "none";
RequestSourceFrameFormat(converter != null ? DisplayFrameFormat.Dmd4 : DisplayFrameFormat.Dmd8);
_pipeline = new DmdPipeline(display, destinations, converter, _settings.FlipHorizontally);
Logger.Info($"[DMD] Pipeline for \"{display.Id}\" created with {destinations.Count} destination(s).");
Logger.Info("[DMD] Pipeline for {DisplayId} ({Width}x{Height}) created with {Count} destination(s): {Destinations:l}, colorization: {Colorization:l}.",
display.Id, display.Width, display.Height, destinations.Count, _destinationNames, _colorization);
PublishDiagnostics();
}

private static string DestinationNames(List<IDestination> destinations)
{
var names = new List<string>(destinations.Count);
foreach (var destination in destinations) {
string name;
try {
name = destination.Name;
} catch (Exception) {
name = null;
}
names.Add(string.IsNullOrEmpty(name) ? destination.GetType().Name : name);
}
return string.Join(", ", names);
}

private void RequestSourceFrameFormat(DisplayFrameFormat format)
Expand Down Expand Up @@ -407,7 +433,7 @@ private List<IDestination> CreateDestinations(DisplayConfig display)
if (zeDmd.IsAvailable) {
destinations.Add(zeDmd);
} else {
Logger.Info("[DMD] ZeDMD destination not available.");
Logger.Warn("[DMD] ZeDMD is enabled, but no device is available.");
zeDmd.Dispose();
}
} catch (Exception exception) {
Expand All @@ -423,7 +449,7 @@ private List<IDestination> CreateDestinations(DisplayConfig display)
if (pinDmd3.IsAvailable) {
destinations.Add(pinDmd3);
} else {
Logger.Info("[DMD] PinDMD3 destination not available.");
Logger.Warn("[DMD] PinDMD3 is enabled, but no device is available.");
pinDmd3.Dispose();
}
} catch (Exception exception) {
Expand All @@ -439,7 +465,7 @@ private List<IDestination> CreateDestinations(DisplayConfig display)
if (pixelcade.IsAvailable) {
destinations.Add(pixelcade);
} else {
Logger.Info("[DMD] Pixelcade destination not available.");
Logger.Warn("[DMD] Pixelcade is enabled, but no device is available.");
pixelcade.Dispose();
}
} catch (Exception exception) {
Expand All @@ -453,7 +479,7 @@ private List<IDestination> CreateDestinations(DisplayConfig display)
if (pin2Dmd.IsAvailable) {
destinations.Add(pin2Dmd);
} else {
Logger.Info("[DMD] PIN2DMD destination not available.");
Logger.Warn("[DMD] PIN2DMD is enabled, but no device is available.");
pin2Dmd.Dispose();
}
} catch (Exception exception) {
Expand All @@ -467,7 +493,7 @@ private List<IDestination> CreateDestinations(DisplayConfig display)
if (pinDmd2.IsAvailable) {
destinations.Add(pinDmd2);
} else {
Logger.Info("[DMD] PinDMDv2 destination not available.");
Logger.Warn("[DMD] PinDMDv2 is enabled, but no device is available.");
pinDmd2.Dispose();
}
} catch (Exception exception) {
Expand All @@ -481,7 +507,7 @@ private List<IDestination> CreateDestinations(DisplayConfig display)
if (pinDmd1.IsAvailable) {
destinations.Add(pinDmd1);
} else {
Logger.Info("[DMD] PinDMDv1 destination not available.");
Logger.Warn("[DMD] PinDMDv1 is enabled, but no device is available.");
pinDmd1.Dispose();
}
} catch (Exception exception) {
Expand Down Expand Up @@ -511,13 +537,16 @@ private List<IDestination> CreateDestinations(DisplayConfig display)

private AbstractConverter CreateConverter()
{
_serumLibraryVersion = null;
if (!_settings.EnableColorization) {
Logger.Info("[DMD] Colorization disabled.");
_colorization = "disabled";
return null;
}

if (string.IsNullOrWhiteSpace(_settings.AltColorPath) || string.IsNullOrWhiteSpace(_settings.RomName)) {
Logger.Info($"[DMD] Colorization enabled, but missing altcolor path or ROM name. AltColorPath=\"{_settings.AltColorPath}\", RomName=\"{_settings.RomName}\".");
Logger.Warn("[DMD] Colorization is enabled, but the altcolor path ({AltColorPath:l}) or the ROM name ({RomName}) is missing.", _settings.AltColorPath ?? "", _settings.RomName ?? "");
_colorization = "none (altcolor path or ROM name missing)";
return null;
}

Expand All @@ -527,38 +556,55 @@ private AbstractConverter CreateConverter()
try {
var serum = new Serum(_settings.AltColorPath, _settings.RomName, _settings.ColorizationScalerMode);
if (serum.IsLoaded) {
Logger.Info($"[DMD] Serum colorization loaded ({serum.ColorizationVersion}).");
_serumLibraryVersion = SerumLibraryVersion();
_colorization = "Serum " + serum.ColorizationVersion;
Logger.Info("[DMD] Serum {Format} colorization loaded for {RomName} (libserum {Version}).", serum.ColorizationVersion, _settings.RomName, _serumLibraryVersion ?? "unknown");
return serum;
}

serum.Dispose();
Logger.Info($"[DMD] Serum files were found for \"{_settings.RomName}\", but no Serum colorization was loaded.");
Logger.Warn("[DMD] Serum files were found for {RomName}, but no Serum colorization was loaded.", _settings.RomName);
} catch (Exception exception) {
Logger.Warn(exception, "[DMD] Could not initialize Serum colorization.");
Logger.Warn(exception, "[DMD] Could not initialize Serum colorization for {RomName}.", _settings.RomName);
}
} else {
Logger.Info($"[DMD] No Serum files found for \"{_settings.RomName}\".");
Logger.Info("[DMD] No Serum files found for {RomName}.", _settings.RomName);
}

try {
var loader = new VniLoader(_settings.AltColorPath, _settings.RomName);
if (!loader.FilesExist) {
Logger.Info($"[DMD] Colorization was requested, but no Serum/VNI/PAL/PAC files were found for \"{_settings.RomName}\".");
Logger.Info("[DMD] Colorization was requested, but no Serum/VNI/PAL/PAC files were found for {RomName}.", _settings.RomName);
_colorization = "none (no colorization files found)";
return null;
}

loader.Load(string.IsNullOrWhiteSpace(_settings.VniKey) ? null : _settings.VniKey);
if (loader.Pal == null) {
Logger.Info($"[DMD] VNI/PAL/PAC colorization was found for \"{_settings.RomName}\" but no palette was loaded.");
Logger.Warn("[DMD] VNI/PAL/PAC colorization was found for {RomName}, but no palette was loaded.", _settings.RomName);
_colorization = "none (VNI/PAL/PAC found, but no palette loaded)";
return null;
}

Logger.Info($"[DMD] VNI/PAL/PAC colorization loaded for \"{_settings.RomName}\".");
Logger.Info("[DMD] VNI/PAL/PAC colorization loaded for {RomName}.", _settings.RomName);
_colorization = loader.Vni != null ? "VNI/PAL" : "PAL";
return new VniColorizer(loader.Pal, loader.Vni) {
ScalerMode = _settings.ColorizationScalerMode
};
} catch (Exception exception) {
Logger.Warn(exception, "[DMD] Could not initialize VNI/PAL/PAC colorization.");
Logger.Warn(exception, "[DMD] Could not initialize VNI/PAL/PAC colorization for {RomName}.", _settings.RomName);
_colorization = "none (VNI/PAL/PAC failed to load)";
return null;
}
}

private static string SerumLibraryVersion()
{
try {
return Serum.GetVersion();
} catch (Exception exception) {
// only for diagnostics: the colorization itself is already loaded
Logger.Debug(exception, "[DMD] Could not read the libserum version.");
return null;
}
}
Expand All @@ -580,13 +626,13 @@ private static void LogColorizationSearchPath(string altColorPath, string romNam
{
var gamePath = Path.Combine(altColorPath, romName);
if (!Directory.Exists(gamePath)) {
Logger.Info($"[DMD] Colorization folder not found: \"{gamePath}\".");
Logger.Info("[DMD] Colorization folder not found: {Path:l}", gamePath);
return;
}

try {
var files = Directory.GetFiles(gamePath);
Logger.Info($"[DMD] Looking for colorization in \"{gamePath}\" ({files.Length} file(s)).");
Logger.Info("[DMD] Looking for colorization in {Path:l} ({Count} file(s)).", gamePath, files.Length);
foreach (var file in files) {
var extension = Path.GetExtension(file);
if (string.Equals(extension, ".crz", StringComparison.OrdinalIgnoreCase)
Expand All @@ -595,11 +641,11 @@ private static void LogColorizationSearchPath(string altColorPath, string romNam
|| string.Equals(extension, ".pal", StringComparison.OrdinalIgnoreCase)
|| string.Equals(extension, ".vni", StringComparison.OrdinalIgnoreCase)
|| string.Equals(extension, ".pac", StringComparison.OrdinalIgnoreCase)) {
Logger.Info($"[DMD] Colorization candidate: {Path.GetFileName(file)}");
Logger.Debug("[DMD] Colorization candidate: {File:l}", Path.GetFileName(file));
}
}
} catch (Exception exception) {
Logger.Warn(exception, $"[DMD] Could not inspect colorization folder \"{gamePath}\".");
Logger.Warn(exception, "[DMD] Could not inspect colorization folder {Path:l}.", gamePath);
}
}

Expand Down Expand Up @@ -652,7 +698,7 @@ private DmdBridgeSettings LoadSettings()
var writeTimeUtc = File.Exists(configPath) ? File.GetLastWriteTimeUtc(configPath) : DateTime.MinValue;
if (!File.Exists(configPath)) {
if (!_missingConfigWarningLogged && !DmdBridgeConfig.IsDefaultConfigPath(_dmdDeviceIniPath)) {
Logger.Info($"[DMD] No DmdDevice.ini found at \"{configPath}\"; using component settings.");
Logger.Info("[DMD] No DmdDevice.ini found at {Path:l}, using component settings.", configPath);
_missingConfigWarningLogged = true;
}
_lastFallbackSettings = fallback.Clone();
Expand Down Expand Up @@ -725,6 +771,50 @@ private string ResolveAltColorPath(string configuredAltColorPath)
return _defaultAltColorPath;
}

#region Diagnostics

public string DiagnosticsSection => "DMD";

/// <summary>
/// The source published as the "DMD" section. The plugin sets itself here so its own
/// settings are part of it; it describes this bridge as part of its section.
/// </summary>
public IDiagnosticsSource DiagnosticsOwner { get; set; }

private void PublishDiagnostics()
{
DiagnosticsContext.Set(DiagnosticsOwner ?? this);
}

public void Describe(DiagnosticsWriter writer)
{
writer.Add("mode", _managed ? "plugin" : "component");
if (!_managed) {
writer.Add("gamelogic-engine", _gamelogicEngine?.Name ?? "none");
var configPath = _appliedConfigPath ?? DmdBridgeConfig.ResolveConfigPath(_dmdDeviceIniPath);
writer.Add("dmddevice-ini", configPath ?? "");
writer.Add("dmddevice-ini.exists", !string.IsNullOrEmpty(configPath) && File.Exists(configPath));
}
writer.Add("rom", _settings?.RomName ?? "");
writer.Add("display", _currentDisplay != null ? $"{_currentDisplay.Id} {_currentDisplay.Width}x{_currentDisplay.Height}" : "none yet");
writer.Add("pipeline", _pipeline != null || _managedInput?.Pipeline != null ? "running" : "none");
writer.Add("destinations", _destinationNames);
writer.Add("altcolor-path", _settings?.AltColorPath ?? "");
writer.Add("colorization", _colorization);
if (_serumLibraryVersion != null) {
writer.Add("libserum-version", _serumLibraryVersion);
}
// as a plugin, the plugin writes the settings it was given
if (_settings != null && !_managed) {
// VniKey is redacted by AddSetting
foreach (var field in typeof(DmdBridgeSettings).GetFields(BindingFlags.Public | BindingFlags.Instance)) {
writer.AddSetting("setting." + field.Name, field.GetValue(_settings));
}
}
}

#endregion

private void SyncNativeWindowLayout()
{
if (_pipeline == null
Expand Down Expand Up @@ -914,7 +1004,7 @@ public static DmdBridgeSettings Load(string path, DmdBridgeSettings fallback, bo
{
var resolvedPath = exactPath ? Path.GetFullPath(path) : ResolveConfigPath(path);
if (string.IsNullOrWhiteSpace(resolvedPath) || !File.Exists(resolvedPath)) {
Logger.Warn($"[DMD] No DmdDevice.ini found at \"{resolvedPath}\"; using component settings.");
Logger.Warn("[DMD] No DmdDevice.ini found at {Path:l}, using component settings.", resolvedPath ?? "");
return fallback.Clone();
}

Expand All @@ -930,10 +1020,10 @@ public static DmdBridgeSettings Load(string path, DmdBridgeSettings fallback, bo
ApplyPinDmd1(ini, settings);
ApplyPinDmd2(ini, settings);
ApplyGame(ini, settings, Path.GetDirectoryName(resolvedPath));
Logger.Info($"[DMD] Loaded DmdDevice.ini from \"{resolvedPath}\".");
Logger.Info("[DMD] Loaded DmdDevice.ini from {Path:l}.", resolvedPath);
return settings;
} catch (Exception exception) {
Logger.Warn(exception, $"[DMD] Could not load DmdDevice.ini at \"{resolvedPath}\"; using component settings.");
Logger.Warn(exception, "[DMD] Could not load DmdDevice.ini at {Path:l}, using component settings.", resolvedPath);
return fallback.Clone();
}
}
Expand Down
14 changes: 12 additions & 2 deletions VisualPinball.Engine.DMD.Unity/Runtime/DmdPipeline.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,9 @@ internal sealed class DmdPipeline : IManagedDmdPipeline
private bool _disposed;

private static readonly Logger Logger = LogManager.GetCurrentClassLogger();
// per pipeline, so one failing display doesn't use up another one's first errors
private readonly LogThrottle _frameFailureThrottle = new LogThrottle(3, TimeSpan.FromSeconds(30));
private readonly LogThrottle _renderGraphErrorThrottle = new LogThrottle(3, TimeSpan.FromSeconds(30));

public DmdPipeline(DisplayConfig display, List<IDestination> destinations, AbstractConverter converter, bool flipHorizontally)
{
Expand All @@ -73,7 +76,11 @@ public DmdPipeline(DisplayConfig display, List<IDestination> destinations, Abstr
Converter = converter,
FlipHorizontally = display.FlipX ^ flipHorizontally,
};
_renderer = _renderGraph.Init().StartRendering(null, exception => Logger.Warn(exception, "[DMD] RenderGraph reported an error."));
_renderer = _renderGraph.Init().StartRendering(null, exception => {
if (_renderGraphErrorThrottle.ShouldLog(out var suppressed)) {
Logger.Warn(exception, "[DMD] RenderGraph reported an error ({Suppressed} suppressed).", suppressed);
}
});

foreach (var destination in destinations) {
if (destination is INativeDmdWindow window && window.RequiresHostPump) {
Expand Down Expand Up @@ -222,7 +229,10 @@ private void WorkerLoop()
_source.Push(format, _work, length);
}
} catch (Exception exception) {
Logger.Warn(exception, "[DMD] DMD worker failed to render a frame.");
// runs per frame on the worker: a broken device would otherwise flood the log
if (_frameFailureThrottle.ShouldLog(out var suppressed)) {
Logger.Warn(exception, "[DMD] DMD worker failed to render a frame for {Display} ({Suppressed} suppressed).", _display.Id, suppressed);
}
}

if (!doClear && !doFrame) {
Expand Down
4 changes: 2 additions & 2 deletions VisualPinball.Engine.DMD.Unity/Runtime/InSceneDmdDestination.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -55,11 +55,11 @@ public static InSceneDmdDestination TryCreate(DisplayConfig config, GameObject s
{
var display = scene != null ? scene.GetComponentsInChildren<DisplayComponent>(true).FirstOrDefault(candidate => candidate.Id == config.Id) : FindDisplay(config.Id);
if (display == null) {
Logger.Info($"[DMD] No in-scene display found for \"{config.Id}\".");
Logger.Info("[DMD] No in-scene display found for {DisplayId}.", config.Id);
return null;
}

Logger.Info($"[DMD] In-scene display destination connected for \"{config.Id}\".");
Logger.Info("[DMD] In-scene display destination connected for {DisplayId}.", config.Id);
return new InSceneDmdDestination(display, config);
}

Expand Down
3 changes: 2 additions & 1 deletion VisualPinball.Engine.DMD.Unity/Runtime/NativeWindowDestinationFactory.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,8 @@ public static IDestination TryCreate(DisplayConfig display, DmdBridgeSettings se
return null;
}

Logger.Info($"[DMD] Native-window destination created for {display.Width}x{display.Height} at {settings.NativeWindowLeft},{settings.NativeWindowTop} ({settings.NativeWindowWidth}x{settings.NativeWindowHeight}).");
Logger.Info("[DMD] Native-window destination created for {Width}x{Height} at {Left},{Top} ({WindowWidth}x{WindowHeight}).",
display.Width, display.Height, settings.NativeWindowLeft, settings.NativeWindowTop, settings.NativeWindowWidth, settings.NativeWindowHeight);
return window;
}

Expand Down
Loading
Loading