Logging levels, process output and diagnostics for the MPF engine

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": [],

Runtime/MediaController/Core/BcpInterface.cs

@@ -84,6 +84,8 @@ public event EventHandler<StateChangedEventArgs<BcpConnectionState>> 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<string> 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()));
             }
         }

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,13 +162,15 @@ 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();
                     if (listener.Pending())
                     {
                         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,13 +202,20 @@ 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
                     {
                         await Task.Delay(100);
                     }
                 }
             }
+            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();

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<T>
         private readonly CreateMessage _createStopListeningMessage;
         private readonly Dictionary<T, HashSet<object>> _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()
                 );
         }
 

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,

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,