diff --git a/VisualPinball.Engine.DMD.Unity/Runtime/DmdBridgePlayer.cs b/VisualPinball.Engine.DMD.Unity/Runtime/DmdBridgePlayer.cs index 0d59c02..4b02a24 100644 --- a/VisualPinball.Engine.DMD.Unity/Runtime/DmdBridgePlayer.cs +++ b/VisualPinball.Engine.DMD.Unity/Runtime/DmdBridgePlayer.cs @@ -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; @@ -37,7 +38,7 @@ namespace VisualPinball.Engine.DMD.Unity /// Bridges VPE gamelogic display events into LibDmd's RenderGraph. /// [AddComponentMenu("Pinball/DMD/DMD Bridge Player")] - public class DmdBridgePlayer : MonoBehaviour + public class DmdBridgePlayer : MonoBehaviour, IDiagnosticsSource { [Header("Source")] [SerializeField] private string _targetDisplayId = "dmd0"; @@ -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(); @@ -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(); } /// Configures direct resource input; automatic GLE subscriptions and INI polling stay inactive. @@ -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; } } @@ -365,9 +372,11 @@ 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; } @@ -375,7 +384,24 @@ private void EnsurePipeline(DisplayConfig display, bool force = false) _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 destinations) + { + var names = new List(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) @@ -407,7 +433,7 @@ private List 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) { @@ -423,7 +449,7 @@ private List 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) { @@ -439,7 +465,7 @@ private List 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) { @@ -453,7 +479,7 @@ private List 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) { @@ -467,7 +493,7 @@ private List 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) { @@ -481,7 +507,7 @@ private List 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) { @@ -511,13 +537,16 @@ private List 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; } @@ -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; } } @@ -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) @@ -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); } } @@ -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(); @@ -725,6 +771,50 @@ private string ResolveAltColorPath(string configuredAltColorPath) return _defaultAltColorPath; } + #region Diagnostics + + public string DiagnosticsSection => "DMD"; + + /// + /// 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. + /// + 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 @@ -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(); } @@ -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(); } } diff --git a/VisualPinball.Engine.DMD.Unity/Runtime/DmdPipeline.cs b/VisualPinball.Engine.DMD.Unity/Runtime/DmdPipeline.cs index 5f92e27..dda83a6 100644 --- a/VisualPinball.Engine.DMD.Unity/Runtime/DmdPipeline.cs +++ b/VisualPinball.Engine.DMD.Unity/Runtime/DmdPipeline.cs @@ -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 destinations, AbstractConverter converter, bool flipHorizontally) { @@ -73,7 +76,11 @@ public DmdPipeline(DisplayConfig display, List 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) { @@ -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) { diff --git a/VisualPinball.Engine.DMD.Unity/Runtime/InSceneDmdDestination.cs b/VisualPinball.Engine.DMD.Unity/Runtime/InSceneDmdDestination.cs index 2034733..88f7b44 100644 --- a/VisualPinball.Engine.DMD.Unity/Runtime/InSceneDmdDestination.cs +++ b/VisualPinball.Engine.DMD.Unity/Runtime/InSceneDmdDestination.cs @@ -55,11 +55,11 @@ public static InSceneDmdDestination TryCreate(DisplayConfig config, GameObject s { var display = scene != null ? scene.GetComponentsInChildren(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); } diff --git a/VisualPinball.Engine.DMD.Unity/Runtime/NativeWindowDestinationFactory.cs b/VisualPinball.Engine.DMD.Unity/Runtime/NativeWindowDestinationFactory.cs index d54147c..6d3f000 100644 --- a/VisualPinball.Engine.DMD.Unity/Runtime/NativeWindowDestinationFactory.cs +++ b/VisualPinball.Engine.DMD.Unity/Runtime/NativeWindowDestinationFactory.cs @@ -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; } diff --git a/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPlugin.cs b/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPlugin.cs index c937408..0f06494 100644 --- a/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPlugin.cs +++ b/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPlugin.cs @@ -10,6 +10,8 @@ using System.Linq; using System.Threading; using System.Threading.Tasks; +using Newtonsoft.Json; +using Newtonsoft.Json.Linq; using UnityEngine; using VisualPinball.Engine.DMD.Unity; using VisualPinball.Plugins; @@ -17,7 +19,7 @@ namespace VisualPinball.Engine.DMD.Player { - internal sealed class DmdPlugin : PlayerPlugin, IPluginTick, IPluginEmergencyStop, IPluginDeferredCleanup + internal sealed class DmdPlugin : PlayerPlugin, IPluginTick, IPluginEmergencyStop, IPluginDeferredCleanup, IDiagnosticsSource { private readonly PluginApplicationContext _application; private readonly List _presentations = new List(); @@ -28,23 +30,34 @@ internal sealed class DmdPlugin : PlayerPlugin, IPluginTick, IPluginEmergencySto private DmdBridgePlayer _bridge; private GameObject _root; private PluginResourceBinding _binding; + // kept for diagnostics + private PluginSettingsSnapshot _gameSettings; + private string _colorizationLibrary; + private string _colorizationAsset; + private string _stagedColorization; internal DmdPlugin(PluginApplicationContext application) { _application = application; } public override Task PrepareGameAsync(PluginGameContext game, CancellationToken cancellation) { var scene = game.Capabilities.Require(UnityPluginCapability.GameScene); var settings = DmdPluginFactory.Settings(game.Settings); settings.RomName = game.Identity.Key; - var asset = ColorizationCatalog.Select(DmdPluginFactory.ColorizationLibrary(game.Settings.String("AltColorRoot")), game.Identity.Key, game.Settings.String("Colorization", "auto"), game.Settings.String("VniKey").Length > 0); + _gameSettings = game.Settings; + _colorizationLibrary = DmdPluginFactory.ColorizationLibrary(game.Settings.String("AltColorRoot")); + var asset = ColorizationCatalog.Select(_colorizationLibrary, game.Identity.Key, game.Settings.String("Colorization", "auto"), game.Settings.String("VniKey").Length > 0); settings.EnableColorization = asset != null; + _colorizationAsset = asset != null ? asset.Id + " (" + asset.Label + ")" : "none"; if (asset != null) { _nativeResources.Own(ColorizationCatalog.Stage(asset, Path.Combine(_application.Configuration.DirectoryFor(_application.Plugin), "cache", "colorizations"), game.Identity.Key, out string staged)); settings.AltColorPath = staged; + _stagedColorization = staged; } + _application.Logger.Info($"Colorization for {game.Identity.Key}: {_colorizationAsset}, library {(_colorizationLibrary.Length > 0 ? _colorizationLibrary : "not found")}."); var outputs = game.Capabilities.Require(UnityPluginCapability.Outputs); foreach (var output in OutputIds(settings)) _nativeResources.Own(outputs.Acquire(output, _application.Plugin.Id)); _root = new GameObject("DMD plugin"); _root.SetActive(false); _root.transform.SetParent(scene.Table.transform, false); game.Lifetime.Own(new Subscription(() => { if (_root != null) UnityEngine.Object.Destroy(_root); })); _bridge = _root.AddComponent(); + _bridge.DiagnosticsOwner = this; var selection = new PluginResourceSelection(ResourceKind.Display) { Controller = game.ControllerId, Session = game.Session, Role = "dmd", Intent = asset == null ? ResourceView.Original : ResourceView.Identification, Accepts = asset == null ? DisplayEncoding.Gray2 | DisplayEncoding.Gray4 | DisplayEncoding.Luminance8 | DisplayEncoding.Rgb24 : DisplayEncoding.Gray2 | DisplayEncoding.Gray4 }; @@ -61,8 +74,31 @@ public override Task PrepareGameAsync(PluginGameContext game, CancellationToken _binding.Changed += ReportBinding; game.Lifetime.Own(new Subscription(() => _binding.Changed -= ReportBinding)); _root.SetActive(true); + DiagnosticsContext.Set(this); return Task.CompletedTask; } + + public string DiagnosticsSection => "DMD"; + + public void Describe(DiagnosticsWriter writer) + { + writer.Add("plugin", DmdPluginFactory.Id); + writer.Add("colorization.library", string.IsNullOrEmpty(_colorizationLibrary) ? "not found" : _colorizationLibrary); + writer.Add("colorization.asset", _colorizationAsset ?? "none"); + if (_stagedColorization != null) writer.Add("colorization.staged", _stagedColorization); + if (_binding != null) { + writer.Add("source", _binding.Descriptor?.Id ?? "none"); + writer.Add("source.state", _binding.State.ToString()); + if (_binding.State != ResourceBindingState.Bound && !string.IsNullOrEmpty(_binding.Diagnostic)) writer.Add("source.diagnostic", _binding.Diagnostic); + } + if (_bridge != null) _bridge.Describe(writer); + if (_gameSettings?.Values != null) { + // VniKey is redacted by AddSetting + foreach (var property in _gameSettings.Values.Properties()) { + writer.AddSetting("setting." + property.Name, property.Value.Type == JTokenType.String ? (string)property.Value : property.Value.ToString(Formatting.None)); + } + } + } private static IEnumerable OutputIds(DmdBridgeSettings settings) { if (settings.EnableZeDmd) yield return string.IsNullOrWhiteSpace(settings.ZeDmdPort) ? "usb:zedmd:auto" : "serial:" + settings.ZeDmdPort.ToUpperInvariant(); @@ -72,7 +108,17 @@ private static IEnumerable OutputIds(DmdBridgeSettings settings) if (settings.EnablePinDmd1) yield return "usb:pindmd1:auto"; if (settings.EnablePinDmd2) yield return "usb:pindmd2:auto"; } - private void ReportBinding() { if (_binding.State != ResourceBindingState.Bound) _application.Log(_binding.Diagnostic); } + private void ReportBinding() + { + // No DMD source for the game, or it went away: something the table or settings decide. + // Waiting is normal for tables without a DMD; a resource that's named but missing is not. + if (_binding.State != ResourceBindingState.Bound && _binding.State != ResourceBindingState.Disposed && !string.IsNullOrEmpty(_binding.Diagnostic)) { + if (_binding.State == ResourceBindingState.Waiting && _binding.Diagnostic.StartsWith("Waiting", StringComparison.Ordinal)) _application.Logger.Info(_binding.Diagnostic); + else _application.Logger.Warn(_binding.Diagnostic); + } + // Changed can be raised from the frame path, so publish from the owner thread + _application.Scheduler.Post(() => { if (_gameSettings != null) DiagnosticsContext.Set(this); }); + } public void Tick(double unscaledSeconds) { foreach (var presentation in _dispatch) presentation.Pump(); } public override async Task StopGameAsync(CancellationToken cancellation) { @@ -81,6 +127,8 @@ public override async Task StopGameAsync(CancellationToken cancellation) await _application.Scheduler.Switch(); if (_bridge != null) Quiescence = _bridge.ShutdownCompletion; ReleaseWhenStopped(); _presentations.Clear(); _dispatch = Array.Empty(); + _gameSettings = null; + DiagnosticsContext.Remove(DiagnosticsSection); } } public void EmergencyStop() { if (_bridge != null) { _bridge.Shutdown(); Quiescence = _bridge.ShutdownCompletion; } ReleaseWhenStopped(); } diff --git a/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPluginFactory.cs b/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPluginFactory.cs index 28551e7..cae8f87 100644 --- a/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPluginFactory.cs +++ b/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPluginFactory.cs @@ -15,15 +15,18 @@ using LibDmd.Output.Pixelcade; using Newtonsoft.Json.Linq; using Newtonsoft.Json; +using NLog; using UnityEngine; using VisualPinball.Engine.DMD.Unity; using VisualPinball.Plugins; +using Logger = NLog.Logger; namespace VisualPinball.Engine.DMD.Player { internal sealed class DmdPluginFactory : IPlayerPluginFactory, IPluginSettingsProvider { internal const string Id = "org.visualpinball.dmd"; + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); public PluginDescriptor Descriptor { get; } = new PluginDescriptor(Id, "DMD", "Colorizations, your in-scene DMD and native displays, with optional cabinet hardware.") { EnabledByDefault = true, Category = "Displays", Order = 20 }; public PluginSettingsSchema Schema { get; } = BuildSchema(); public IPluginSettingsProvider SettingsProvider => this; @@ -95,7 +98,7 @@ internal static string ColorizationLibrary(string configured) { if (!string.IsNullOrWhiteSpace(configured)) return configured.Trim(); foreach (string candidate in DefaultColorizationLibraries()) { - try { if (!string.IsNullOrWhiteSpace(candidate) && Directory.Exists(candidate)) return candidate; } catch (Exception) { } + try { if (!string.IsNullOrWhiteSpace(candidate) && Directory.Exists(candidate)) return candidate; } catch (Exception error) { Logger.Debug(error, "[DMD] Skipping colorization library candidate {Path:l}.", candidate); } } return ""; } @@ -106,18 +109,18 @@ internal static string ColorizationLibrary(string configured) private static IEnumerable DefaultColorizationLibraries() { string config = null; - try { config = DmdBridgeConfig.ResolveEnvConfigPath(); } catch (Exception) { } + try { config = DmdBridgeConfig.ResolveEnvConfigPath(); } catch (Exception error) { Logger.Debug(error, "[DMD] Could not resolve DMDDEVICE_CONFIG."); } if (!string.IsNullOrWhiteSpace(config)) yield return Path.Combine(Path.GetDirectoryName(config) ?? "", "altcolor"); string home = Environment.GetEnvironmentVariable("VPM_HOME"); if (!string.IsNullOrWhiteSpace(home)) yield return Path.Combine(home.Trim().Trim('"'), "altcolor"); foreach (string roms in (VisualPinball.Unity.GamelogicPaths.RomFolder ?? "").Split(';')) { if (string.IsNullOrWhiteSpace(roms)) continue; string parent = null; - try { parent = Path.GetDirectoryName(Path.GetFullPath(roms.Trim()).TrimEnd(Path.DirectorySeparatorChar, Path.AltDirectorySeparatorChar)); } catch (Exception) { } + try { parent = Path.GetDirectoryName(Path.GetFullPath(roms.Trim()).TrimEnd(Path.DirectorySeparatorChar, Path.AltDirectorySeparatorChar)); } catch (Exception error) { Logger.Debug(error, "[DMD] Skipping ROM folder {Path:l}.", roms); } if (parent != null) yield return Path.Combine(parent, "altcolor"); } string libDmd = null; - try { libDmd = PathUtil.GetVpmFolder("altcolor", "[DMD]"); } catch (Exception) { } + try { libDmd = PathUtil.GetVpmFolder("altcolor", "[DMD]"); } catch (Exception error) { Logger.Debug(error, "[DMD] Could not locate VPinMAME's altcolor folder."); } yield return libDmd; } public IReadOnlyList Validate(PluginChoiceRequest request) diff --git a/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPresentationDestination.cs b/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPresentationDestination.cs index 63a633b..1ada7ab 100644 --- a/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPresentationDestination.cs +++ b/VisualPinball.Engine.DMD.Unity/Runtime/Plugins/DmdPresentationDestination.cs @@ -18,6 +18,8 @@ namespace VisualPinball.Engine.DMD.Player internal sealed class DmdPresentationDestination : IRgb24Destination { private static long _instances; + // per destination, so each one gets to report its first faults + private readonly VisualPinball.Unity.LogThrottle _faultThrottle = new VisualPinball.Unity.LogThrottle(3, TimeSpan.FromSeconds(30)); private readonly DisplayResourceSource _source; private readonly IDisposable _publication; private readonly long _instance; @@ -31,7 +33,13 @@ internal sealed class DmdPresentationDestination : IRgb24Destination internal DmdPresentationDestination(PluginApplicationContext application, PluginResourceDescriptor original) { _instance = Interlocked.Increment(ref _instances); - _source = new DisplayResourceSource(fault: error => application.Log(error.Message)); + _source = new DisplayResourceSource(fault: error => { + // a consumer of the presentation frames threw: a bug, and it would throw on every frame + // plugin messages are plain text and reports group them by text, so keep it constant + if (_faultThrottle.ShouldLog()) { + application.Logger.Error(error, "A consumer of the DMD presentation failed."); + } + }); _publication = application.Resources.Publish(new PluginResourceDescriptor(original.Id + "/presentation/" + application.Plugin.Id, application.Plugin.Id, original.Controller, original.Label + " ยท DMD presentation", original.Role, ResourceKind.Display, original.Session, _instance, ResourceView.Presentation, DisplayEncoding.Rgb24, original.Id), _source); }