chore: Add logging to all JSON schema/parsing errors and command messages

qdot · qdot · commit d6a93caa63af · 2017-07-19T00:29:27.000-07:00
We don't receive command messages at high frequency, and
schema/parsing errors should be extremely visible. Add better logging
for both of these.
diff --git a/Buttplug.Core/ButtplugJsonMessageParser.cs b/Buttplug.Core/ButtplugJsonMessageParser.cs
@@ -77,46 +77,44 @@ public ButtplugMessage[] Deserialize(string aJsonMsg)
             _bpLogger.Trace($"Got JSON Message: {aJsonMsg}");
 
             var res = new List<ButtplugMessage>();
-            JArray a;
+            JArray msgArray;
             try
             {
-                a = JArray.Parse(aJsonMsg);
+                msgArray = JArray.Parse(aJsonMsg);
             }
             catch (JsonReaderException e)
             {
-                _bpLogger.Debug($"Not valid JSON: {aJsonMsg}");
-                _bpLogger.Debug(e.Message);
-                res.Add(new Error("Not valid JSON", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));
+                res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "Not valid JSON"));
                 return res.ToArray();
             }
 
-            var errors = _schema.Validate(a);
+            var errors = _schema.Validate(msgArray);
             if (errors.Any())
             {
-                res.Add(new Error("Message does not conform to schema: " + string.Join(", ", errors.Select(aErr => aErr.ToString()).ToArray()), ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));
+                res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "Message does not conform to schema: " + string.Join(", ", errors.Select(aErr => aErr.ToString()).ToArray())));
                 return res.ToArray();
             }
 
-            if (!a.Any())
+            if (!msgArray.Any())
             {
-                res.Add(new Error("No messages in array", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));
+                res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "No messages in array"));
                 return res.ToArray();
             }
 
             // JSON input is an array of messages.
             // We currently only handle the first one.
-            foreach (var o in a.Children<JObject>())
+            foreach (var o in msgArray.Children<JObject>())
             {
                 if (!o.Properties().Any())
                 {
-                    res.Add(new Error("No message name available", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));
+                    res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "No message name available"));
                     continue;
                 }
 
                 var msgName = o.Properties().First().Name;
                 if (!_messageTypes.Keys.Any() || !_messageTypes.Keys.Contains(msgName))
                 {
-                    res.Add(new Error($"{msgName} is not a valid message class", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));
+                    res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, $"{msgName} is not a valid message class"));
                     continue;
                 }
 
diff --git a/Buttplug.Server.Managers.XInputGamepadManager/XInputGamepadDevice.cs b/Buttplug.Server.Managers.XInputGamepadManager/XInputGamepadDevice.cs
@@ -20,6 +20,7 @@ public XInputGamepadDevice(IButtplugLogManager aLogManager, Controller aDevice)
 
         private Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)
         {
+            BpLogger.Debug("Stopping Device " + Name);
             return HandleSingleMotorVibrateCmd(new SingleMotorVibrateCmd(aMsg.DeviceIndex, 0, aMsg.Id));
         }
 
diff --git a/Buttplug.Server/Bluetooth/Devices/FleshlightLaunch.cs b/Buttplug.Server/Bluetooth/Devices/FleshlightLaunch.cs
@@ -70,6 +70,7 @@ private Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)
             // actually stop movement. It just makes it move really slow.
             // However, since each move it makes is finite (unlike setting vibration on some devices),
             // so we can assume it will be a short move, similar to what we do for the Kiiroo toys.
+            BpLogger.Debug("Stopping Device " + Name);
             return Task.FromResult<ButtplugMessage>(new Ok(aMsg.Id));
         }
 
diff --git a/Buttplug.Server/Bluetooth/Devices/Kiiroo.cs b/Buttplug.Server/Bluetooth/Devices/Kiiroo.cs
@@ -52,6 +52,7 @@ private Task<ButtplugMessage> HandleStopDeviceCmd([NotNull] ButtplugDeviceMessag
             // Right now, this is a nop. The Onyx doesn't have any sort of permanent movement state,
             // and its longest movement is like 150ms or so. The Pearl is supposed to vibrate but I've
             // never gotten that to work. So for now, we just return ok.
+            BpLogger.Debug("Stopping Device " + Name);
             return Task.FromResult<ButtplugMessage>(new Ok(aMsg.Id));
         }
 
diff --git a/Buttplug.Server/Bluetooth/Devices/Lovense.cs b/Buttplug.Server/Bluetooth/Devices/Lovense.cs
@@ -141,6 +141,7 @@ public Lovense(IButtplugLogManager aLogManager,
 
         private async Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)
         {
+            BpLogger.Debug("Stopping Device " + Name);
             return await HandleSingleMotorVibrateCmd(new SingleMotorVibrateCmd(aMsg.DeviceIndex, 0, aMsg.Id));
         }
 
