From 6a96288968b2ef35eb39b39a093f73d904ec5c9e Mon Sep 17 00:00:00 2001 From: Dominique Louis Date: Thu, 19 Oct 2023 10:07:59 +0100 Subject: [PATCH 1/5] Remove -m arg and use --verbose to set verbose logging. --- Source/v2/Meadow.Cli/Program.cs | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/Source/v2/Meadow.Cli/Program.cs b/Source/v2/Meadow.Cli/Program.cs index 4f4c853a..bf789832 100644 --- a/Source/v2/Meadow.Cli/Program.cs +++ b/Source/v2/Meadow.Cli/Program.cs @@ -15,14 +15,9 @@ public class Program public static async Task Main(string[] args) { var logLevel = LogEventLevel.Information; - var logModifier = args.FirstOrDefault(a => a.Contains("-m")) - ?.Count(x => x == 'm') ?? 0; - logLevel -= logModifier; - if (logLevel < 0) - { - logLevel = 0; - } + if (args.Contains("--verbose")) + logLevel = LogEventLevel.Verbose; var outputTemplate = logLevel == LogEventLevel.Verbose ? "[{Timestamp:HH:mm:ss.fff} {Level:u3}] {Message:lj}{NewLine}{Exception}" From 2ead31b1999de9a9619991dad9445dfcd5ed35d6 Mon Sep 17 00:00:00 2001 From: Dominique Louis Date: Fri, 20 Oct 2023 13:18:05 +0100 Subject: [PATCH 2/5] More belt and braces out serial port open/close. Refactor to centralise. --- .../SerialConnection.ListenerProc.cs | 14 +---- .../Connections/SerialConnection.cs | 57 +++++++++++-------- 2 files changed, 36 insertions(+), 35 deletions(-) diff --git a/Source/v2/Meadow.Hcom/Connections/SerialConnection.ListenerProc.cs b/Source/v2/Meadow.Hcom/Connections/SerialConnection.ListenerProc.cs index 2f5181bd..6c4ac819 100644 --- a/Source/v2/Meadow.Hcom/Connections/SerialConnection.ListenerProc.cs +++ b/Source/v2/Meadow.Hcom/Connections/SerialConnection.ListenerProc.cs @@ -30,17 +30,7 @@ public override async Task WaitForMeadowAttach(CancellationToken? cancellationTo await Task.Delay(500); - if (!_port.IsOpen) - { - try - { - Open(); - } - catch (Exception ex) - { - Debug.WriteLine($"Unable to open port: {ex.Message}"); - } - } + Open(); } throw new TimeoutException(); @@ -204,7 +194,7 @@ private async Task ListenerProc() } else if (response is ReconnectRequiredResponse rrr) { - // the device is going to restart - we need to wait for a HCOM_HOST_REQUEST_TEXT_CONCLUDED to know it's back + // the device is going to restart - we need to wait for a HCOM_HOST_REQUEST_TEXT_CONCLUDED/TextConcludedResponse to know it's back State = ConnectionState.Disconnected; _reconnectInProgress = true; } diff --git a/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs b/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs index 3300d1b4..022fa66c 100644 --- a/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs +++ b/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs @@ -12,6 +12,7 @@ public partial class SerialConnection : ConnectionBase, IDisposable { public const int DefaultBaudRate = 115200; public const int ReadBufferSizeBytes = 0x2000; + private const int DefaultTimeout = 5000; private event EventHandler? FileReadCompleted = delegate { }; private event EventHandler? FileWriteAccepted; @@ -42,7 +43,7 @@ public SerialConnection(string port, ILogger? logger = default) State = ConnectionState.Disconnected; _logger = logger; _port = new SerialPort(port); - _port.ReadTimeout = _port.WriteTimeout = 5000; + _port.ReadTimeout = _port.WriteTimeout = DefaultTimeout; new Task( () => _ = ListenerProc(), @@ -86,24 +87,7 @@ private void ConnectionManagerProc() { while (_maintainConnection) { - if (!_port.IsOpen) - { - try - { - Debug.WriteLine("Opening COM port..."); - _port.Open(); - Debug.WriteLine("Opened COM port"); - } - catch (Exception ex) - { - Debug.WriteLine($"{ex.Message}"); - Thread.Sleep(1000); - } - } - else - { - Thread.Sleep(1000); - } + Open(true); } } @@ -129,27 +113,54 @@ public void RemoveListener(IConnectionListener listener) // TODO: stop maintaining connection? } - private void Open() + private void Open(bool inLoop = false) { if (!_port.IsOpen) { try { + Debug.WriteLine("Opening COM port..."); _port.Open(); } - catch (FileNotFoundException) + catch (UnauthorizedAccessException ex) + { + // Handle unauthorized access (e.g., port in use by another application) + throw new Exception($"Serial port '{_port.PortName}' is in use by another application.", ex.InnerException); + } + catch (IOException ex) { - throw new Exception($"Serial port '{_port.PortName}' not found"); + // Handle I/O errors + throw new Exception($"An I/O error occurred when opening the serial port '{_port.PortName}'.", ex.InnerException); } + catch (TimeoutException ex) + { + // Handle timeout + throw new Exception($"Timeout occurred when opening the serial port '{_port.PortName}'.", ex.InnerException); + } + } + else if (inLoop) + { + Thread.Sleep(1000); } + State = ConnectionState.Connected; + + Debug.WriteLine("Opened COM port"); } private void Close() { if (_port.IsOpen) { - _port.Close(); + try + { + _port.Close(); + } + catch (IOException ex) + { + // Handle I/O errors + throw new Exception($"An I/O error occurred when attempting to close the serial port '{_port.PortName}'.", ex.InnerException); + } } State = ConnectionState.Disconnected; From f512f70f5be8a89d7c06a0e48a1ad8d82e41c007 Mon Sep 17 00:00:00 2001 From: Dominique Louis Date: Fri, 20 Oct 2023 13:19:54 +0100 Subject: [PATCH 3/5] Move Logging so that we only see the messages if we have valid connection and device. --- .../Commands/Current/Runtime/RuntimeDisableCommand.cs | 3 ++- .../Commands/Current/Runtime/RuntimeEnableCommand.cs | 3 ++- .../Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs | 3 ++- 3 files changed, 6 insertions(+), 3 deletions(-) diff --git a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs index ddab77b2..c0602ce2 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs @@ -9,7 +9,6 @@ public class RuntimeDisableCommand : BaseDeviceCommand public RuntimeDisableCommand(MeadowConnectionManager connectionManager, ILoggerFactory loggerFactory) : base(connectionManager, loggerFactory) { - Logger?.LogInformation($"Disabling runtime..."); } protected override async ValueTask ExecuteCommand() @@ -20,6 +19,8 @@ protected override async ValueTask ExecuteCommand() { if (Connection.Device != null) { + Logger?.LogInformation($"Disabling runtime..."); + await Connection.Device.RuntimeDisable(CancellationToken); var state = await Connection.Device.IsRuntimeEnabled(CancellationToken); diff --git a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs index e2bd960a..117565af 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs @@ -9,7 +9,6 @@ public class RuntimeEnableCommand : BaseDeviceCommand public RuntimeEnableCommand(MeadowConnectionManager connectionManager, ILoggerFactory loggerFactory) : base(connectionManager, loggerFactory) { - Logger?.LogInformation($"Enabling runtime..."); } protected override async ValueTask ExecuteCommand() @@ -20,6 +19,8 @@ protected override async ValueTask ExecuteCommand() { if (Connection.Device != null) { + Logger?.LogInformation($"Enabling runtime..."); + await Connection.Device.RuntimeEnable(CancellationToken); var state = await Connection.Device.IsRuntimeEnabled(CancellationToken); diff --git a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs index 9b744eb0..cc911da2 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs @@ -9,7 +9,6 @@ public class RuntimeStateCommand : BaseDeviceCommand public RuntimeStateCommand(MeadowConnectionManager connectionManager, ILoggerFactory loggerFactory) : base(connectionManager, loggerFactory) { - Logger?.LogInformation($"Querying runtime state..."); } protected override async ValueTask ExecuteCommand() @@ -20,6 +19,8 @@ protected override async ValueTask ExecuteCommand() { if (Connection.Device != null) { + Logger?.LogInformation($"Querying runtime state..."); + var state = await Connection.Device.IsRuntimeEnabled(CancellationToken); Logger?.LogInformation($"Runtime is {(state ? "ENABLED" : "DISABLED")}"); From a607b04d15815e7cc5ae198b0bf91d17be3288c6 Mon Sep 17 00:00:00 2001 From: Dominique Louis Date: Fri, 20 Oct 2023 14:13:28 +0100 Subject: [PATCH 4/5] Fix DeviceMessageReceived logging bug. --- .../Commands/Current/App/AppDeployCommand.cs | 1 + .../Commands/Current/App/AppRunCommand.cs | 1 + .../Commands/Current/BaseDeviceCommand.cs | 10 +++++++++- .../Commands/Current/File/FileDeleteCommand.cs | 4 ++-- .../Current/Firmware/FirmwareWriteCommand.cs | 16 ---------------- .../Meadow.Cli/Commands/Legacy/FlashOsCommand.cs | 13 ------------- 6 files changed, 13 insertions(+), 32 deletions(-) diff --git a/Source/v2/Meadow.Cli/Commands/Current/App/AppDeployCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/App/AppDeployCommand.cs index 659bf665..4930ad38 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/App/AppDeployCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/App/AppDeployCommand.cs @@ -35,6 +35,7 @@ protected override async ValueTask ExecuteCommand() // in order to deploy, the runtime must be disabled var wasRuntimeEnabled = await Connection.IsRuntimeEnabled(); + if (wasRuntimeEnabled) { Logger?.LogInformation("Disabling runtime..."); diff --git a/Source/v2/Meadow.Cli/Commands/Current/App/AppRunCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/App/AppRunCommand.cs index ce217065..9d5013dd 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/App/AppRunCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/App/AppRunCommand.cs @@ -46,6 +46,7 @@ protected override async ValueTask ExecuteCommand() // in order to deploy, the runtime must be disabled var wasRuntimeEnabled = await Connection.IsRuntimeEnabled(); + if (wasRuntimeEnabled) { Logger?.LogInformation("Disabling runtime..."); diff --git a/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs index 16a0967d..2254c67a 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs @@ -34,9 +34,17 @@ protected override async ValueTask ExecuteCommand() Logger?.LogInformation(message); }; + // the connection passes messages back to us (info about actions happening on-device connection.DeviceMessageReceived += (s, e) => { - Logger?.LogInformation(e.message); + if (e.message.Contains("% downloaded")) + { + // don't echo this, as we're already reporting % written + } + else + { + Logger?.LogInformation(e.message); + } }; try diff --git a/Source/v2/Meadow.Cli/Commands/Current/File/FileDeleteCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/File/FileDeleteCommand.cs index 857437d7..7578932c 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/File/FileDeleteCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/File/FileDeleteCommand.cs @@ -58,8 +58,8 @@ protected override async ValueTask ExecuteCommand() if (wasRuntimeEnabled) { - Logger?.LogError($"The runtime must be disabled before doing any file management. Use 'meadow runtime disable' first."); - return; + Logger?.LogInformation("Disabling device runtime..."); + await Connection.Device.RuntimeDisable(); } Logger?.LogInformation($"Deleting file '{MeadowFile}' from device..."); diff --git a/Source/v2/Meadow.Cli/Commands/Current/Firmware/FirmwareWriteCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/Firmware/FirmwareWriteCommand.cs index 19dd6702..6604600c 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/Firmware/FirmwareWriteCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/Firmware/FirmwareWriteCommand.cs @@ -236,22 +236,6 @@ private ILibUsbDevice GetLibUsbDeviceForCurrentEnvironment() private async ValueTask WriteFiles(IMeadowConnection connection) { - // the connection passes messages back to us (info about actions happening on-device - connection.DeviceMessageReceived += (s, e) => - { - if (e.message.Contains("% downloaded")) - { - // don't echo this, as we're already reporting % written - } - else - { - Logger?.LogInformation(e.message); - } - }; - connection.ConnectionMessage += (s, message) => - { - Logger?.LogInformation(message); - }; connection.FileWriteFailed += (s, e) => { // TODO _fileWriteError = true; diff --git a/Source/v2/Meadow.Cli/Commands/Legacy/FlashOsCommand.cs b/Source/v2/Meadow.Cli/Commands/Legacy/FlashOsCommand.cs index e6ff56d6..325a8886 100644 --- a/Source/v2/Meadow.Cli/Commands/Legacy/FlashOsCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Legacy/FlashOsCommand.cs @@ -240,19 +240,6 @@ private async ValueTask WriteFiles() { if (Connection != null) { - // the connection passes messages back to us (info about actions happening on-device - /* TODO Don't think this is needed as it's in the base class now Connection.DeviceMessageReceived += (s, e) => - { - if (e.message.Contains("% downloaded")) - { - // don't echo this, as we're already reporting % written - } - else - { - Logger?.LogInformation(e.message); - } - };*/ - var package = await GetSelectedPackage(); if (Connection.Device != null From a8c085d2c89b1845dd7d2eba48fff6ea9b72e34b Mon Sep 17 00:00:00 2001 From: Dominique Louis Date: Sat, 21 Oct 2023 12:40:39 +0100 Subject: [PATCH 5/5] Refactor to listen out for State/Enable/Disable runtime state messages. --- .../Commands/Current/BaseDeviceCommand.cs | 2 +- .../Current/Runtime/RuntimeDisableCommand.cs | 15 ++++++----- .../Current/Runtime/RuntimeEnableCommand.cs | 15 ++++++----- .../Current/Runtime/RuntimeStateCommand.cs | 13 +++++++--- .../Connections/SerialConnection.cs | 25 +++++++++++++------ 5 files changed, 46 insertions(+), 24 deletions(-) diff --git a/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs index 2254c67a..c6df98bc 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/BaseDeviceCommand.cs @@ -34,7 +34,7 @@ protected override async ValueTask ExecuteCommand() Logger?.LogInformation(message); }; - // the connection passes messages back to us (info about actions happening on-device + // the connection passes messages back to us (info about actions happening on-device) connection.DeviceMessageReceived += (s, e) => { if (e.message.Contains("% downloaded")) diff --git a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs index c0602ce2..a3d1074d 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeDisableCommand.cs @@ -19,13 +19,16 @@ protected override async ValueTask ExecuteCommand() { if (Connection.Device != null) { - Logger?.LogInformation($"Disabling runtime..."); + try + { + Logger?.LogInformation($"Disabling runtime..."); - await Connection.Device.RuntimeDisable(CancellationToken); - - var state = await Connection.Device.IsRuntimeEnabled(CancellationToken); - - Logger?.LogInformation($"Runtime is {(state ? "ENABLED" : "DISABLED")}"); + await Connection.Device.RuntimeDisable(CancellationToken); + } + catch (Exception ex) + { + Logger?.LogError(ex, $"Failed to disable runtime."); + } } } } diff --git a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs index 117565af..c073c96b 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeEnableCommand.cs @@ -19,13 +19,16 @@ protected override async ValueTask ExecuteCommand() { if (Connection.Device != null) { - Logger?.LogInformation($"Enabling runtime..."); + try + { + Logger?.LogInformation($"Enabling runtime..."); - await Connection.Device.RuntimeEnable(CancellationToken); - - var state = await Connection.Device.IsRuntimeEnabled(CancellationToken); - - Logger?.LogInformation($"Runtime is {(state ? "ENABLED" : "DISABLED")}"); + await Connection.Device.RuntimeEnable(CancellationToken); + } + catch (Exception ex) + { + Logger?.LogError(ex, $"Failed to enable runtime."); + } } } } diff --git a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs index cc911da2..6ae4095b 100644 --- a/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs +++ b/Source/v2/Meadow.Cli/Commands/Current/Runtime/RuntimeStateCommand.cs @@ -19,11 +19,16 @@ protected override async ValueTask ExecuteCommand() { if (Connection.Device != null) { - Logger?.LogInformation($"Querying runtime state..."); + try + { + Logger?.LogInformation($"Querying runtime state..."); - var state = await Connection.Device.IsRuntimeEnabled(CancellationToken); - - Logger?.LogInformation($"Runtime is {(state ? "ENABLED" : "DISABLED")}"); + await Connection.Device.IsRuntimeEnabled(CancellationToken); + } + catch (Exception ex) + { + Logger?.LogError(ex, $"Unable to determine the runtime state."); + } } } } diff --git a/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs b/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs index 022fa66c..7883880b 100644 --- a/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs +++ b/Source/v2/Meadow.Hcom/Connections/SerialConnection.cs @@ -5,6 +5,7 @@ using System.Net; using System.Security.Cryptography; using System.Text; +using System.Threading; namespace Meadow.Hcom; @@ -492,9 +493,12 @@ protected override void Dispose(bool disposing) private List InfoMessages { get; } = new List(); private const string RuntimeSucessfullyEnabledToken = "Meadow successfully started MONO"; - private const string RuntimeSucessfullyDisabledToken = "Mono is disabled"; private const string RuntimeStateToken = "Mono is"; private const string RuntimeIsEnabledToken = "Mono is enabled"; + private const string RuntimeIsDisabledToken = "Mono is disabled"; + private const string RuntimeHasBeenToken = "Mono has been"; + private const string RuntimeHasBeenEnabledToken = "Mono has been enabled"; + private const string RuntimeHasBeenDisabledToken = "Mono has been disabled"; private const string RtcRetrievalToken = "UTC time:"; public int CommandTimeoutSeconds { get; set; } = 30; @@ -611,19 +615,26 @@ public override async Task IsRuntimeEnabled(CancellationToken? cancellatio EnqueueRequest(command); + return await WaitForInformationResponse(RuntimeStateToken, RuntimeIsEnabledToken, cancellationToken); + } + + private async Task WaitForInformationResponse(string textToContain, string textToVerify, CancellationToken? cancellationToken) + { // wait for an information response var timeout = CommandTimeoutSeconds * 2; while (timeout-- > 0) { - if (cancellationToken?.IsCancellationRequested ?? false) return false; - if (timeout <= 0) throw new TimeoutException(); + if (cancellationToken?.IsCancellationRequested ?? false) + return false; + if (timeout <= 0) + throw new TimeoutException(); if (InfoMessages.Count > 0) { - var m = InfoMessages.FirstOrDefault(i => i.Contains(RuntimeStateToken)); + var m = InfoMessages.FirstOrDefault(i => i.Contains(textToContain)); if (m != null) { - return m == RuntimeIsEnabledToken; + return m == textToVerify; } } @@ -642,7 +653,7 @@ public override async Task RuntimeEnable(CancellationToken? cancellationToken = EnqueueRequest(command); - await WaitForConcluded(null, cancellationToken); + await WaitForInformationResponse(RuntimeHasBeenToken, RuntimeHasBeenEnabledToken, cancellationToken); } public override async Task RuntimeDisable(CancellationToken? cancellationToken = null) @@ -655,7 +666,7 @@ public override async Task RuntimeDisable(CancellationToken? cancellationToken = EnqueueRequest(command); - await WaitForConcluded(null, cancellationToken); + await WaitForInformationResponse(RuntimeHasBeenToken, RuntimeHasBeenDisabledToken, cancellationToken); } public override async Task TraceEnable(CancellationToken? cancellationToken = null)