feat(launcher): write startup diagnostics to launcher.log

Records spawned processes and their fuse state, exit and unhandled
exception codes, detach timing and reason, and the exit code after detach.

CHANGELOG.md

@@ -40,6 +40,7 @@ The newest entry must match the version in `WandEnhancer/Properties/AssemblyInfo
 
 ### Improvements
 
+- The launcher now writes a `launcher.log` next to itself, recording every process Electron starts and whether its fuse was cleared, exit and crash codes, and how long it stayed attached. Starting Wand happens without a window, so until now a client that refused to open left nothing to go on.
 - Log messages in the desktop app are now translated into all 12 supported languages.
 - The remote panel is now usable with a keyboard and a screen reader: dialogs trap focus and close on Escape, and controls have accessible names. Pinning a mod previously required a swipe and had no keyboard path at all, so mod rows now have a pin button.
 

WandEnhancer/Core/FuseLauncher.cs

@@ -4,6 +4,7 @@ using System.IO;
 using System.Diagnostics;
 using System.Runtime.InteropServices;
 using System.Text;
+using WandEnhancer.View.MainWindow;
 
 namespace WandEnhancer.Core
 {
@@ -41,6 +42,9 @@ namespace WandEnhancer.Core
         private const int OffsetThreadId = 8;
         private const int OffsetUnion = 16;
         private const int OffsetExceptionCode = OffsetUnion;
+        // EXCEPTION_DEBUG_INFO is EXCEPTION_RECORD (152 bytes on x64) followed by dwFirstChance.
+        private const int OffsetExceptionFirstChance = OffsetUnion + 152;
+        private const int OffsetExitCode = OffsetUnion;
         private const int OffsetCreateProcessFile = OffsetUnion;
         private const int OffsetCreateProcessHandle = OffsetUnion + 8;
         private const int OffsetCreateProcessImageBase = OffsetUnion + 24;
@@ -51,10 +55,17 @@ namespace WandEnhancer.Core
         private const long QuietMs = 1500;
         private const long MaxDebugMs = 9000;
 
+        // Electron dies a second or two after a renderer fails, which is past the detach.
+        // Watching that window is the only way the exit code reaches the log.
+        private const int PostDetachWatchMs = 5000;
+
+        /// <summary>Electron's exit code when the ASAR integrity fuse rejects the archive.</summary>
+        private const int AsarIntegrityExitCode = -36861;
+
         private static readonly byte[] Sentinel =
             Encoding.ASCII.GetBytes("dL7pKGdnNz796PbbjQWNKmHXBZaB9tsX");
 
-        public static bool Launch(string exePath, string args, Action<string> log = null)
+        public static bool Launch(string exePath, string args, Action<string, ELogType> log = null)
         {
             var si = new STARTUPINFO { cb = Marshal.SizeOf<STARTUPINFO>() };
             var cmdLine = new StringBuilder(
@@ -64,20 +75,35 @@ namespace WandEnhancer.Core
                     false, DEBUG_PROCESS, IntPtr.Zero,
                     Path.GetDirectoryName(exePath), ref si, out var pi))
             {
-                log?.Invoke($"Could not start Wand under the fuse patcher (win32 error {Marshal.GetLastWin32Error()}).");
+                log?.Invoke($"Could not start Wand under the fuse patcher (win32 error {Marshal.GetLastWin32Error()}).",
+                    ELogType.Error);
                 return false;
             }
 
             // Debugged processes must survive after we detach and exit.
             DebugSetProcessKillOnExit(false);
             CloseHandle(pi.hThread);
-            CloseHandle(pi.hProcess);
+            log?.Invoke($"Started {exePath} as pid {pi.dwProcessId}.", ELogType.Info);
+
+            try
+            {
+                // The process handle outlives the debug loop on purpose: once detached it is
+                // the only remaining way to read why Wand died.
+                if (!DrivePatchingDebugLoop(pi.dwProcessId, log))
+                {
+                    WatchAfterDetach(pi.hProcess, log);
+                }
+            }
+            finally
+            {
+                CloseHandle(pi.hProcess);
+            }
 
-            DrivePatchingDebugLoop(pi.dwProcessId, log);
             return true;
         }
 
-        private static void DrivePatchingDebugLoop(int mainPid, Action<string> log)
+        /// <returns>True when the main process exited while the debugger was still attached.</returns>
+        private static bool DrivePatchingDebugLoop(int mainPid, Action<string, ELogType> log)
         {
             var pids = new List<int>();
             var brokeIn = new HashSet<int>();
@@ -86,6 +112,8 @@ namespace WandEnhancer.Core
             // every ~25 days, and a negative elapsed would keep the debugger attached forever.
             var clock = Stopwatch.StartNew();
             long lastCreate = 0;
+            int created = 0;
+            int patched = 0;
 
             while (true)
             {
@@ -109,8 +137,13 @@ namespace WandEnhancer.Core
                         var hProc = (IntPtr)BitConverter.ToInt64(evt, OffsetCreateProcessHandle);
                         var baseImg = (IntPtr)BitConverter.ToInt64(evt, OffsetCreateProcessImageBase);
                         if (!pids.Contains(pid)) pids.Add(pid);
-                        if (!PatchFuse(hProc, baseImg))
-                            log?.Invoke($"Fuse not cleared in pid {pid}; renderers may fail with -36861.");
+                        created++;
+                        bool cleared = PatchFuse(hProc, baseImg);
+                        if (cleared) patched++;
+                        log?.Invoke(
+                            $"pid {pid} started at {now} ms - fuse " +
+                            (cleared ? "cleared." : $"NOT cleared, it may exit with {AsarIntegrityExitCode}."),
+                            cleared ? ELogType.Info : ELogType.Warn);
                         // The debugger owns the image handle the kernel hands over with this event.
                         if (hFile != IntPtr.Zero) CloseHandle(hFile);
                         lastCreate = now;
@@ -122,14 +155,27 @@ namespace WandEnhancer.Core
                         status = (exCode == EXCEPTION_BREAKPOINT && brokeIn.Add(pid))
                             ? DBG_CONTINUE
                             : DBG_EXCEPTION_NOT_HANDLED;
+                        // Chromium raises first-chance exceptions constantly and handles them.
+                        // A second chance means nothing handled it and the process is dying.
+                        if (BitConverter.ToInt32(evt, OffsetExceptionFirstChance) == 0)
+                            log?.Invoke($"pid {pid} hit an unhandled exception at {now} ms: {DescribeCode(exCode)}.",
+                                ELogType.Error);
                         break;
 
                     case EXIT_PROCESS_DEBUG_EVENT:
+                        int exitCode = BitConverter.ToInt32(evt, OffsetExitCode);
                         pids.Remove(pid);
+                        log?.Invoke(
+                            $"{(pid == mainPid ? "Main process" : $"pid {pid}")} exited at {now} ms " +
+                            $"with code {DescribeCode(exitCode)}.",
+                            exitCode == 0 ? ELogType.Info : ELogType.Error);
+
                         if (pid == mainPid)
                         {
+                            log?.Invoke($"Wand exited during startup: {created} processes started, {patched} fuse-patched.",
+                                ELogType.Error);
                             ContinueDebugEvent(pid, tid, status);
-                            return;
+                            return true;
                         }
                         break;
                 }
@@ -141,8 +187,59 @@ namespace WandEnhancer.Core
                     break;
             }
 
+            long detachedAt = clock.ElapsedMilliseconds;
+            // The detach reason matters: hitting the cap means Electron was still spawning
+            // processes we never patched, which looks exactly like "Wand does not open".
+            string reason = detachedAt > MaxDebugMs
+                ? $"{MaxDebugMs} ms cap reached"
+                : $"no new process for {QuietMs} ms";
+            log?.Invoke(
+                $"Detached after {detachedAt} ms ({reason}): {created} processes started, " +
+                $"{patched} fuse-patched, {pids.Count} still attached.",
+                patched == 0 ? ELogType.Error : ELogType.Info);
+
             foreach (var pid in pids)
                 DebugActiveProcessStop(pid);
+
+            return false;
+        }
+
+        /// <summary>
+        /// Electron usually dies a second or two after a renderer fails, which lands after the
+        /// detach. Without this the log ends on a healthy-looking "detached" line.
+        /// </summary>
+        private static void WatchAfterDetach(IntPtr hProcess, Action<string, ELogType> log)
+        {
+            if (WaitForSingleObject(hProcess, PostDetachWatchMs) != WAIT_OBJECT_0)
+            {
+                log?.Invoke($"Wand still running {PostDetachWatchMs} ms after detach.", ELogType.Success);
+                return;
+            }
+
+            if (!GetExitCodeProcess(hProcess, out int exitCode))
+            {
+                log?.Invoke($"Wand exited after detach, exit code unreadable (win32 error {Marshal.GetLastWin32Error()}).",
+                    ELogType.Error);
+                return;
+            }
+
+            log?.Invoke($"Wand exited right after detach with code {DescribeCode(exitCode)}.", ELogType.Error);
+        }
+
+        /// <summary>Names the exit and exception codes that actually turn up when Wand will not start.</summary>
+        private static string DescribeCode(int code)
+        {
+            switch (code)
+            {
+                case 0: return "0";
+                case AsarIntegrityExitCode:
+                    return $"{code} (ASAR integrity check failed - the fuse was not cleared in that process)";
+                case unchecked((int)0xC0000005): return $"0x{code:X8} (access violation)";
+                case unchecked((int)0xC0000135): return $"0x{code:X8} (a required DLL is missing)";
+                case unchecked((int)0xC0000142): return $"0x{code:X8} (a DLL failed to initialise)";
+                case unchecked((int)0xC0000409): return $"0x{code:X8} (stack buffer overrun)";
+                default: return $"{code} (0x{code:X8})";
+            }
         }
 
         private static bool ShouldDetach(long elapsed, long sinceLastCreate)
@@ -229,6 +326,7 @@ namespace WandEnhancer.Core
         private const int CREATE_PROCESS_DEBUG_EVENT = 3;
         private const int EXIT_PROCESS_DEBUG_EVENT = 5;
         private const int EXCEPTION_BREAKPOINT = unchecked((int)0x80000003);
+        private const uint WAIT_OBJECT_0 = 0;
 
         [StructLayout(LayoutKind.Sequential)]
         private struct STARTUPINFO
@@ -283,6 +381,12 @@ namespace WandEnhancer.Core
         [DllImport("kernel32.dll", SetLastError = true)]
         private static extern bool DebugSetProcessKillOnExit(bool KillOnExit);
 
+        [DllImport("kernel32.dll", SetLastError = true)]
+        private static extern uint WaitForSingleObject(IntPtr hHandle, int dwMilliseconds);
+
+        [DllImport("kernel32.dll", SetLastError = true)]
+        private static extern bool GetExitCodeProcess(IntPtr hProcess, out int lpExitCode);
+
         [DllImport("kernel32.dll")]
         private static extern bool CloseHandle(IntPtr hObject);
 

WandEnhancer/Core/LauncherLog.cs

@@ -0,0 +1,60 @@
+using System;
+using System.IO;
+using WandEnhancer.View.MainWindow;
+
+namespace WandEnhancer.Core
+{
+    /// <summary>
+    /// Append-only log written next to the deployed launcher. Launch mode has no window and
+    /// exits as soon as Wand is up, so without this file a "Wand does not start" report
+    /// carries no evidence at all. Every operation swallows its own failure: diagnostics must
+    /// never be the reason Wand fails to launch.
+    /// </summary>
+    internal static class LauncherLog
+    {
+        public const string FileName = "launcher.log";
+        private const long MaxBytes = 512 * 1024;
+
+        private static string _path;
+
+        public static void Open(string launcherDirectory, string header)
+        {
+            try
+            {
+                var file = new FileInfo(Path.Combine(launcherDirectory, FileName));
+                // Dropped whole rather than trimmed: the session being diagnosed is the last
+                // one, and keeping half a rotated file is not worth the code.
+                if (file.Exists && file.Length > MaxBytes)
+                {
+                    file.Delete();
+                }
+
+                _path = file.FullName;
+                Write($"=== {DateTime.Now:yyyy-MM-dd} {header}", ELogType.Info);
+            }
+            catch (Exception e) when (e is IOException || e is UnauthorizedAccessException ||
+                                      e is ArgumentException || e is NotSupportedException)
+            {
+                _path = null;
+            }
+        }
+
+        public static void Write(string message, ELogType type)
+        {
+            if (_path == null)
+            {
+                return;
+            }
+
+            try
+            {
+                File.AppendAllText(_path,
+                    $"{DateTime.Now:HH:mm:ss.fff} [{type.ToString().ToUpperInvariant()}] {message}{Environment.NewLine}");
+            }
+            catch (Exception e) when (e is IOException || e is UnauthorizedAccessException)
+            {
+                // A log line lost to a locked or full disk must not abort the launch.
+            }
+        }
+    }
+}

WandEnhancer/Program.cs

@@ -44,28 +44,45 @@ namespace WandEnhancer
                 return false;
 
             string myDir = Path.GetDirectoryName(myExe);
+            string forwardedArgs = args.Length > 0 ? QuoteArguments(args) : null;
+
+            LauncherLog.Open(myDir, $"WandEnhancer {Constants.Version} | {myExe}" +
+                                    (forwardedArgs == null ? "" : $" | args {forwardedArgs}"));
 
             if (args.Length > 0 &&
                 args[0].StartsWith("--squirrel", StringComparison.OrdinalIgnoreCase))
             {
                 string updateExe = Path.Combine(myDir, "Update.exe");
                 if (File.Exists(updateExe))
+                {
+                    LauncherLog.Write($"Squirrel hook {args[0]} forwarded to Update.exe.", ELogType.Info);
                     Process.Start(updateExe, QuoteArguments(args));
+                }
+                else
+                {
+                    LauncherLog.Write($"Squirrel hook {args[0]} ignored: Update.exe is missing.", ELogType.Warn);
+                }
+
                 return true;
             }
 
             var config = WeModInstalls.FindLatestWeMod(myDir);
             if (config == null)
+            {
+                LauncherLog.Write($"No Wand install found under {myDir}; opening the UI instead.", ELogType.Error);
                 return false;
+            }
+
+            bool isPatched = Enhancer.IsPatched(config.RootDirectory);
+            LauncherLog.Write($"Install {config.ExecutablePath} is {(isPatched ? "patched" : "not patched")}.",
+                ELogType.Info);
 
             // A fresh Wand version drops our patches; re-apply the saved selection automatically.
             // On failure fall through to the UI so the user sees which patch broke.
-            if (!Enhancer.IsPatched(config.RootDirectory) && !TryAutoPatch(config, myDir))
+            if (!isPatched && !TryAutoPatch(config, myDir))
                 return false;
 
-            string forwardedArgs = args.Length > 0 ? QuoteArguments(args) : null;
-            FuseLauncher.Launch(config.ExecutablePath, forwardedArgs,
-                message => RecordStartupLog(message, ELogType.Warn));
+            FuseLauncher.Launch(config.ExecutablePath, forwardedArgs, LauncherLog.Write);
             return true;
         }
 
@@ -132,9 +149,12 @@ namespace WandEnhancer
             }
         }
 
+        /// <summary>Buffers for the UI and mirrors to disk: auto-patch runs headless, so the
+        /// file is the only copy if the user never opens the window afterwards.</summary>
         private static void RecordStartupLog(string message, ELogType type)
         {
             StartupLog.Add(new KeyValuePair<string, ELogType>(message, type));
+            LauncherLog.Write(message, type);
         }
         
         

WandEnhancer/WandEnhancer.csproj

@@ -67,6 +67,7 @@
         <Compile Include="Core\Enhancer.cs" />
         <Compile Include="Core\EnhancerConfig.cs" />
         <Compile Include="Core\FuseLauncher.cs" />
+        <Compile Include="Core\LauncherLog.cs" />
         <Compile Include="Core\JavaScriptPatchApplier.cs" />
         <Compile Include="Core\Js\JsCursor.cs" />
         <Compile Include="Core\Js\JsFunction.cs" />