diff --git a/Buttplug.Server/Bluetooth/Devices/Vibratissimo.cs b/Buttplug.Server/Bluetooth/Devices/Vibratissimo.cs
@@ -54,6 +54,7 @@ public Vibratissimo(IButtplugLogManager aLogManager,
 
         private async Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)
         {
+            BpLogger.Debug("Stopping Device " + Name);
             return await HandleSingleMotorVibrateCmd(new SingleMotorVibrateCmd(aMsg.DeviceIndex, 0, aMsg.Id));
         }
 
diff --git a/Buttplug.Server/Bluetooth/Devices/VorzeA10Cyclone.cs b/Buttplug.Server/Bluetooth/Devices/VorzeA10Cyclone.cs
@@ -44,6 +44,7 @@ public VorzeA10Cyclone(IButtplugLogManager aLogManager,
 
         private async Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)
         {
+            BpLogger.Debug("Stopping Device " + Name);
             return await HandleVorzeA10CycloneCmd(new VorzeA10CycloneCmd(aMsg.DeviceIndex, 0, false, aMsg.Id));
         }
 
diff --git a/Buttplug.Server/ButtplugServer.cs b/Buttplug.Server/ButtplugServer.cs
@@ -146,6 +146,7 @@ public async Task<ButtplugMessage> SendMessage([NotNull] ButtplugMessage aMsg)
             switch (aMsg)
             {
                 case RequestLog m:
+                    _bpLogger.Debug("Got RequestLog Message");
                     _bpLogManager.Level = m.LogLevel;
                     return new Ok(id);
 
@@ -159,6 +160,7 @@ public async Task<ButtplugMessage> SendMessage([NotNull] ButtplugMessage aMsg)
                     return new Ok(id);
 
                 case RequestServerInfo rsi:
+                    _bpLogger.Debug("Got RequestServerInfo Message");
                     _receivedRequestServerInfo = true;
                     _pingTimer?.Start();
                     ClientConnected?.Invoke(this, new MessageReceivedEventArgs(rsi));
diff --git a/Buttplug.Server/DeviceManager.cs b/Buttplug.Server/DeviceManager.cs
@@ -126,14 +126,17 @@ public async Task<ButtplugMessage> SendMessage(ButtplugMessage aMsg)
             switch (aMsg)
             {
                 case StartScanning _:
+                    _bpLogger.Debug("Got StartScanning Message");
                     StartScanning();
                     return new Ok(id);
 
                 case StopScanning _:
+                    _bpLogger.Debug("Got StopScanning Message");
                     StopScanning();
                     return new Ok(id);
 
                 case StopAllDevices _:
+                    _bpLogger.Debug("Got StopAllDevices Message");
                     var isOk = true;
                     var errorMsg = string.Empty;
                     foreach (var d in _devices.ToList())
@@ -155,6 +158,7 @@ public async Task<ButtplugMessage> SendMessage(ButtplugMessage aMsg)
 
                     return new Error(errorMsg, Error.ErrorClass.ERROR_DEVICE, aMsg.Id);
                 case RequestDeviceList _:
+                    _bpLogger.Debug("Got RequestDeviceList Message");
                     var msgDevices = _devices
                         .Select(aDevice => new DeviceMessageInfo(aDevice.Key, aDevice.Value.Name,
                                 GetAllowedMessageTypesAsStrings(aDevice.Value).ToArray())).ToList();

Original file line number	Diff line number	Diff line change
`@@ -77,46 +77,44 @@ public ButtplugMessage[] Deserialize(string aJsonMsg)`
`77`	`77`	`_bpLogger.Trace($"Got JSON Message: {aJsonMsg}");`
`78`	`78`
`79`	`79`	`var res = new List<ButtplugMessage>();`
`80`		`- JArray a;`
	`80`	`+ JArray msgArray;`
`81`	`81`	`try`
`82`	`82`	`{`
`83`		`- a = JArray.Parse(aJsonMsg);`
	`83`	`+ msgArray = JArray.Parse(aJsonMsg);`
`84`	`84`	`}`
`85`	`85`	`catch (JsonReaderException e)`
`86`	`86`	`{`
`87`		`- _bpLogger.Debug($"Not valid JSON: {aJsonMsg}");`
`88`		`- _bpLogger.Debug(e.Message);`
`89`		`- res.Add(new Error("Not valid JSON", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));`
	`87`	`+ res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "Not valid JSON"));`
`90`	`88`	`return res.ToArray();`
`91`	`89`	`}`
`92`	`90`
`93`		`- var errors = _schema.Validate(a);`
	`91`	`+ var errors = _schema.Validate(msgArray);`
`94`	`92`	`if (errors.Any())`
`95`	`93`	`{`
`96`		`- res.Add(new Error("Message does not conform to schema: " + string.Join(", ", errors.Select(aErr => aErr.ToString()).ToArray()), ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));`
	`94`	`+ res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "Message does not conform to schema: " + string.Join(", ", errors.Select(aErr => aErr.ToString()).ToArray())));`
`97`	`95`	`return res.ToArray();`
`98`	`96`	`}`
`99`	`97`
`100`		`- if (!a.Any())`
	`98`	`+ if (!msgArray.Any())`
`101`	`99`	`{`
`102`		`- res.Add(new Error("No messages in array", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));`
	`100`	`+ res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "No messages in array"));`
`103`	`101`	`return res.ToArray();`
`104`	`102`	`}`
`105`	`103`
`106`	`104`	`// JSON input is an array of messages.`
`107`	`105`	`// We currently only handle the first one.`
`108`		`- foreach (var o in a.Children<JObject>())`
	`106`	`+ foreach (var o in msgArray.Children<JObject>())`
`109`	`107`	`{`
`110`	`108`	`if (!o.Properties().Any())`
`111`	`109`	`{`
`112`		`- res.Add(new Error("No message name available", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));`
	`110`	`+ res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, "No message name available"));`
`113`	`111`	`continue;`
`114`	`112`	`}`
`115`	`113`
`116`	`114`	`var msgName = o.Properties().First().Name;`
`117`	`115`	`if (!_messageTypes.Keys.Any() \|\| !_messageTypes.Keys.Contains(msgName))`
`118`	`116`	`{`
`119`		`- res.Add(new Error($"{msgName} is not a valid message class", ErrorClass.ERROR_MSG, ButtplugConsts.SystemMsgId));`
	`117`	`+ res.Add(_bpLogger.LogErrorMsg(ButtplugConsts.SystemMsgId, ErrorClass.ERROR_MSG, $"{msgName} is not a valid message class"));`
`120`	`118`	`continue;`
`121`	`119`	`}`
`122`	`120`
Original file line number	Diff line number	Diff line change
`@@ -20,6 +20,7 @@ public XInputGamepadDevice(IButtplugLogManager aLogManager, Controller aDevice)`
`20`	`20`
`21`	`21`	`private Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)`
`22`	`22`	`{`
	`23`	`+ BpLogger.Debug("Stopping Device " + Name);`
`23`	`24`	`return HandleSingleMotorVibrateCmd(new SingleMotorVibrateCmd(aMsg.DeviceIndex, 0, aMsg.Id));`
`24`	`25`	`}`
`25`	`26`
Original file line number	Diff line number	Diff line change
`@@ -70,6 +70,7 @@ private Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)`
`70`	`70`	`// actually stop movement. It just makes it move really slow.`
`71`	`71`	`// However, since each move it makes is finite (unlike setting vibration on some devices),`
`72`	`72`	`// so we can assume it will be a short move, similar to what we do for the Kiiroo toys.`
	`73`	`+ BpLogger.Debug("Stopping Device " + Name);`
`73`	`74`	`return Task.FromResult<ButtplugMessage>(new Ok(aMsg.Id));`
`74`	`75`	`}`
`75`	`76`
Original file line number	Diff line number	Diff line change
`@@ -52,6 +52,7 @@ private Task<ButtplugMessage> HandleStopDeviceCmd([NotNull] ButtplugDeviceMessag`
`52`	`52`	`// Right now, this is a nop. The Onyx doesn't have any sort of permanent movement state,`
`53`	`53`	`// and its longest movement is like 150ms or so. The Pearl is supposed to vibrate but I've`
`54`	`54`	`// never gotten that to work. So for now, we just return ok.`
	`55`	`+ BpLogger.Debug("Stopping Device " + Name);`
`55`	`56`	`return Task.FromResult<ButtplugMessage>(new Ok(aMsg.Id));`
`56`	`57`	`}`
`57`	`58`
Original file line number	Diff line number	Diff line change
`@@ -141,6 +141,7 @@ public Lovense(IButtplugLogManager aLogManager,`
`141`	`141`
`142`	`142`	`private async Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)`
`143`	`143`	`{`
	`144`	`+ BpLogger.Debug("Stopping Device " + Name);`
`144`	`145`	`return await HandleSingleMotorVibrateCmd(new SingleMotorVibrateCmd(aMsg.DeviceIndex, 0, aMsg.Id));`
`145`	`146`	`}`
`146`	`147`
Original file line number	Diff line number	Diff line change
`@@ -54,6 +54,7 @@ public Vibratissimo(IButtplugLogManager aLogManager,`
`54`	`54`
`55`	`55`	`private async Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)`
`56`	`56`	`{`
	`57`	`+ BpLogger.Debug("Stopping Device " + Name);`
`57`	`58`	`return await HandleSingleMotorVibrateCmd(new SingleMotorVibrateCmd(aMsg.DeviceIndex, 0, aMsg.Id));`
`58`	`59`	`}`
`59`	`60`
Original file line number	Diff line number	Diff line change
`@@ -44,6 +44,7 @@ public VorzeA10Cyclone(IButtplugLogManager aLogManager,`
`44`	`44`
`45`	`45`	`private async Task<ButtplugMessage> HandleStopDeviceCmd(ButtplugDeviceMessage aMsg)`
`46`	`46`	`{`
	`47`	`+ BpLogger.Debug("Stopping Device " + Name);`
`47`	`48`	`return await HandleVorzeA10CycloneCmd(new VorzeA10CycloneCmd(aMsg.DeviceIndex, 0, false, aMsg.Id));`
`48`	`49`	`}`
`49`	`50`