diff --git a/Editor/VisualPinball.Engine.Mpf.Unity.Editor.asmdef b/Editor/VisualPinball.Engine.Mpf.Unity.Editor.asmdef index 0d32245a..54fd4fd1 100644 --- a/Editor/VisualPinball.Engine.Mpf.Unity.Editor.asmdef +++ b/Editor/VisualPinball.Engine.Mpf.Unity.Editor.asmdef @@ -5,7 +5,8 @@ "VisualPinball.Engine", "VisualPinball.Unity", "VisualPinball.Unity.Editor", - "VisualPinball.Engine.Mpf.Unity" + "VisualPinball.Engine.Mpf.Unity", + "VisualPinball.Plugins" ], "includePlatforms": [ "Editor" ], "excludePlatforms": [], diff --git a/Runtime/MediaController/Core/BcpInterface.cs b/Runtime/MediaController/Core/BcpInterface.cs index ef298ccb..1e781cb7 100644 --- a/Runtime/MediaController/Core/BcpInterface.cs +++ b/Runtime/MediaController/Core/BcpInterface.cs @@ -84,6 +84,8 @@ public event EventHandler> ConnectionS public readonly BcpMessageHandlers MessageHandlers; private static Logger Logger = LogManager.GetCurrentClassLogger(); + private static readonly LogThrottle ParseFailedThrottle = new(5, TimeSpan.FromSeconds(30)); + private static readonly LogOncePerKey UnknownCommandLog = new(); public BcpInterface(BcpInterfaceOptions options) { @@ -98,7 +100,8 @@ public void EnqueueMessage(ISentMessage message) { BcpMessage bcpMessage = message.ToGenericMessage(); if (_options.LogSentMessages) - Logger.Info($"Sending BCP message: {bcpMessage}"); + // the user asked for every message in the inspector + Logger.Info("Sending BCP message: {Message:l}", bcpMessage.ToString()); Server.EnqueueMessage(bcpMessage); } @@ -156,6 +159,12 @@ private void OnHelloMessageReceived(object sender, HelloMessage message) } else { + Logger.Warn( + "MPF speaks BCP {MpfBcpVersion}, but VPE's media controller speaks {VpeBcpVersion}. " + + "The media controller won't work with this MPF version.", + message.BcpSpecVersion, + Constants.BcpSpecVersion + ); string originalHelloMessage = message.ToGenericMessage().ToString(); response = new ErrorMessage( message: "unknown protocol version", @@ -193,7 +202,8 @@ private async Task HandleReceivedMessagesLoop(CancellationToken ct) private void HandleReceivedMessage(BcpMessage message) { if (_options.LogReceivedMessages) - Logger.Info($"BCP Message received: {message}"); + // the user asked for every message in the inspector + Logger.Info("BCP message received: {Message:l}", message.ToString()); if (MessageHandlers.Handlers.TryGetValue(message.Command, out var handler)) { @@ -203,15 +213,25 @@ private void HandleReceivedMessage(BcpMessage message) } catch (BcpParseException e) { - Logger.Error($"Failed to parse BCP message. Message: {message} Exception: {e}"); + // MPF sent something this media controller doesn't understand + if (ParseFailedThrottle.ShouldLog(out var suppressed)) + Logger.Warn( + e, + "Could not parse BCP message {Message:l} from MPF ({Suppressed} similar suppressed before).", + message.ToString(), + suppressed + ); } } else { - Logger.Error( - $"No parser registered for BCP message with command '{message.Command}' " - + $"Message: {message}" - ); + if (UnknownCommandLog.ShouldLog(message.Command ?? "")) + Logger.Warn( + "MPF sent BCP command {Command}, which VPE's media controller doesn't handle: " + + "{Message:l}. Further messages with this command are not logged.", + message.Command, + message.ToString() + ); EnqueueMessage(new ErrorMessage("unknown command", message.ToString())); } } diff --git a/Runtime/MediaController/Core/BcpServer.cs b/Runtime/MediaController/Core/BcpServer.cs index e0c22c99..cfff2ece 100644 --- a/Runtime/MediaController/Core/BcpServer.cs +++ b/Runtime/MediaController/Core/BcpServer.cs @@ -16,7 +16,9 @@ using System.Text; using System.Threading; using System.Threading.Tasks; +using NLog; using VisualPinball.Unity; +using Logger = NLog.Logger; namespace VisualPinball.Engine.Mpf.Unity.MediaController { @@ -73,6 +75,8 @@ private set private const char Terminator = '\n'; + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + private enum ReceiveEndReason { Finished, @@ -158,6 +162,7 @@ private async Task CommunicateAsync(int port, CancellationToken ct) try { listener.Start(); + Logger.Info("BCP server listening on port {Port} for MPF", port); while (true) { ct.ThrowIfCancellationRequested(); @@ -165,6 +170,7 @@ private async Task CommunicateAsync(int port, CancellationToken ct) { using TcpClient client = listener.AcceptTcpClient(); ConnectionState = BcpConnectionState.Connected; + Logger.Info("MPF connected to the BCP server"); using NetworkStream stream = client.GetStream(); const int bufferSize = 1024; var byteBuffer = new byte[bufferSize]; @@ -196,6 +202,7 @@ private async Task CommunicateAsync(int port, CancellationToken ct) ConnectionState = BcpConnectionState.Disconnecting; await SendMessagesAsync(stream, ct); _disconnectRequested.Reset(); + Logger.Info("MPF disconnected from the BCP server"); } else { @@ -203,6 +210,12 @@ private async Task CommunicateAsync(int port, CancellationToken ct) } } } + catch (Exception e) when (e is SocketException or System.IO.IOException) + { + // e.g. the port is taken, or MPF dropped the connection + Logger.Warn(e, "The BCP server on port {Port} stopped, the media controller no longer gets MPF's messages.", port); + throw; + } finally { listener.Stop(); diff --git a/Runtime/MediaController/Core/MpfEventRequester.cs b/Runtime/MediaController/Core/MpfEventRequester.cs index ddc6a219..355841d9 100644 --- a/Runtime/MediaController/Core/MpfEventRequester.cs +++ b/Runtime/MediaController/Core/MpfEventRequester.cs @@ -10,7 +10,8 @@ // SOFTWARE. using System.Collections.Generic; -using UnityEngine; +using NLog; +using Logger = NLog.Logger; namespace VisualPinball.Engine.Mpf.Unity.MediaController { @@ -29,6 +30,8 @@ public class MpfEventRequester private readonly CreateMessage _createStopListeningMessage; private readonly Dictionary> _listeners = new(); private bool _canSendMonitoringRequests = false; + + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); private bool CanSendMonitoringRequests { get => _canSendMonitoringRequests; @@ -69,9 +72,10 @@ public void AddListener(object listener, T @event) SendStartMonitoringRequest(@event); } else if (!_listeners[@event].Add(listener)) - Debug.LogError( - $"[EventPool] Cannot add listener '{listener}' to event '{@event}' because it " - + "was already added." + Logger.Error( + "Cannot add listener {Listener:l} to MPF event {Event} because it was already added.", + listener?.GetType().Name, + @event?.ToString() ); } @@ -89,9 +93,10 @@ public void RemoveListener(object listener, T @event) } } else - Debug.LogError( - $"[EventPool] Cannot remove listener '{listener}' from event '{@event}' " - + "because it is not a listener." + Logger.Error( + "Cannot remove listener {Listener:l} from MPF event {Event} because it is not a listener.", + listener?.GetType().Name, + @event?.ToString() ); } diff --git a/Runtime/MediaController/Messages/Monitor/MonitorStartMessage.cs b/Runtime/MediaController/Messages/Monitor/MonitorStartMessage.cs index d64090b5..839d2003 100644 --- a/Runtime/MediaController/Messages/Monitor/MonitorStartMessage.cs +++ b/Runtime/MediaController/Messages/Monitor/MonitorStartMessage.cs @@ -11,7 +11,8 @@ using System; using Newtonsoft.Json.Linq; -using UnityEngine; +using NLog; +using Logger = NLog.Logger; namespace VisualPinball.Engine.Mpf.Unity.MediaController.Messages.Monitor { @@ -21,6 +22,8 @@ public class MonitorStartMessage : EventArgs, ISentMessage private const string CategoryParamName = "category"; public readonly MonitoringCategory Category; + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + public MonitorStartMessage(MonitoringCategory category) { Category = category; @@ -30,9 +33,9 @@ public BcpMessage ToGenericMessage() { var categoryString = Category.GetStringValue(); if (string.IsNullOrEmpty(categoryString)) - Debug.LogError( - "[MonitorStartMessage] Cannot create proper BCP message because monitoring " - + "category has no associated string value." + Logger.Error( + "Cannot create a proper BCP message, monitoring category {Category} has no string value.", + Category ); return new( command: Command, diff --git a/Runtime/MediaController/Messages/Monitor/MonitorStopMessage.cs b/Runtime/MediaController/Messages/Monitor/MonitorStopMessage.cs index e1508eca..e914345f 100644 --- a/Runtime/MediaController/Messages/Monitor/MonitorStopMessage.cs +++ b/Runtime/MediaController/Messages/Monitor/MonitorStopMessage.cs @@ -11,7 +11,8 @@ using System; using Newtonsoft.Json.Linq; -using UnityEngine; +using NLog; +using Logger = NLog.Logger; namespace VisualPinball.Engine.Mpf.Unity.MediaController.Messages.Monitor { @@ -21,6 +22,8 @@ public class MonitorStopMessage : EventArgs, ISentMessage private const string CategoryParamName = "category"; public readonly MonitoringCategory Category; + private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + public MonitorStopMessage(MonitoringCategory category) { Category = category; @@ -30,9 +33,9 @@ public BcpMessage ToGenericMessage() { var categoryString = Category.GetStringValue(); if (string.IsNullOrEmpty(categoryString)) - Debug.LogError( - "[MonitorStopMessage] Cannot create proper BCP message because " - + "monitoring category has no associated string value." + Logger.Error( + "Cannot create a proper BCP message, monitoring category {Category} has no string value.", + Category ); return new BcpMessage( command: Command, diff --git a/Runtime/MpfGamelogicEngine.cs b/Runtime/MpfGamelogicEngine.cs index 7ae4d659..d68ea610 100644 --- a/Runtime/MpfGamelogicEngine.cs +++ b/Runtime/MpfGamelogicEngine.cs @@ -35,8 +35,13 @@ public class MpfGamelogicEngine : MonoBehaviour, IGamelogicEngine, IGamelogicInputThreading, - IGamelogicNativeOutputs + IGamelogicNativeOutputs, + IDiagnosticsSource, + IGamelogicStartupStatus { + /// + public string StartupFailure => _mpfWrangler?.StartupError; + [SerializeField] private MpfWranglerOptions _wranglerOptions; @@ -111,6 +116,17 @@ private MpfWrangler MpfWrangler } private Player _player; private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + // per engine, so one table's mapping problems don't hide the next one's + private readonly LogOncePerKey _unmappedSwitchLog = new(); + private readonly LogOncePerKey _unknownLampNumberLog = new(); + private readonly LogOncePerKey _unknownCoilNumberLog = new(); + private readonly LogOncePerKey _unknownHardwareRuleLog = new(); + private readonly LogOncePerKey _segmentDisplayLog = new(); + private static readonly LogThrottle SwitchNotSentThrottle = new(3, TimeSpan.FromSeconds(30)); + private static readonly LogThrottle SwitchSendFailedThrottle = new(3, TimeSpan.FromSeconds(30)); + + // for diagnostics: whether the machine description stored in VPE matches MPF's + private string _machineDescriptionStatus = "not checked"; private readonly MpfOutputModel _nativeOutputModel = new(MonotonicMs); private NativeOutputSink _nativeOutputSink; @@ -252,21 +268,66 @@ CancellationToken ct ExecuteMpfSetSegmentDisplayFrameRequest; MachineState initialState = CompileMachineState(player); - await MpfWrangler.StartMpf(initialState, ct); + try + { + await MpfWrangler.StartMpf(initialState, ct); + } + catch (Exception e) when (MpfWrangler.IsEnvironmentFailure(e)) + { + // MPF is missing, didn't respond or exited. The wrangler logged what failed and + // how to find out why. That's for the user to fix, not a VPE error, so the table + // runs without gamelogic. + return; + } OnDisplaysRequested?.Invoke(this, new RequestedDisplays(_mpfDotMatrixDisplays)); OnStarted?.Invoke(this, EventArgs.Empty); - var md = await MpfWrangler.GetMachineDescription(timeout: 3f, ct); - if (!DoesMachineDescriptionMatch(md)) - Logger.Warn("Mismatch between MPF's and VPE's machine description detected."); + MachineDescription md; + try + { + md = await MpfWrangler.GetMachineDescription(timeout: 3f, ct); + } + catch (Exception e) when (MpfWrangler.IsEnvironmentFailure(e)) + { + _machineDescriptionStatus = "could not be read from MPF"; + Logger.Warn(e, "Could not get MPF's machine description to compare it with VPE's."); + return; + } + + var differences = GetMachineDescriptionDifferences(md); + if (differences.Count > 0) + { + _machineDescriptionStatus = $"differs ({differences.Count} difference(s))"; + Logger.Warn( + "MPF's machine description differs from the one stored in VPE: {Differences:l}. " + + "Click 'Get Machine Description' in the inspector of the MPF gamelogic " + + "engine to update it.", + string.Join("; ", differences) + ); + } else + { + _machineDescriptionStatus = "matches"; Logger.Info("MPF's machine description matches VPE's machine description."); + } } private async void OnDestroy() { - await MpfWrangler.StopMpf(); + try + { + await MpfWrangler.StopMpf(); + } + catch (Exception e) when (e is OperationCanceledException || MpfWrangler.IsEnvironmentFailure(e)) + { + // MPF was gone already, or didn't answer the quit request + Logger.Debug(e, "MPF didn't shut down cleanly."); + } + catch (Exception e) + { + Logger.Error(e, "Stopping MPF failed."); + } MpfWrangler.MpfFadeLightRequestReceived -= ExecuteMpfFadeLightRequest; MpfWrangler.MpfPulseCoilRequestReceived -= ExecuteMpfPulseCoilRequest; MpfWrangler.MpfEnableCoilRequestReceived -= ExecuteMpfEnableCoilRequest; @@ -286,29 +347,30 @@ out BcpInterface bcpInterface ) { var gle = requestingComponent.GetComponentInParent(); - - var errorMessage = - $"Component '{requestingComponent.GetType()}' on game object " - + $"'{requestingComponent.gameObject.name}' is requesting a BCP interface, but " - + "{0} The BCP interface is used to communicate with the Mission Pinball Framework"; + var componentType = requestingComponent.GetType().Name; + var gameObjectName = requestingComponent.gameObject.name; if (!Application.isPlaying) { - Logger.Error(string.Format(errorMessage, "the game is not running.")); + Logger.Warn( + "{Component:l} on {GameObject} requests a BCP interface (used to talk to MPF), " + + "but the game is not running.", + componentType, + gameObjectName + ); bcpInterface = null; return false; } if (gle == null) { - Logger.Error( - string.Format( - errorMessage, - "no MPF game logic engine was found. Make sure the requesting component is " - + "attached to an object that is part of the table hierarchy and " - + "attach an 'MpfGamelogicEngine' component to the root object of the " - + "table or remove the component that requested the BCP interface." - ) + Logger.Warn( + "{Component:l} on {GameObject} requests a BCP interface (used to talk to MPF), " + + "but no MPF gamelogic engine was found. Make sure the component is part of " + + "the table hierarchy and that the table's root object has an " + + "'MpfGamelogicEngine' component, or remove the component.", + componentType, + gameObjectName ); bcpInterface = null; return false; @@ -316,13 +378,12 @@ out BcpInterface bcpInterface if (gle._wranglerOptions.MediaController != MpfMediaController.Included) { - Logger.Error( - string.Format( - errorMessage, - "the game logic engine is not configured to use the integrated MPF media " - + "controller. Set 'Media Controller' to 'Included' in the MPF game " - + "logic engine inspector." - ) + Logger.Warn( + "{Component:l} on {GameObject} requests a BCP interface (used to talk to MPF), " + + "but the MPF gamelogic engine doesn't use the included media controller. " + + "Set 'Media Controller' to 'Included' in its inspector.", + componentType, + gameObjectName ); bcpInterface = null; return false; @@ -330,8 +391,12 @@ out BcpInterface bcpInterface if (gle.MpfWrangler == null) { + // the property creates the wrangler, so this can't happen Logger.Error( - string.Format(errorMessage, "the game logic engine is not initialized.") + "{Component:l} on {GameObject} requests a BCP interface, but the MPF gamelogic " + + "engine is not initialized.", + componentType, + gameObjectName ); bcpInterface = null; return false; @@ -341,6 +406,84 @@ out BcpInterface bcpInterface return true; } + #region Diagnostics + + public string DiagnosticsSection => "MPF"; + + public void Describe(DiagnosticsWriter writer) + { + var options = _wranglerOptions; + var wrangler = _mpfWrangler; + if (options == null) + { + writer.Add("options", "none"); + return; + } + + writer.Add("mpf-version", wrangler?.MpfVersion ?? ( + options.StartupBehavior == MpfStartupBehavior.DelayConnection + ? "unknown (not queried with startup behavior DelayConnection)" + : "unknown (not connected)" + )); + writer.Add("state", MpfState.ToString()); + if (!string.IsNullOrEmpty(wrangler?.StartupError)) + writer.Add("startup-error", wrangler.StartupError); + if (wrangler?.ExitCode is int exitCode) + writer.Add("exit-code", exitCode); + + writer.Add("executable-source", options.ExecutableSource.ToString()); + if (!string.IsNullOrEmpty(wrangler?.ExecutablePath)) + { + writer.Add("executable", wrangler.ExecutablePath); + if (options.ExecutableSource == MpfExecutableSource.Included) + writer.Add("executable-found", System.IO.File.Exists(wrangler.ExecutablePath)); + writer.Add("arguments", wrangler.Arguments ?? ""); + } + + var machineFolder = options.MachineFolder; + writer.Add("machine-folder", machineFolder ?? ""); + if (!string.IsNullOrEmpty(machineFolder)) + writer.Add("machine-folder-found", System.IO.Directory.Exists(machineFolder)); + writer.Add("machine-description", _machineDescriptionStatus); + + writer.Add("media-controller", options.MediaController.ToString()); + if (options.MediaController == MpfMediaController.Included) + { + writer.Add("bcp-state", BcpState.ToString()); + writer.AddSetting("bcp-port", options.BcpInterfaceOptions?.Port); + } + + var effectiveOutput = wrangler?.EffectiveOutputType; + writer.Add( + "output", + effectiveOutput == null || effectiveOutput == options.OutputType + ? options.OutputType.ToString() + : $"{effectiveOutput} (configured {options.OutputType}, release builds hide MPF)" + ); + if (wrangler != null && wrangler.OutputCaptured) + writer.Add("mpf-output", "captured in the log (logger Mpf.Process)"); + var logFolder = wrangler?.MpfLogFolder + ?? (string.IsNullOrEmpty(machineFolder) ? null : System.IO.Path.Combine(machineFolder, "logs")); + if (logFolder != null) + { + writer.Add("mpf-log-folder", logFolder); + writer.Add("mpf-log-folder-found", System.IO.Directory.Exists(logFolder)); + } + + writer.AddSetting("startup-behavior", options.StartupBehavior); + writer.AddSetting("connect-timeout", options.ConnectTimeout); + writer.AddSetting("connect-delay", options.ConnectDelay); + writer.AddSetting("verbose-logging", options.VerboseLogging); + writer.AddSetting("cache-config-files", options.CacheConfigFiles); + writer.AddSetting("force-reload-config", options.ForceReloadConfig); + writer.AddSetting("force-load-all-assets", options.ForceLoadAllAssetsOnStart); + writer.Add("switches", _requestedSwitches?.Length ?? 0); + writer.Add("coils", _requestedCoils?.Length ?? 0); + writer.Add("lamps", _requestedLamps?.Length ?? 0); + } + + #endregion + public void DisplayChanged(DisplayFrameData displayFrameData) { } public bool GetCoil(string id) @@ -373,37 +516,79 @@ public void SetLamp(string id, float value, bool isCoil, LampSource source) public async void Switch(string id, bool isClosed) { - OnSwitchChanged?.Invoke(this, new SwitchEventArgs2(id, isClosed)); + // async void: nothing observes this method's task, so whatever goes wrong is logged here + try + { + OnSwitchChanged?.Invoke(this, new SwitchEventArgs2(id, isClosed)); - // VPE runs MPF's hardware rules as wires, so their coils only show up here. - if (_mpfSwitchNumbers.TryGetNumberByName(id, out var ruleSwitchNumber)) - _nativeOutputModel.EnqueueSwitch(ruleSwitchNumber, isClosed); + // VPE runs MPF's hardware rules as wires, so their coils only show up here. + if (_mpfSwitchNumbers.TryGetNumberByName(id, out var ruleSwitchNumber)) + _nativeOutputModel.EnqueueSwitch(ruleSwitchNumber, isClosed); - if (_mpfSwitchNumbers.ContainsName(id)) - { - if (MpfWrangler.MpfState == MpfState.Connected) + if (_mpfSwitchNumbers.ContainsName(id)) { - var number = _mpfSwitchNumbers.GetNumberByName(id); - var change = new SwitchChanges + var state = MpfWrangler.MpfState; + if (state == MpfState.Connected) + { + var number = _mpfSwitchNumbers.GetNumberByName(id); + var change = new SwitchChanges + { + SwitchNumber = number, + SwitchState = isClosed, + }; + await MpfWrangler.SendSwitchChange(change); + } + else if (SwitchNotSentThrottle.ShouldLog(out var suppressed)) { - SwitchNumber = number, - SwitchState = isClosed, - }; - await MpfWrangler.SendSwitchChange(change); + if (suppressed == 0) + Logger.Warn( + "Switch {SwitchId} was not sent to MPF, because MPF is {MpfState}.", + id, + state + ); + else + Logger.Warn( + "Switch {SwitchId} was not sent to MPF, because MPF is {MpfState} " + + "({Suppressed} similar suppressed).", + id, + state, + suppressed + ); + } } - else + else if (_unmappedSwitchLog.ShouldLog(id)) { Logger.Warn( - $"Switch change '{id}' will not be sent to MPF because MPF is not ready" + "Switch {SwitchId} has no MPF number, so its changes are not sent to MPF. Click " + + "'Get Machine Description' in the inspector of the MPF gamelogic engine " + + "to update it. Further changes of this switch are not logged.", + id ); } } - else + catch (OperationCanceledException) { - Logger.Error( - $"Switch '{id}' is defined in the MPF game logic engine but not" - + $" associated with an MPF number. State change cannot be forwarded to MPF." - ); + // MPF is stopping + } + catch (Exception e) when (MpfWrangler.IsEnvironmentFailure(e)) + { + if (SwitchSendFailedThrottle.ShouldLog(out var suppressed)) + Logger.Warn( + e, + "Could not send switch {SwitchId} to MPF ({Suppressed} similar suppressed before).", + id, + suppressed + ); + } + catch (Exception e) + { + if (SwitchSendFailedThrottle.ShouldLog(out var suppressed)) + Logger.Error( + e, + "Sending switch {SwitchId} to MPF failed ({Suppressed} similar suppressed before).", + id, + suppressed + ); } } @@ -510,25 +695,73 @@ StateChangedEventArgs args BcpStateChanged?.Invoke(this, args); } - private bool DoesMachineDescriptionMatch(MachineDescription md) + /// + /// Lists how the machine description stored in VPE differs from MPF's, e.g. + /// "coils not in MPF: c_flipper". Empty if they match. + /// + private List GetMachineDescriptionDifferences(MachineDescription md) + { + var differences = new List(); + AddDifference( + differences, + "switches not in MPF or with a different type", + _requestedSwitches + .Where(gleSw => !md.Switches.Any(mpfSw => MpfExtensions.Equals(gleSw, mpfSw))) + .Select(sw => sw.Id) + ); + AddDifference( + differences, + "coils not in MPF", + _requestedCoils + .Where(gleCoil => !md.Coils.Any(mpfCoil => MpfExtensions.Equals(gleCoil, mpfCoil))) + .Select(coil => coil.Id) + ); + AddDifference( + differences, + "lights not in MPF", + _requestedLamps + .Where(gleLamp => !md.Lights.Any(mpfLight => MpfExtensions.Equals(gleLamp, mpfLight))) + .Select(lamp => lamp.Id) + ); + AddDifference( + differences, + "DMDs not in MPF or with a different size", + (_mpfDotMatrixDisplays ?? Array.Empty()) + .Where(cfg => !md.Dmds.Any(mpfDmd => MpfExtensions.Equals(cfg, mpfDmd))) + .Select(cfg => cfg.Id) + ); + AddDifference( + differences, + "switch numbers", + _mpfSwitchNumbers.GetDifferences(md.GetSwitchNumbersByNameDict()) + ); + AddDifference( + differences, + "coil numbers", + _mpfCoilNumbers.GetDifferences(md.GetCoilNumbersByNameDict()) + ); + AddDifference( + differences, + "light numbers", + _mpfLampNumbers.GetDifferences(md.GetLampNumbersByNameDict()) + ); + return differences; + } + + private static void AddDifference( + List differences, + string what, + IEnumerable names + ) { - return _requestedSwitches.All( - (gleSw) => md.Switches.Any((mpfSw) => MpfExtensions.Equals(gleSw, mpfSw)) - ) - && _requestedCoils.All( - (gleCoil) => md.Coils.Any((mpfCoil) => MpfExtensions.Equals(gleCoil, mpfCoil)) - ) - && _requestedLamps.All( - (gleLamp) => - md.Lights.Any((mpfLight) => MpfExtensions.Equals(gleLamp, mpfLight)) - ) - && _mpfDotMatrixDisplays.All( - (displayCfg) => - md.Dmds.Any((mpfDmd) => MpfExtensions.Equals(displayCfg, mpfDmd)) - ) - && _mpfSwitchNumbers.Equals(md.GetSwitchNumbersByNameDict()) - && _mpfCoilNumbers.Equals(md.GetCoilNumbersByNameDict()) - && _mpfLampNumbers.Equals(md.GetLampNumbersByNameDict()); + const int maxNames = 10; + var list = names.ToList(); + if (list.Count == 0) + return; + var text = string.Join(", ", list.Take(maxNames)); + if (list.Count > maxNames) + text += $" and {list.Count - maxNames} more"; + differences.Add($"{what}: {text}"); } private MachineState CompileMachineState(Player player) @@ -559,10 +792,12 @@ private void ExecuteMpfFadeLightRequest(object sender, FadeLightRequest request) { if (_mpfLampNumbers.TryGetNameByNumber(fade.LightNumber, out var lampName)) args.Add(new LampEventArgs(lampName, fade.TargetBrightness)); - else - Logger.Error( - $"MPF sent a lamp number '{fade.LightNumber}' that is" - + $" not associated with a lamp id." + else if (_unknownLampNumberLog.ShouldLog(fade.LightNumber)) + Logger.Warn( + "MPF drives light number {LightNumber}, which VPE has no lamp for. Update the " + + "machine description in the MPF gamelogic engine inspector. Further " + + "changes of this light are not logged.", + fade.LightNumber ); } OnLampsChanged?.Invoke(this, new LampsEventArgs(args.ToArray())); @@ -578,10 +813,7 @@ private void ExecuteMpfPulseCoilRequest(object sender, PulseCoilRequest request) _player.ScheduleAction(request.PulseMs, () => SetCoil(coilName, false)); } else - Logger.Error( - $"MPF sent a coil number '{request.CoilNumber}'" - + $" that is not associated with a coil id." - ); + LogUnknownCoilNumber(request.CoilNumber); } private void ExecuteMpfEnableCoilRequest(object sender, EnableCoilRequest request) @@ -591,10 +823,7 @@ private void ExecuteMpfEnableCoilRequest(object sender, EnableCoilRequest reques if (_mpfCoilNumbers.TryGetNameByNumber(request.CoilNumber, out var coilName)) SetCoil(coilName, true); else - Logger.Error( - $"MPF sent a coil number '{request.CoilNumber}'" - + $" that is not associated with a coil id." - ); + LogUnknownCoilNumber(request.CoilNumber); } private void ExecuteMpfCommandDisableCoilRequest(object sender, DisableCoilRequest request) @@ -604,10 +833,7 @@ private void ExecuteMpfCommandDisableCoilRequest(object sender, DisableCoilReque if (_mpfCoilNumbers.TryGetNameByNumber(request.CoilNumber, out var coilName)) SetCoil(coilName, false); else - Logger.Error( - $"MPF sent a coil number '{request.CoilNumber}'" - + $" that is not associated with a coil id." - ); + LogUnknownCoilNumber(request.CoilNumber); } private void ExecuteMpfConfigureHardwareRuleRequest( @@ -629,11 +855,7 @@ ConfigureHardwareRuleRequest request ) _player.AddHardwareRule(switchName, coilName); else - Logger.Error( - $"MPF wants to add a hardware rule for switch number " - + $"'{switchNumber} and coil number '{coilNumber}.' At least one " - + $"of them is not associated with an id." - ); + LogUnknownHardwareRule(switchNumber, coilNumber); } private void ExecuteMpfRemoveHardwareRuleRequest( @@ -650,13 +872,34 @@ RemoveHardwareRuleRequest request ) _player.RemoveHardwareRule(switchName, coilName); else - Logger.Error( - $"MPF wants to remove a hardware rule for switch number " - + $"'{switchNumber} and coil number '{coilNumber}.' At least one " - + $"of them is not associated with an id." + LogUnknownHardwareRule(switchNumber, coilNumber); + } + + private void LogUnknownCoilNumber(string coilNumber) + { + if (_unknownCoilNumberLog.ShouldLog(coilNumber)) + Logger.Warn( + "MPF drives coil number {CoilNumber}, which VPE has no coil for. Update the " + + "machine description in the MPF gamelogic engine inspector. Further " + + "changes of this coil are not logged.", + coilNumber ); } + private void LogUnknownHardwareRule(string switchNumber, string coilNumber) + { + if (!_unknownHardwareRuleLog.ShouldLog(switchNumber + "/" + coilNumber)) + return; + Logger.Warn( + "MPF configured a hardware rule for switch number {SwitchNumber} and coil number " + + "{CoilNumber}, but VPE has no {Missing:l} for it, so the rule is ignored. Update " + + "the machine description in the MPF gamelogic engine inspector.", + switchNumber, + coilNumber, + _mpfSwitchNumbers.ContainsNumber(switchNumber) ? "coil" : "switch" + ); + } + private void ExecuteMpfSetDmdFrameRequest(object sender, SetDmdFrameRequest request) { var frameData = new DisplayFrameData( @@ -672,10 +915,12 @@ private void ExecuteMpfSetSegmentDisplayFrameRequest( SetSegmentDisplayFrameRequest request ) { - Logger.Error( - "MPF sent a segment display frame, but segment displays are not yet supported by " - + "VPEs MPF integration." - ); + if (_segmentDisplayLog.ShouldLog(request.Name ?? "")) + Logger.Warn( + "MPF sent a frame for segment display {Display}, but VPE's MPF integration doesn't " + + "support segment displays yet. Further frames are ignored silently.", + request.Name + ); } } } diff --git a/Runtime/MpfNameNumberDictionary.cs b/Runtime/MpfNameNumberDictionary.cs index 2c60bcf1..6ecf3dc7 100644 --- a/Runtime/MpfNameNumberDictionary.cs +++ b/Runtime/MpfNameNumberDictionary.cs @@ -50,6 +50,25 @@ public bool Equals(Dictionary numbersByName) ); } + /// + /// Lists the names whose number differs from the given map, for logging. + /// + public IEnumerable GetDifferences(Dictionary numbersByName) + { + foreach (var kvp in numbersByName) + { + if (!_numbersByName.TryGetValue(kvp.Key, out var number)) + yield return $"{kvp.Key} (only in MPF)"; + else if (number != kvp.Value) + yield return $"{kvp.Key} (VPE {number}, MPF {kvp.Value})"; + } + foreach (var name in _numbersByName.Keys) + { + if (!numbersByName.ContainsKey(name)) + yield return $"{name} (only in VPE)"; + } + } + public void Init(Dictionary numbersByName) { _namesByNumber.Clear(); diff --git a/Runtime/MpfWrangler.cs b/Runtime/MpfWrangler.cs index 2b1021e4..8208d311 100644 --- a/Runtime/MpfWrangler.cs +++ b/Runtime/MpfWrangler.cs @@ -217,6 +217,70 @@ public class MpfWrangler : IDisposable private static readonly Logger Logger = LogManager.GetCurrentClassLogger(); + // MPF's own output (stdout/stderr), when it's not shown in a terminal window + private static readonly Logger ProcessLogger = LogManager.GetLogger("Mpf.Process"); + private static readonly LogThrottle ProcessWarnThrottle = new(200, TimeSpan.FromSeconds(1)); + private static readonly LogThrottle EmptyCommandThrottle = new(3, TimeSpan.FromSeconds(30)); + private static readonly LogThrottle CommandHandlerFailedThrottle = new(3, TimeSpan.FromSeconds(30)); + private static readonly LogOncePerKey UnknownCommandLog = new(); + + private string _startupStep; + private string _machineFolder; + private volatile bool _processExitExpected; + private bool _launchedViaTerminal; + private bool _echoOutputToConsole; + private bool _inStdErrTraceback; + + /// + /// MPF's version, as reported when VPE connected to it. Null until then, and with + /// , which doesn't ask. + /// + public string MpfVersion { get; private set; } + + /// + /// The MPF executable that was started last, or null if none was. + /// + public string ExecutablePath { get; private set; } + + /// + /// The command line arguments MPF was started with last. + /// + public string Arguments { get; private set; } + + /// + /// Why the last start failed, or null. + /// + public string StartupError { get; private set; } + + /// + /// MPF's exit code, once it exited. + /// + public int? ExitCode { get; private set; } + + /// + /// Whether MPF's output is captured into the log (logger Mpf.Process). When MPF + /// runs in a terminal window, it isn't, and has its log. + /// + public bool OutputCaptured { get; private set; } + + /// + /// Where MPF writes its own log files. + /// + public string MpfLogFolder + { + get + { + // resolving the machine folder needs the main thread, so it's cached when MPF starts + var machineFolder = _machineFolder ?? _options.MachineFolder; + return string.IsNullOrEmpty(machineFolder) ? null : Path.Combine(machineFolder, "logs"); + } + } + + /// + /// The output type actually used. Release builds never show MPF's terminal. + /// + public MpfOutputType EffectiveOutputType => OutputTypeOverride; + public MpfState MpfState { get => _mpfState; @@ -260,13 +324,24 @@ public async Task StartMpf(MachineState initialState, CancellationToken ct) try { MpfState = MpfState.Starting; + StartupError = null; + _machineFolder = _options.MachineFolder; if (_options.ExecutableSource != MpfExecutableSource.AssumeRunning) { + _startupStep = "starting the MPF process"; KillAllMpfProcesses(); _mpfProcess = StartMpfProcess(); } + else + { + Logger.Info( + "Connecting to an MPF instance that is expected to be running already, at {Address:l}", + _grpcAddress + ); + } + _startupStep = "connecting to MPF"; if (_options.MediaController == MpfMediaController.Included) await Task.WhenAll(BcpInterface.StartServer(), ConnectToMpf(initialState, ct)); else @@ -274,13 +349,20 @@ public async Task StartMpf(MachineState initialState, CancellationToken ct) } catch (Exception ex) { + LogStartupFailure(ex); try { if (_options.MediaController == MpfMediaController.Included) await BcpInterface.StopServer(); } + catch (Exception stopEx) + { + // the start failure is what counts, it's rethrown below + Logger.Debug(stopEx, "Stopping the BCP server after the failed MPF start failed too."); + } finally { + _processExitExpected = true; if (_mpfProcess != null && !_mpfProcess.HasExited) _mpfProcess.Kill(); @@ -297,9 +379,8 @@ public async Task StartMpf(MachineState initialState, CancellationToken ct) { _startStopSemaphore.Ref.Release(); } - - throw ex; } + throw; } try @@ -354,6 +435,8 @@ public async Task StopMpf() return; } + _processExitExpected = true; + Logger.Info("Stopping MPF"); try { MpfState = MpfState.Stopping; @@ -410,7 +493,10 @@ await Task.WhenAny( ) != processExited.Task && !_mpfProcess.HasExited ) + { + Logger.Info("MPF didn't quit within a second, killing it."); _mpfProcess.Kill(); + } } } finally @@ -444,14 +530,33 @@ await Task.WhenAny( private Process StartMpfProcess() { + var executable = GetExecutablePath(); + var machineFolder = _machineFolder; + ExecutablePath = executable; + Arguments = GetCmdArgs(machineFolder); + ExitCode = null; + + if (_options.ExecutableSource == MpfExecutableSource.Included && !File.Exists(executable)) + throw new FileNotFoundException( + $"The MPF executable included with VPE is missing at {executable}.", + executable + ); + if (!Directory.Exists(machineFolder)) + Logger.Warn( + "MPF machine folder {MachineFolder:l} does not exist, so MPF won't find its config.", + machineFolder + ); + var process = new Process(); - process.StartInfo.FileName = GetExecutablePath(); - process.StartInfo.Arguments = GetCmdArgs(_options.MachineFolder); + process.StartInfo.FileName = executable; + process.StartInfo.Arguments = Arguments; // Make sure the MPF window does not pop up in release builds + var outputType = OutputTypeOverride; var createWindow = - OutputTypeOverride is MpfOutputType.LogInTerminal or MpfOutputType.TableInTerminal; + outputType is MpfOutputType.LogInTerminal or MpfOutputType.TableInTerminal; process.StartInfo.UseShellExecute = createWindow; process.StartInfo.CreateNoWindow = !createWindow; + _launchedViaTerminal = false; if (createWindow) { @@ -460,6 +565,7 @@ private Process StartMpfProcess() process.StartInfo.Arguments = $"-e {process.StartInfo.FileName} {process.StartInfo.Arguments}"; process.StartInfo.FileName = "x-terminal-emulator"; + _launchedViaTerminal = true; #elif UNITY_EDITOR_OSX || UNITY_STANDALONE_OSX // There is no way to pass arguments trough the macOS terminal, // so create a temporary shell script that contains the arguments. @@ -474,50 +580,184 @@ private Process StartMpfProcess() Process.Start("chmod", $"u+x {tmpScriptPath}"); process.StartInfo.Arguments = $"-a Terminal {tmpScriptPath}"; process.StartInfo.FileName = "open"; + _launchedViaTerminal = true; #endif } else { + // Always read what MPF writes: a redirected pipe that nobody reads fills up and + // blocks MPF. It goes to the log, so a user's report includes it. process.StartInfo.RedirectStandardError = true; process.StartInfo.RedirectStandardOutput = true; - - if (OutputTypeOverride == MpfOutputType.LogInUnityConsole) - { - process.OutputDataReceived += new DataReceivedEventHandler( - (sender, e) => Logger.Info($"MPF: {e.Data}") - ); - - process.ErrorDataReceived += new DataReceivedEventHandler( - (sender, e) => - { - if (e.Data == null) - return; - // For some reason, all (?) output from MPF is routed to this error handler, - // so filter manually. This is obviously flawed and will sometimes fail - // to recognize errors. - // https://github.com/missionpinball/mpf/issues/1866 - if (e.Data.Contains("ERROR") || e.Data.Contains("Exception")) - Logger.Error($"MPF: {e.Data}"); - else if (e.Data.Contains("WARNING")) - Logger.Warn($"MPF: {e.Data}"); - else - Logger.Info($"MPF: {e.Data}"); - } - ); - } + _echoOutputToConsole = outputType == MpfOutputType.LogInUnityConsole; + _inStdErrTraceback = false; + process.OutputDataReceived += (sender, e) => LogProcessOutput(e.Data, false); + process.ErrorDataReceived += (sender, e) => LogProcessOutput(e.Data, true); } + process.EnableRaisingEvents = true; + process.Exited += (sender, args) => OnProcessExited(process); + _processExitExpected = false; + OutputCaptured = !createWindow; + process.Start(); - if (OutputTypeOverride == MpfOutputType.LogInUnityConsole) + if (OutputCaptured) { process.BeginOutputReadLine(); process.BeginErrorReadLine(); } + Logger.Info( + "Started MPF (pid {Pid}): {Executable:l} {Arguments:l}, machine folder {MachineFolder:l}, " + + "output {OutputType}, media controller {MediaController}, MPF's own log in {MpfLogFolder:l}", + process.Id, + process.StartInfo.FileName, + process.StartInfo.Arguments, + machineFolder, + outputType, + _options.MediaController, + MpfLogFolder + ); + return process; } + /// + /// Logs a line MPF wrote. Called on a thread pool thread, one line at a time per stream. + /// + /// + /// MPF writes all of its log to stderr (https://github.com/missionpinball/mpf/issues/1866), + /// so the level is guessed from the text. Errors in there come from the machine config or + /// the game code, not from VPE, so they're warnings here. + /// + private void LogProcessOutput(string line, bool fromStdErr) + { + if (line == null) + return; + + var warn = fromStdErr && IsProblemLine(line, ref _inStdErrTraceback); + if (warn) + { + if (ProcessWarnThrottle.ShouldLog(out var suppressed)) + { + if (suppressed == 0) + ProcessLogger.Warn("{Line:l}", line); + else + ProcessLogger.Warn( + "{Line:l} ({Suppressed} lines suppressed before)", + line, + suppressed + ); + } + } + else if (_echoOutputToConsole) + // the user chose to see MPF's output in the Unity console + ProcessLogger.Info("{Line:l}", line); + else if (ProcessLogger.IsDebugEnabled) + ProcessLogger.Debug("{Line:l}", line); + } + + /// + /// Whether a line of Python output reports a problem. Lines of a traceback count too. + /// + private static bool IsProblemLine(string line, ref bool inTraceback) + { + if (line.StartsWith("Traceback (most recent call last)", StringComparison.Ordinal)) + { + inTraceback = true; + return true; + } + if (inTraceback) + { + // indented lines are the stack, the first one that isn't is the exception + if (line.Length > 0 && char.IsWhiteSpace(line[0])) + return true; + inTraceback = false; + return true; + } + return line.Contains("ERROR") + || line.Contains("CRITICAL") + || line.Contains("Exception") + || line.Contains("WARNING"); + } + + private void OnProcessExited(Process process) + { + int? exitCode = null; + try + { + exitCode = process.ExitCode; + } + catch (Exception e) + { + // already disposed after stopping + Logger.Debug(e, "Cannot read MPF's exit code."); + } + // a terminal launcher's exit code is the launcher's, not MPF's, which keeps running + if (!_launchedViaTerminal) + ExitCode = exitCode; + var code = exitCode?.ToString() ?? "unknown"; + + if (_launchedViaTerminal) + // that's the terminal launcher, which returns right away + Logger.Debug("MPF's terminal launcher exited with code {ExitCode:l}", code); + else if (_processExitExpected) + Logger.Info("MPF exited with code {ExitCode:l}", code); + else + Logger.Warn( + "MPF exited unexpectedly with code {ExitCode:l}. {Hint:l}", + code, + OutputCaptured + ? "Its output is in the log above (logger Mpf.Process)." + : $"Its own log is in {MpfLogFolder}." + ); + } + + /// + /// Whether a start failed because of something outside of VPE: MPF missing, not + /// responding, or exiting. + /// + internal static bool IsEnvironmentFailure(Exception e) => + e is System.ComponentModel.Win32Exception or TimeoutException or RpcException or IOException; + + private void LogStartupFailure(Exception ex) + { + var step = _startupStep ?? "starting MPF"; + if (ex is OperationCanceledException) + { + Logger.Debug("MPF startup was cancelled while {Step:l}.", step); + return; + } + + StartupError = $"{step}: {ex.Message}"; + var executable = + _options.ExecutableSource == MpfExecutableSource.AssumeRunning + ? "(assumed to be running)" + : ExecutablePath; + if (IsEnvironmentFailure(ex)) + Logger.Warn( + ex, + "Could not start MPF, failed while {Step:l}. Executable source {ExecutableSource}, " + + "executable {Executable:l}, machine folder {MachineFolder:l}. {Hint:l}", + step, + _options.ExecutableSource, + executable, + _machineFolder, + OutputCaptured + ? "MPF's output is in the log above (logger Mpf.Process)." + : $"MPF's own log is in {MpfLogFolder}." + ); + else + // not something the user can fix, the caller logs the exception + Logger.Info( + "MPF startup failed while {Step:l} (executable {Executable:l}, machine folder {MachineFolder:l})", + step, + executable, + _machineFolder + ); + } + private async Task ConnectToMpf(MachineState initialState, CancellationToken ct) { var handler = new YetAnotherHttpHandler() { Http2Only = true }; @@ -534,6 +774,7 @@ private async Task ConnectToMpf(MachineState initialState, CancellationToken ct) if (_options.ExecutableSource != MpfExecutableSource.AssumeRunning) await WaitUntilMpfReady(_grpcChannel, ct); + _startupStep = "opening the command streams to MPF"; var client = new MpfHardwareService.MpfHardwareServiceClient(_grpcChannel); _mpfCommandStreamCall = client.Start( initialState, @@ -544,7 +785,7 @@ private async Task ConnectToMpf(MachineState initialState, CancellationToken ct) ); _receiveMpfCommandsTask = ReceiveMpfCommands(); } - catch (Exception ex) + catch (Exception) { _mpfCommunicationCts?.Cancel(); try @@ -552,7 +793,12 @@ private async Task ConnectToMpf(MachineState initialState, CancellationToken ct) if (_receiveMpfCommandsTask != null) await _receiveMpfCommandsTask; } - catch (OperationCanceledException) { } + catch (Exception receiveEx) + { + // the connection failure is what counts, it's rethrown below + if (receiveEx is not OperationCanceledException) + Logger.Debug(receiveEx, "Receiving MPF commands failed while giving up connecting."); + } finally { _receiveMpfCommandsTask = null; @@ -564,8 +810,8 @@ private async Task ConnectToMpf(MachineState initialState, CancellationToken ct) _mpfSwitchStreamCall = null; _mpfCommandStreamCall?.Dispose(); _mpfCommandStreamCall = null; - throw ex; } + throw; } } @@ -655,17 +901,28 @@ private async Task WaitUntilMpfReady(GrpcChannel channel, CancellationToken ct) switch (_options.StartupBehavior) { case MpfStartupBehavior.PingUntilReady: - Logger.Info("Attempting to connect to MPF..."); - var startTime = DateTime.Now; + _startupStep = "waiting for MPF to respond"; + Logger.Info( + "Waiting for MPF to respond at {Address:l}, for up to {Timeout} s", + _grpcAddress, + _options.ConnectTimeout + ); + var stopwatch = Stopwatch.StartNew(); var pingResponse = await PingUntilResponseOrTimeout(channel, ct); - var timeToConnect = (DateTime.Now - startTime).TotalSeconds; + MpfVersion = pingResponse.MpfVersion; Logger.Info( - $"Successfully connected to MPF in {timeToConnect:F2} seconds. " - + $"MPF version: {pingResponse.MpfVersion}" + "Connected to MPF {MpfVersion:l} in {ConnectMs} ms", + MpfVersion, + stopwatch.ElapsedMilliseconds ); break; case MpfStartupBehavior.DelayConnection: + _startupStep = "waiting before connecting to MPF"; await Task.Delay(TimeSpan.FromSeconds(_options.ConnectDelay), ct); + Logger.Info( + "Connecting to MPF after a fixed delay of {Delay} s (its version isn't queried in this mode)", + _options.ConnectDelay + ); break; } } @@ -747,7 +1004,7 @@ CancellationToken ct catch (Exception ex) when (ex is IOException or RpcException) { ct.ThrowIfCancellationRequested(); - Logger.Info("No response from MPF. Retrying..."); + Logger.Debug("No response from MPF yet, retrying."); await Task.Delay(TimeSpan.FromSeconds(0.2)); } } @@ -762,7 +1019,21 @@ await _mpfCommandStreamCall.ResponseStream.MoveNext(_mpfCommunicationCts.Token) ) { var command = _mpfCommandStreamCall.ResponseStream.Current; - ExecuteMpfCommand(command); + try + { + ExecuteMpfCommand(command); + } + catch (Exception e) + { + // a handler failing must not stop the commands that follow + if (CommandHandlerFailedThrottle.ShouldLog(out var suppressed)) + Logger.Error( + e, + "Handling MPF command {Command} failed ({Suppressed} similar suppressed before)", + command.CommandCase, + suppressed + ); + } } } catch (RpcException ex) @@ -770,7 +1041,13 @@ await _mpfCommandStreamCall.ResponseStream.MoveNext(_mpfCommunicationCts.Token) if (!_mpfCommunicationCts.IsCancellationRequested) { MpfState = MpfState.NotConnected; - Logger.Error($"Unable to receive commands from MPF: {ex}"); + Logger.Warn( + ex, + "Lost the connection to MPF, it no longer drives the table. {Hint:l}", + OutputCaptured + ? "MPF's output is in the log above (logger Mpf.Process)." + : $"MPF's own log is in {MpfLogFolder}." + ); } } } @@ -780,7 +1057,8 @@ private void ExecuteMpfCommand(Commands command) switch (command.CommandCase) { case Commands.CommandOneofCase.None: - Logger.Warn("Received empty command from MPF."); + if (EmptyCommandThrottle.ShouldLog()) + Logger.Warn("Received an empty command from MPF."); break; case Commands.CommandOneofCase.FadeLight: MpfFadeLightRequestReceived?.Invoke(this, command.FadeLight); @@ -813,7 +1091,14 @@ private void ExecuteMpfCommand(Commands command) ); break; default: - Logger.Error($"MPF sent an unknown commnand '{command}'"); + // a newer MPF than this package knows + if (UnknownCommandLog.ShouldLog((int)command.CommandCase)) + Logger.Warn( + "MPF sent command {CommandCase}, which VPE doesn't know. MPF {MpfVersion:l} " + + "may be newer than VPE's MPF package.", + (int)command.CommandCase, + MpfVersion ?? "(unknown version)" + ); break; } } @@ -823,11 +1108,17 @@ private void KillAllMpfProcesses() var mpfProcesses = Process.GetProcessesByName("mpf"); try { + var killed = 0; foreach (var process in mpfProcesses) { if (!process.HasExited) + { process.Kill(); + killed++; + } } + if (killed > 0) + Logger.Info("Killed {Count} MPF process(es) that were still running.", killed); } finally {