Added trace logging to client

LANCommander.Playnite.Extension/Helpers/RetryHelper.cs

@@ -1,4 +1,5 @@
-using System;
+using Playnite.SDK;
+using System;
 using System.Collections.Generic;
 using System.Linq;
 using System.Text;
@@ -8,6 +9,8 @@ namespace LANCommander.PlaynitePlugin.Helpers
 {
     internal static class RetryHelper
     {
+        internal static readonly ILogger Logger = LogManager.GetLogger();
+
         internal static T RetryOnException<T>(int maxAttempts, TimeSpan delay, T @default, Func<T> action)
         {
             int attempts = 0;
@@ -16,11 +19,15 @@ namespace LANCommander.PlaynitePlugin.Helpers
             {
                 try
                 {
+                    Logger.Trace($"Attempt #{attempts + 1}/{maxAttempts}...");
+
                     attempts++;
                     return action();
                 }
                 catch (Exception ex)
                 {
+                    Logger.Error(ex, $"Attempt failed!");
+
                     if (attempts >= maxAttempts)
                         return @default;
 

LANCommander.Playnite.Extension/InstallController.cs

@@ -17,6 +17,8 @@ namespace LANCommander.PlaynitePlugin
 {
     public class LANCommanderInstallController : InstallController
     {
+        public static readonly ILogger Logger = LogManager.GetLogger();
+
         private LANCommanderLibraryPlugin Plugin;
         private PowerShellRuntime PowerShellRuntime;
         private Playnite.SDK.Models.Game PlayniteGame;
@@ -31,16 +33,23 @@ namespace LANCommander.PlaynitePlugin
 
         public override void Install(InstallActionArgs args)
         {
+            Logger.Trace("Game install triggered, checking connection...");
+
             while (!Plugin.ValidateConnection())
             {
+                Logger.Trace("User not authenticated. Opening auth window...");
+
                 Plugin.ShowAuthenticationWindow();
             }
 
             var gameId = Guid.Parse(Game.GameId);
             var game = Plugin.LANCommander.GetGame(gameId);
 
+            Logger.Trace($"Installing game {game.Title} ({game.Id})...");
+
             var installDirectory = RetryHelper.RetryOnException(10, TimeSpan.FromMilliseconds(500), "", () =>
             {
+                Logger.Trace("Attempting to download and extract game...");
                 return DownloadAndExtract(game);
             });
 
@@ -58,6 +67,8 @@ namespace LANCommander.PlaynitePlugin
 
             var writeManifestSuccess = RetryHelper.RetryOnException(10, TimeSpan.FromSeconds(1), false, () =>
             {
+                Logger.Trace("Attempting to get game manifest...");
+
                 manifest = Plugin.LANCommander.GetGameManifest(gameId);
 
                 WriteManifest(manifest, installDirectory);
@@ -68,6 +79,8 @@ namespace LANCommander.PlaynitePlugin
             if (!writeManifestSuccess)
                 throw new Exception("Could not get or write the manifest file. Retry the install or check your connection.");
 
+            Logger.Trace("Saving scripts...");
+
             SaveScript(game, installDirectory, ScriptType.Install);
             SaveScript(game, installDirectory, ScriptType.Uninstall);
             SaveScript(game, installDirectory, ScriptType.NameChange);
@@ -95,11 +108,15 @@ namespace LANCommander.PlaynitePlugin
         {
             if (game == null)
             {
+                Logger.Trace("Game failed to download! No game was specified!");
+
                 throw new Exception("Game failed to download!");
             }
 
             var destination = Path.Combine(Plugin.Settings.InstallDirectory, game.Title.SanitizeFilename());
 
+            Logger.Trace($"Downloading and extracting \"{game}\" to path {destination}");
+
             Plugin.PlayniteApi.Dialogs.ActivateGlobalProgress(progress =>
             {
                 try
@@ -127,8 +144,12 @@ namespace LANCommander.PlaynitePlugin
                 }
                 catch (Exception ex)
                 {
+                    Logger.Error(ex, $"Could not extract to path {destination}");
+
                     if (Directory.Exists(destination))
                     {
+                        Logger.Trace("Directory at install path already exists. Deleting...");
+
                         Directory.Delete(destination, true);
                     }
                 }
@@ -139,6 +160,8 @@ namespace LANCommander.PlaynitePlugin
                 Cancelable = false,
             });
 
+            Logger.Trace($"Game successfully downloaded and extracted to {destination}");
+
             return destination;
         }
 
@@ -217,13 +240,19 @@ namespace LANCommander.PlaynitePlugin
 
         private void WriteManifest(SDK.GameManifest manifest, string installDirectory)
         {
+            var destination = Path.Combine(installDirectory, "_manifest.yml");
+
+            Logger.Trace($"Attempting to write manifest to path {destination}");
+
             var serializer = new SerializerBuilder()
                 .WithNamingConvention(new PascalCaseNamingConvention())
                 .Build();
 
+            Logger.Trace("Serializing manifest...");
             var yaml = serializer.Serialize(manifest);
 
-            File.WriteAllText(Path.Combine(installDirectory, "_manifest.yml"), yaml);
+            Logger.Trace("Writing manifest file...");
+            File.WriteAllText(destination, yaml);
         }
 
         private void SaveScript(LANCommander.SDK.Models.Game game, string installationDirectory, ScriptType type)
@@ -241,6 +270,8 @@ namespace LANCommander.PlaynitePlugin
             if (File.Exists(filename))
                 File.Delete(filename);
 
+            Logger.Trace($"Writing {type} script to {filename}");
+
             File.WriteAllText(filename, script.Contents);
         }
     }

LANCommander.Playnite.Extension/LANCommanderClient.cs

@@ -1,5 +1,6 @@
 using LANCommander.SDK;
 using LANCommander.SDK.Models;
+using Playnite.SDK;
 using RestSharp;
 using System;
 using System.Collections.Generic;
@@ -14,6 +15,8 @@ namespace LANCommander.PlaynitePlugin
 {
     internal class LANCommanderClient
     {
+        public static readonly ILogger Logger = LogManager.GetLogger();
+
         public readonly RestClient Client;
         public AuthToken Token;
 
@@ -142,17 +145,32 @@ namespace LANCommander.PlaynitePlugin
 
         public bool ValidateToken(AuthToken token)
         {
+            Logger.Trace("Validating token...");
+
             if (token == null)
+            {
+                Logger.Trace("Token is null!");
                 return false;
+            }
 
             var request = new RestRequest("/api/Auth/Validate")
                 .AddHeader("Authorization", $"Bearer {token.AccessToken}");
 
             if (String.IsNullOrEmpty(token.AccessToken) || String.IsNullOrEmpty(token.RefreshToken))
+            {
+                Logger.Trace("Token is empty!");
                 return false;
+            }
 
             var response = Client.Post(request);
 
+            var valid = response.StatusCode == HttpStatusCode.OK;
+
+            if (valid)
+                Logger.Trace("Token is valid!");
+            else
+                Logger.Trace("Token is invalid!");
+
             return response.StatusCode == HttpStatusCode.OK;
         }
 
@@ -198,6 +216,8 @@ namespace LANCommander.PlaynitePlugin
 
         public GameSave UploadSave(string gameId, byte[] data)
         {
+            Logger.Trace("Uploading save...");
+
             var request = new RestRequest($"/api/Saves/Upload/{gameId}", Method.POST)
                 .AddHeader("Authorization", $"Bearer {Token.AccessToken}");
 
@@ -210,6 +230,8 @@ namespace LANCommander.PlaynitePlugin
 
         public string GetKey(Guid id)
         {
+            Logger.Trace("Requesting key allocation...");
+
             var macAddress = GetMacAddress();
 
             var request = new KeyRequest()
@@ -227,6 +249,8 @@ namespace LANCommander.PlaynitePlugin
 
         public string GetAllocatedKey(Guid id)
         {
+            Logger.Trace("Requesting allocated key...");
+
             var macAddress = GetMacAddress();
 
             var request = new KeyRequest()
@@ -247,6 +271,8 @@ namespace LANCommander.PlaynitePlugin
 
         public string GetNewKey(Guid id)
         {
+            Logger.Trace("Requesting new key allocation...");
+
             var macAddress = GetMacAddress();
 
             var request = new KeyRequest()

LANCommander.Playnite.Extension/LANCommanderLibraryPlugin.cs

@@ -55,6 +55,7 @@ namespace LANCommander.PlaynitePlugin
         {
             if (LANCommander.Token == null || LANCommander.Client == null || !LANCommander.ValidateToken(LANCommander.Token))
             {
+                Logger.Trace("No valid authentication token exists. Showing auth window...");
                 ShowAuthenticationWindow();
             }
         }
@@ -70,10 +71,10 @@ namespace LANCommander.PlaynitePlugin
 
             while (!ValidateConnection())
             {
+                Logger.Trace("Authentication invalid, showing auth window...");
                 ShowAuthenticationWindow();
             }
 
-
             var games = LANCommander
                 .GetGames()
                 .Where(g => g.Archives != null && g.Archives.Count() > 0);
@@ -82,16 +83,24 @@ namespace LANCommander.PlaynitePlugin
             {
                 try
                 {
+                    Logger.Trace($"Importing/updating metadata for game \"{game.Title}\"...");
+
                     var manifest = LANCommander.GetGameManifest(game.Id);
+                    Logger.Trace("Successfully grabbed game manifest");
+
                     var existingGame = PlayniteApi.Database.Games.FirstOrDefault(g => g.GameId == game.Id.ToString() && g.PluginId == Id && g.IsInstalled);
 
                     if (existingGame != null)
                     {
+                        Logger.Trace("Game already exists in library, updating metadata...");
+
                         UpdateGame(manifest, game.Id);
 
                         continue;
                     }
 
+                    Logger.Trace("Game does not exist in the library, importing metadata...");
+
                     var metadata = new GameMetadata()
                     {
                         IsInstalled = false,
@@ -142,7 +151,7 @@ namespace LANCommander.PlaynitePlugin
                 }
                 catch (Exception ex)
                 {
-
+                    Logger.Error(ex, $"Could not update game \"{game.Title}\" in library");
                 }
             };
 
@@ -167,6 +176,8 @@ namespace LANCommander.PlaynitePlugin
 
         public override IEnumerable<GameMenuItem> GetGameMenuItems(GetGameMenuItemsArgs args)
         {
+            Logger.Trace("Populating game menu items...");
+
             if (args.Games.Count == 1 && args.Games.First().IsInstalled && !String.IsNullOrWhiteSpace(args.Games.First().InstallDirectory))
             {
                 var nameChangeScriptPath = PowerShellRuntime.GetScriptFilePath(args.Games.First(), SDK.Enums.ScriptType.NameChange);
@@ -174,6 +185,9 @@ namespace LANCommander.PlaynitePlugin
                 var installScriptPath = PowerShellRuntime.GetScriptFilePath(args.Games.First(), SDK.Enums.ScriptType.Install);
 
                 if (File.Exists(nameChangeScriptPath))
+                {
+                    Logger.Trace($"Name change script found at path {nameChangeScriptPath}");
+
                     yield return new GameMenuItem
                     {
                         Description = "Change Player Name",
@@ -187,8 +201,12 @@ namespace LANCommander.PlaynitePlugin
                                 PowerShellRuntime.RunScript(nameChangeArgs.Games.First(), SDK.Enums.ScriptType.NameChange, $@"""{result.SelectedString}"" ""{oldName}""");
                         }
                     };
+                }
 
                 if (File.Exists(keyChangeScriptPath))
+                {
+                    Logger.Trace($"Key change script found at path {keyChangeScriptPath}");
+
                     yield return new GameMenuItem
                     {
                         Description = "Change Game Key",
@@ -212,8 +230,12 @@ namespace LANCommander.PlaynitePlugin
                             }
                         }
                     };
+                }
 
                 if (File.Exists(installScriptPath))
+                {
+                    Logger.Trace($"Install script found at path {installScriptPath}");
+
                     yield return new GameMenuItem
                     {
                         Description = "Run Install Script",
@@ -231,6 +253,7 @@ namespace LANCommander.PlaynitePlugin
                             }
                         }
                     };
+                }
             }
         }
 
@@ -304,28 +327,41 @@ namespace LANCommander.PlaynitePlugin
 
         public void ShowNameChangeWindow()
         {
+            Logger.Trace("Showing name change dialog!");
+
             var result = PlayniteApi.Dialogs.SelectString("Enter your new player name. This will change your name across all installed games!", "Enter Name", Settings.PlayerName);
 
             if (result.Result == true)
             {
+                Logger.Trace($"New name entered was \"{result.SelectedString}\"");
+
                 // Check to make sure they're staying in ASCII encoding
                 if (String.IsNullOrEmpty(result.SelectedString) || result.SelectedString.Any(c => c > sbyte.MaxValue))
                 {
                     PlayniteApi.Dialogs.ShowErrorMessage("The name you supplied is invalid. Try again.");
 
+                    Logger.Trace("An invalid name was specified. Showing the name dialog again...");
+
                     ShowNameChangeWindow();
                 }
                 else
                 {
                     Settings.PlayerName = result.SelectedString;
 
+                    Logger.Trace($"New player name of \"{Settings.PlayerName}\" has been set!");
+
+                    Logger.Trace("Saving plugin settings!");
                     SavePluginSettings(Settings);
 
                     var games = PlayniteApi.Database.Games.Where(g => g.IsInstalled).ToList();
 
+                    Logger.Trace($"Running name change scripts across {games.Count} installed game(s)");
+
                     PowerShellRuntime.RunScripts(games, SDK.Enums.ScriptType.NameChange, Settings.PlayerName);
                 }
             }
+            else
+                Logger.Trace("Name change was cancelled");
         }
 
         public Window ShowAuthenticationWindow()

LANCommander.Playnite.Extension/PowerShellRuntime.cs

@@ -1,4 +1,5 @@
 using LANCommander.SDK.Enums;
+using Playnite.SDK;
 using Playnite.SDK.Models;
 using System;
 using System.Collections.Generic;
@@ -15,6 +16,8 @@ namespace LANCommander.PlaynitePlugin
 {
     internal class PowerShellRuntime
     {
+        public static readonly ILogger Logger = LogManager.GetLogger();
+
         [DllImport("kernel32.dll", SetLastError = true)]
         static extern bool Wow64DisableWow64FsRedirection(ref IntPtr ptr);
 
@@ -23,8 +26,12 @@ namespace LANCommander.PlaynitePlugin
 
         public void RunCommand(string command, bool asAdmin = false)
         {
+            Logger.Trace($"Executing command `{command}` | Admin: {asAdmin}");
+
             var tempScript = Path.Combine(Path.GetTempPath(), Guid.NewGuid().ToString() + ".ps1");
 
+            Logger.Trace($"Creating temp script at path {tempScript}");
+
             File.WriteAllText(tempScript, command);
 
             RunScript(tempScript, asAdmin);
@@ -34,8 +41,11 @@ namespace LANCommander.PlaynitePlugin
 
         public void RunScript(string path, bool asAdmin = false, string arguments = null)
         {
+            Logger.Trace($"Executing script at path {path} | Admin: {asAdmin} | Arguments: {arguments}");
+
             var wow64Value = IntPtr.Zero;
 
+            // Disable Wow64 redirection so we can hit areas of the registry absolutely
             Wow64DisableWow64FsRedirection(ref wow64Value);
 
             var process = new Process();
@@ -49,7 +59,10 @@ namespace LANCommander.PlaynitePlugin
                 process.StartInfo.Arguments += " " + arguments;
 
             if (asAdmin)
+            {
                 process.StartInfo.Verb = "runas";
+                process.StartInfo.UseShellExecute = true;
+            }
 
             process.Start();
             process.WaitForExit();
@@ -57,28 +70,6 @@ namespace LANCommander.PlaynitePlugin
             Wow64RevertWow64FsRedirection(ref wow64Value);
         }
 
-        public void RunScriptsAsAdmin(IEnumerable<string> paths, string arguments = null)
-        {
-            // Concatenate scripts
-            var sb = new StringBuilder();
-
-            foreach (var path in paths)
-            {
-                var contents = File.ReadAllText(path);
-
-                sb.AppendLine(contents);
-            }
-
-            if (sb.Length > 0)
-            {
-                var scriptPath = Path.GetTempFileName();
-
-                File.WriteAllText(scriptPath, sb.ToString());
-
-                RunScript(scriptPath, true, arguments);
-            }
-        }
-
         public void RunScript(Game game, ScriptType type, string arguments = null)
         {
             var path = GetScriptFilePath(game, type);
@@ -94,6 +85,36 @@ namespace LANCommander.PlaynitePlugin
             }
         }
 
+        public void RunScriptsAsAdmin(IEnumerable<string> paths, string arguments = null)
+        {
+            // Concatenate scripts
+            var sb = new StringBuilder();
+
+            Logger.Trace("Concatenating scripts...");
+
+            foreach (var path in paths)
+            {
+                var contents = File.ReadAllText(path);
+
+                sb.AppendLine(contents);
+
+                Logger.Trace($"Added {path}!");
+            }
+
+            Logger.Trace("Done concatenating!");
+
+            if (sb.Length > 0)
+            {
+                var scriptPath = Path.GetTempFileName();
+
+                Logger.Trace($"Creating temp script at path {scriptPath}");
+
+                File.WriteAllText(scriptPath, sb.ToString());
+
+                RunScript(scriptPath, true, arguments);
+            }
+        }
+
         public void RunScripts(IEnumerable<Game> games, ScriptType type, string arguments = null)
         {
             List<string> scripts = new List<string>();

LANCommander.Playnite.Extension/UninstallController.cs

@@ -1,4 +1,5 @@
 using LANCommander.SDK.Enums;
+using Playnite.SDK;
 using Playnite.SDK.Models;
 using Playnite.SDK.Plugins;
 using System;
@@ -8,6 +9,8 @@ namespace LANCommander.PlaynitePlugin
 {
     public class LANCommanderUninstallController : UninstallController
     {
+        public static readonly ILogger Logger = LogManager.GetLogger();
+
         private LANCommanderLibraryPlugin Plugin;
         private PowerShellRuntime PowerShellRuntime;
 
@@ -26,9 +29,13 @@ namespace LANCommander.PlaynitePlugin
             }
             catch { }
 
+            Logger.Trace("Attempting to delete install directory...");
+
             if (!String.IsNullOrWhiteSpace(Game.InstallDirectory) && Directory.Exists(Game.InstallDirectory))
                 Directory.Delete(Game.InstallDirectory, true);
 
+            Logger.Trace("Deleted!");
+
             InvokeOnUninstalled(new GameUninstalledEventArgs());
         }
     }

LANCommander.Playnite.Extension/Views/Authentication.xaml.cs

@@ -21,6 +21,8 @@ namespace LANCommander.PlaynitePlugin.Views
 {
     public partial class Authentication : UserControl
     {
+        public static readonly ILogger Logger = LogManager.GetLogger();
+
         private LANCommanderLibraryPlugin Plugin;
         private ViewModels.Authentication Context { get { return (ViewModels.Authentication)DataContext; } }
 
@@ -32,6 +34,8 @@ namespace LANCommander.PlaynitePlugin.Views
 
             var probe = new Probe("LANCommander");
 
+            Logger.Trace("Attempting to find a LANCommander server on the local network...");
+
             probe.BeaconsUpdated += beacons => Dispatcher.BeginInvoke((System.Action)(() =>
             {
                 var beacon = beacons.First();
@@ -40,6 +44,8 @@ namespace LANCommander.PlaynitePlugin.Views
 
                 this.ServerAddress.Text = Context.ServerAddress;
 
+                Logger.Trace($"The beacons have been lit! LANCommander calls for aid! {Context.ServerAddress}");
+
                 probe.Stop();
             }));