From ab365cd322d4840656fb9f080d7f1c894f94770b Mon Sep 17 00:00:00 2001 From: F K <54195004+fredjk-gh@users.noreply.github.com> Date: Tue, 3 May 2022 17:32:31 -0400 Subject: [PATCH] Expose core error logger to plugins and report custom criteria errors (#78) * Expose core error logger to plugins and report custom criteria errors Fixes #77 This adds an error logging method on the IObservatoryCore interface that writes the exception details to ObservatoryCore's central error log (found in `${Documents}/ObservatoryErrorLog.txt`). In addition, added a timestamp to each error log. Also updates the Explorer to report Custom Criteria file load errors and execution errors to the log. Also updates HeraldNotifier to report CacheIndex.json parse failures to the error log as well. * Expand debugging/error logging in Herald; cleanup empty mp3 files Herald crashes if attempting to play 0-byte mp3s so if detected, delete, re-request (empty files can occur in some azure failure cases (ie. out of quota). Trap and log errors in other places in HeraldQueue to avoid hard crashes due to weird and wonderful unexpected stuff. --- ObservatoryCore/ObservatoryCore.cs | 3 +- .../PluginManagement/PluginCore.cs | 8 ++ ObservatoryExplorer/CustomCriteriaManager.cs | 23 +++++- ObservatoryExplorer/Explorer.cs | 2 +- ObservatoryFramework/Interfaces.cs | 7 ++ ObservatoryHerald/HeraldNotifier.cs | 5 +- ObservatoryHerald/HeraldQueue.cs | 81 ++++++++++++------- ObservatoryHerald/SpeechRequestManager.cs | 28 +++++-- 8 files changed, 114 insertions(+), 43 deletions(-) diff --git a/ObservatoryCore/ObservatoryCore.cs b/ObservatoryCore/ObservatoryCore.cs index 48f9355..600cafd 100644 --- a/ObservatoryCore/ObservatoryCore.cs +++ b/ObservatoryCore/ObservatoryCore.cs @@ -30,8 +30,9 @@ namespace Observatory { var docPath = System.Environment.GetFolderPath(System.Environment.SpecialFolder.MyDocuments); var errorMessage = new System.Text.StringBuilder(); + var timestamp = DateTime.Now.ToString("G"); errorMessage - .AppendLine($"Error encountered in Elite Observatory {context}.") + .AppendLine($"[{timestamp}] Error encountered in Elite Observatory {context}") .AppendLine(FormatExceptionMessage(ex)) .AppendLine(); System.IO.File.AppendAllText(docPath + System.IO.Path.DirectorySeparatorChar + "ObservatoryErrorLog.txt", errorMessage.ToString()); diff --git a/ObservatoryCore/PluginManagement/PluginCore.cs b/ObservatoryCore/PluginManagement/PluginCore.cs index 26a4376..ea1384a 100644 --- a/ObservatoryCore/PluginManagement/PluginCore.cs +++ b/ObservatoryCore/PluginManagement/PluginCore.cs @@ -21,6 +21,14 @@ namespace Observatory.PluginManagement public string Version => System.Reflection.Assembly.GetEntryAssembly().GetName().Version.ToString(); + public Action GetPluginErrorLogger(IObservatoryPlugin plugin) + { + return (ex, context) => + { + ObservatoryCore.LogError(ex, $"from plugin {plugin.ShortName} {context}"); + }; + } + public Status GetStatus() { throw new NotImplementedException(); diff --git a/ObservatoryExplorer/CustomCriteriaManager.cs b/ObservatoryExplorer/CustomCriteriaManager.cs index 515c31b..e412538 100644 --- a/ObservatoryExplorer/CustomCriteriaManager.cs +++ b/ObservatoryExplorer/CustomCriteriaManager.cs @@ -12,9 +12,12 @@ namespace Observatory.Explorer { private Lua LuaState; private List CriteriaFunctions; - - public CustomCriteriaManager() + Action ErrorLogger; + + + public CustomCriteriaManager(Action errorLogger) { + ErrorLogger = errorLogger; CriteriaFunctions = new(); } @@ -174,8 +177,14 @@ namespace Observatory.Explorer originalScript = originalScript.Remove(originalScript.LastIndexOf(Environment.NewLine)); originalScript = originalScript[(originalScript.IndexOf(Environment.NewLine) + Environment.NewLine.Length)..]; - - throw new CriteriaLoadException(e.Message, originalScript.Replace('\t', ' ')); + originalScript = originalScript.Replace('\t', ' '); + + StringBuilder errorDetail = new(); + errorDetail.AppendLine("Error Reading Custom Criteria File:") + .AppendLine(originalScript) + .AppendLine("NOTE: Custom criteria processing has been disable to prevent further errors."); + ErrorLogger(e, errorDetail.ToString()); + throw new CriteriaLoadException(e.Message, originalScript); } } @@ -236,6 +245,12 @@ namespace Observatory.Explorer { settings.EnableCustomCriteria = false; results.Add((e.Message, scan.Json, false)); + + StringBuilder errorDetail = new(); + errorDetail.AppendLine("while processing a custom criteria on scan:") + .AppendLine(scan.Json) + .AppendLine("NOTE: Custom criteria process has been disabled to prevent further errors."); + ErrorLogger(e, errorDetail.ToString()); break; } } diff --git a/ObservatoryExplorer/Explorer.cs b/ObservatoryExplorer/Explorer.cs index ea6ec8b..df57c54 100644 --- a/ObservatoryExplorer/Explorer.cs +++ b/ObservatoryExplorer/Explorer.cs @@ -29,7 +29,7 @@ namespace Observatory.Explorer ExplorerWorker = explorerWorker; ObservatoryCore = core; Results = results; - CustomCriteriaManager = new(); + CustomCriteriaManager = new(core.GetPluginErrorLogger(explorerWorker)); CriteriaLastModified = new DateTime(0); } diff --git a/ObservatoryFramework/Interfaces.cs b/ObservatoryFramework/Interfaces.cs index 3335d68..c50d05d 100644 --- a/ObservatoryFramework/Interfaces.cs +++ b/ObservatoryFramework/Interfaces.cs @@ -174,6 +174,13 @@ namespace Observatory.Framework.Interfaces /// public string Version { get; } + /// + /// Returns a delegate for logging an error for the calling plugin. A plugin can wrap this method + /// or pass it along to its collaborators. + /// + /// The calling plugin + public Action GetPluginErrorLogger (IObservatoryPlugin plugin); + /// /// Perform an action on the current Avalonia UI thread. /// diff --git a/ObservatoryHerald/HeraldNotifier.cs b/ObservatoryHerald/HeraldNotifier.cs index 819f581..8c84548 100644 --- a/ObservatoryHerald/HeraldNotifier.cs +++ b/ObservatoryHerald/HeraldNotifier.cs @@ -53,8 +53,9 @@ namespace Observatory.Herald } public void Load(IObservatoryCore observatoryCore) { - var speechManager = new SpeechRequestManager(heraldSettings, observatoryCore.HttpClient, observatoryCore.PluginStorageFolder); - heraldSpeech = new HeraldQueue(speechManager); + var speechManager = new SpeechRequestManager( + heraldSettings, observatoryCore.HttpClient, observatoryCore.PluginStorageFolder, observatoryCore.GetPluginErrorLogger(this)); + heraldSpeech = new HeraldQueue(speechManager, observatoryCore.GetPluginErrorLogger(this)); heraldSettings.Test = TestVoice; } diff --git a/ObservatoryHerald/HeraldQueue.cs b/ObservatoryHerald/HeraldQueue.cs index 7f36d6a..7ba791f 100644 --- a/ObservatoryHerald/HeraldQueue.cs +++ b/ObservatoryHerald/HeraldQueue.cs @@ -4,6 +4,8 @@ using System.Threading.Tasks; using System.Linq; using NetCoreAudio; using System.Threading; +using System; +using System.Diagnostics; namespace Observatory.Herald { @@ -17,13 +19,15 @@ namespace Observatory.Herald private byte volume; private SpeechRequestManager speechManager; private Player audioPlayer; - - public HeraldQueue(SpeechRequestManager speechManager) + private Action ErrorLogger; + + public HeraldQueue(SpeechRequestManager speechManager, Action errorLogger) { this.speechManager = speechManager; processing = false; notifications = new(); audioPlayer = new(); + ErrorLogger = errorLogger; } @@ -55,37 +59,48 @@ namespace Observatory.Herald private void ProcessQueue() { - - while (notifications.Any()) + + NotificationArgs notification = null; + try { - audioPlayer.SetVolume(volume).Wait(); - var notification = notifications.Dequeue(); - - Task[] audioRequestTasks = new Task [2]; - - - if (string.IsNullOrWhiteSpace(notification.TitleSsml)) + while (notifications.Any()) { - audioRequestTasks[0] = RetrieveAudioToFile(notification.Title); - } - else - { - audioRequestTasks[0] = RetrieveAudioSsmlToFile(notification.TitleSsml); - } + audioPlayer.SetVolume(volume).Wait(); + notification = notifications.Dequeue(); + Debug.WriteLine("Processing notification: {0} - {1}", notification.Title, notification.Detail); - if (string.IsNullOrWhiteSpace(notification.DetailSsml)) - { - audioRequestTasks[1] = RetrieveAudioToFile(notification.Detail); - } - else - { - audioRequestTasks[1] = RetrieveAudioSsmlToFile(notification.DetailSsml); - } + Task[] audioRequestTasks = new Task[2]; - PlayAudioRequestsSequentially(audioRequestTasks); + if (string.IsNullOrWhiteSpace(notification.TitleSsml)) + { + audioRequestTasks[0] = RetrieveAudioToFile(notification.Title); + } + else + { + audioRequestTasks[0] = RetrieveAudioSsmlToFile(notification.TitleSsml); + } + + if (string.IsNullOrWhiteSpace(notification.DetailSsml)) + { + audioRequestTasks[1] = RetrieveAudioToFile(notification.Detail); + } + else + { + audioRequestTasks[1] = RetrieveAudioSsmlToFile(notification.DetailSsml); + } + + PlayAudioRequestsSequentially(audioRequestTasks); + } + } + catch (Exception ex) + { + Debug.WriteLine($"Failed to fetch/play notification: {notification?.Title} - {notification?.Detail}"); + ErrorLogger(ex, "while retrieving and playing audio for a notification"); + } + finally + { + processing = false; } - - processing = false; } private async Task RetrieveAudioToFile(string text) @@ -103,7 +118,15 @@ namespace Observatory.Herald foreach (var request in requestTasks) { string file = request.Result; - audioPlayer.Play(file).Wait(); + try + { + Debug.WriteLine($"Playing audio file: {file}"); + audioPlayer.Play(file).Wait(); + } catch (Exception ex) + { + Debug.WriteLine($"Failed to play {file}: {ex.Message}"); + ErrorLogger(ex, $"while playing: {file}"); + } while (audioPlayer.Playing) Thread.Sleep(50); diff --git a/ObservatoryHerald/SpeechRequestManager.cs b/ObservatoryHerald/SpeechRequestManager.cs index d6dded3..077854a 100644 --- a/ObservatoryHerald/SpeechRequestManager.cs +++ b/ObservatoryHerald/SpeechRequestManager.cs @@ -19,15 +19,18 @@ namespace Observatory.Herald private string ApiEndpoint; private DirectoryInfo cacheLocation; private int cacheSize; - - internal SpeechRequestManager(HeraldSettings settings, HttpClient httpClient, string cacheFolder) + private Action ErrorLogger; + + internal SpeechRequestManager( + HeraldSettings settings, HttpClient httpClient, string cacheFolder, Action errorLogger) { ApiKey = ObservatoryAPI.ApiKey; ApiEndpoint = settings.ApiEndpoint; this.httpClient = httpClient; cacheSize = Math.Max(settings.CacheSize, 1); cacheLocation = new DirectoryInfo(cacheFolder); - + ErrorLogger = errorLogger; + if (!Directory.Exists(cacheLocation.FullName)) { Directory.CreateDirectory(cacheLocation.FullName); @@ -49,7 +52,19 @@ namespace Observatory.Herald var audioFilename = cacheLocation + ssmlHash + ".mp3"; - if (!File.Exists(audioFilename)) + FileInfo audioFileInfo = null; + if (File.Exists(audioFilename)) + { + audioFileInfo = new FileInfo(audioFilename); + if (audioFileInfo.Length == 0) + { + File.Delete(audioFilename); + audioFileInfo = null; + } + } + + + if (audioFileInfo == null) { using StringContent request = new(ssml) { @@ -71,10 +86,10 @@ namespace Observatory.Herald { throw new PluginException("Herald", "Unable to retrieve audio data.", new Exception(response.StatusCode.ToString() + ": " + response.ReasonPhrase)); } - + audioFileInfo = new FileInfo(audioFilename); } - UpdateAndPruneCache(new FileInfo(audioFilename)); + UpdateAndPruneCache(audioFileInfo); return audioFilename; } @@ -231,6 +246,7 @@ namespace Observatory.Herald { Console.WriteLine(ex.Message); cacheIndex = new(); + ErrorLogger(ex, "deserializing CacheIndex.json"); } } else