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

@@ -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());

ObservatoryCore/PluginManagement/PluginCore.cs

@@ -21,6 +21,14 @@ namespace Observatory.PluginManagement
 
         public string Version => System.Reflection.Assembly.GetEntryAssembly().GetName().Version.ToString();
 
+        public Action<Exception, String> GetPluginErrorLogger(IObservatoryPlugin plugin)
+        {
+            return (ex, context) =>
+            {
+                ObservatoryCore.LogError(ex, $"from plugin {plugin.ShortName} {context}");
+            };
+        }
+
         public Status GetStatus()
         {
             throw new NotImplementedException();

ObservatoryExplorer/CustomCriteriaManager.cs

@@ -12,9 +12,12 @@ namespace Observatory.Explorer
     {
         private Lua LuaState;
         private List<LuaFunction> CriteriaFunctions;
-        
-        public CustomCriteriaManager()
+        Action<Exception, String> ErrorLogger;
+
+
+        public CustomCriteriaManager(Action<Exception, String> 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;
                 }
             }

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);
         }
 

ObservatoryFramework/Interfaces.cs

@@ -174,6 +174,13 @@ namespace Observatory.Framework.Interfaces
         /// </summary>
         public string Version { get; }
 
+        /// <summary>
+        /// Returns a delegate for logging an error for the calling plugin. A plugin can wrap this method
+        /// or pass it along to its collaborators.
+        /// </summary>
+        /// <param name="plugin">The calling plugin</param>
+        public Action<Exception, String> GetPluginErrorLogger (IObservatoryPlugin plugin);
+
         /// <summary>
         /// Perform an action on the current Avalonia UI thread.
         /// </summary>

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;
         }
 

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<Exception, String> ErrorLogger;
+
+        public HeraldQueue(SpeechRequestManager speechManager, Action<Exception, String> 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<string>[] audioRequestTasks = new Task<string> [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<string>[] audioRequestTasks = new Task<string>[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<string> 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);

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<Exception, String> ErrorLogger;
+
+        internal SpeechRequestManager(
+            HeraldSettings settings, HttpClient httpClient, string cacheFolder, Action<Exception, String> 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