From 7a17fec1b4cccb6200e730bdde8a3e23d5ece060 Mon Sep 17 00:00:00 2001 From: Mankarse Date: Sun, 31 Mar 2024 22:23:32 +1100 Subject: [PATCH] Improve parsing of infolog_full.txt The new parser identifies regions of the infolog that correspond to individual games. Each game is further parsed to find: GameID FirstDesyncIndex GameState file names If the infolog contains GameState file names, include them in a table in the Issue description. If the infolog contains multiple games with desyncs, try to include all of the desync messages in the truncated infolog. --- ChobbyLauncher/CrashReportHelper.cs | 315 ++++++++++++++++++++++++---- Shared/PlasmaShared/Utils.cs | 29 +++ 2 files changed, 305 insertions(+), 39 deletions(-) diff --git a/ChobbyLauncher/CrashReportHelper.cs b/ChobbyLauncher/CrashReportHelper.cs index 15f141ec28..13c1d7c23b 100644 --- a/ChobbyLauncher/CrashReportHelper.cs +++ b/ChobbyLauncher/CrashReportHelper.cs @@ -1,9 +1,7 @@ using System; using System.Collections.Generic; using System.Diagnostics; -using System.IO; using System.Linq; -using System.Runtime.InteropServices; using System.Text; using System.Text.RegularExpressions; using System.Threading.Tasks; @@ -12,7 +10,6 @@ using Octokit; using PlasmaShared; using ZkData; -using FileMode = System.IO.FileMode; namespace ChobbyLauncher { @@ -25,71 +22,306 @@ public enum CrashType { public static class CrashReportHelper { + private const string CrashReportsRepoOwner = "ZeroK-RTS"; + private const string CrashReportsRepoName = "CrashReports"; + private const int MaxInfologSize = 62000; private const string InfoLogLineStartPattern = @"(^\[t=\d+:\d+:\d+\.\d+\]\[f=-?\d+\] )"; private const string InfoLogLineEndPattern = @"(\r?\n|\Z)"; - public static Issue ReportCrash(string infolog, CrashType type, string engine, string bugReportTitle, string bugReportDescription) + private sealed class GameFromLog + { + public int StartIdxInLog { get; set; } + public string GameID { get; set; } + public bool HasDesync { get => FirstDesyncIdxInLog.HasValue; } + public int? FirstDesyncIdxInLog { get; set; } + public List GameStateFileNames { get; set; } + + //Perhaps in future versions, these could be added? + //PlayerName + //DemoFileName + //MapName + //ModName + } + + private sealed class GameFromLogCollection + { + public IReadOnlyList Games { get; private set; } + public GameFromLogCollection(IEnumerable startIndexes) + { + Games = startIndexes.Select(idx => new GameFromLog { StartIdxInLog = idx }).ToArray(); + } + + private readonly struct GameStartList : IReadOnlyList + { + private readonly GameFromLogCollection _this; + public GameStartList(GameFromLogCollection v) => _this = v; + + int IReadOnlyList.this[int index] => _this.Games[index].StartIdxInLog; + + int IReadOnlyCollection.Count { get => _this.Games.Count; } + + IEnumerator IEnumerable.GetEnumerator() => _this.Games.Select(g => g.StartIdxInLog).GetEnumerator(); + + System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator() => ((IEnumerable)this).GetEnumerator(); + } + public IReadOnlyList AsGameStartReadOnlyList() => new GameStartList(this); + + private GameFromLog GetGameForIndex(int idx) + { + //Equivalent to: + //return Games.LastOrDefault(g => g.StartIdxInLog < idx); + //but takes advantage of the fact that Games is sorted to have log rather than linear runtime. + var lb = AsGameStartReadOnlyList().LowerBoundIndex(idx); + return lb == 0 ? null : Games[lb - 1]; + } + public void AddGameStateFileNames(IEnumerable<(int, string)> gameStateFileNames) + { + foreach (var file in gameStateFileNames) + { + var game = GetGameForIndex(file.Item1); + if (game == null) + { + Trace.TraceWarning("[CrashReportHelper] Unable to match GameState file to Game"); + continue; + } + if (game.GameStateFileNames == null) + { + game.GameStateFileNames = new List(); + } + + game.GameStateFileNames.Add(file.Item2); + } + } + public void AddDesyncs(IEnumerable desyncs) + { + foreach (var desync in desyncs) + { + var game = GetGameForIndex(desync); + if (game == null) + { + Trace.TraceWarning("[CrashReportHelper] Unable to match Desync to Game"); + continue; + } + if (!game.HasDesync) + { + game.FirstDesyncIdxInLog = desync; + } + } + } + public void AddGameIDs(IEnumerable<(int, string)> gameIDs) + { + foreach (var gameID in gameIDs) + { + var game = GetGameForIndex(gameID.Item1); + if (game == null) + { + Trace.TraceWarning("[CrashReportHelper] Unable to match GameID to Game"); + continue; + } + if (game.GameID != null) + { + Trace.TraceWarning("[CrashReportHelper] Found multiple GameIDs for Game"); + continue; + } + + game.GameID = gameID.Item2; + } + } + } + private static IReadOnlyList MakeRegionsOfInterest(int stringLength, IEnumerable pointsOfInterest, IReadOnlyList regionBoundaries) + { + //Pre: + // pointsOfInterest is sorted + // regionBoundaries is sorted + + //Automatically adds a region at the start and end of the string, that can expand to cover the whole string. + //For every element of pointsOfInterest, adds a region with StartLimit/EndLimit corresponding to the relevant regionBoundaries (or the start/end of the string) + + var result = new List(); + + result.Add(new TextTruncator.RegionOfInterest { PointOfInterest = 0, StartLimit = 0, EndLimit = stringLength }); + result.AddRange(pointsOfInterest.Select(poi => { + var regionEndIndex = Utils.LowerBoundIndex(regionBoundaries, poi); + return new TextTruncator.RegionOfInterest + { + PointOfInterest = poi, + StartLimit = regionEndIndex == 0 ? 0 : regionBoundaries[regionEndIndex - 1], + EndLimit = regionEndIndex == regionBoundaries.Count ? stringLength : regionBoundaries[regionEndIndex], + }; + })); + result.Add(new TextTruncator.RegionOfInterest { PointOfInterest = stringLength, StartLimit = 0, EndLimit = stringLength }); + + return result; + } + + private static string EscapeMarkdownTableCell(string str) => str.Replace("\r", "").Replace("\n", " ").Replace("|", @"\|"); + private static string MakeDesyncGameTable(GameFromLogCollection gamesFromLog) + { + var tableEmpty = true; + var sb = new StringBuilder(); + sb.AppendLine("\n\n|GameID|GameState File|"); + sb.AppendLine("|-|-|"); + + foreach (var game in gamesFromLog.Games.Where(g => g.HasDesync && g.GameStateFileNames != null)) + { + var gameIDString = EscapeMarkdownTableCell(game.GameID ?? "Unknown"); + foreach (var gameStateFileName in game.GameStateFileNames) + { + tableEmpty = false; + sb.AppendLine($"|{gameIDString}|{EscapeMarkdownTableCell(gameStateFileName)}|"); + } + } + return tableEmpty ? string.Empty : sb.ToString(); + } + + private static async Task ReportCrash(string infolog, CrashType type, string engine, string bugReportTitle, string bugReportDescription, GameFromLogCollection gamesFromLog) { try { - var client = new GitHubClient(new ProductHeaderValue("chobbyla")); - client.Credentials = new Credentials(GlobalConst.CrashReportGithubToken); + var client = new GitHubClient(new ProductHeaderValue("chobbyla")) + { + Credentials = new Credentials(GlobalConst.CrashReportGithubToken) + }; + + var infologTruncated = TextTruncator.Truncate(infolog, MaxInfologSize, MakeRegionsOfInterest(infolog.Length, gamesFromLog.Games.Where(g => g.HasDesync).Select(g => g.FirstDesyncIdxInLog.Value), gamesFromLog.AsGameStartReadOnlyList())); - infolog = Truncate(infolog, MaxInfologSize); + var desyncDebugInfo = MakeDesyncGameTable(gamesFromLog); - var createdIssue = - client.Issue.Create("ZeroK-RTS", "CrashReports", new NewIssue($"Spring {type} [{engine}] {bugReportTitle}") { Body = $"{bugReportDescription}\n\n```{infolog}```", }) - .Result; + var newIssueRequest = new NewIssue($"Spring {type} [{engine}] {bugReportTitle}") + { + Body = $"{bugReportDescription}{desyncDebugInfo}" + }; + var createdIssue = await client.Issue.Create(CrashReportsRepoOwner, CrashReportsRepoName, newIssueRequest); + + await client.Issue.Comment.Create(CrashReportsRepoOwner, CrashReportsRepoName, createdIssue.Number, $"infolog_full.txt (truncated):\n\n```{infologTruncated}```"); return createdIssue; } catch (Exception ex) { - Trace.TraceWarning("Problem reporting a bug: {0}", ex); + Trace.TraceWarning("[CrashReportHelper] Problem reporting a bug: {0}", ex); } return null; } - public static int FindFirstDesyncMessage(string logStr) + + //All infolog parsing is best-effort only. + //The infolog file format does not have enough structure to guarantee that it is never misinterpreted. + + private static int[] ReadGameReloads(string logStr) { - //[t=00:22:43.533864][f=0003461] Sync error for mankarse in frame 3451 (got 927a6f33, correct is 6b550dd1) + //Game reload detected by [f=-000001] that follows either the start of the file, or [f={non-negative value}] + + var list = new List(); + + var negativeFrameRegex = new Regex(@"f=-(?<=(?^)\[t=\d+:\d+:\d+\.\d+\]\[f=-)\d+\]", RegexOptions.CultureInvariant | RegexOptions.Compiled | RegexOptions.ExplicitCapture | RegexOptions.Multiline, TimeSpan.FromSeconds(30)); + var nonNegativeFrameRegex = new Regex(@"f=\d(?<=^\[t=\d+:\d+:\d+\.\d+\]\[f=\d)\d*\]", RegexOptions.CultureInvariant | RegexOptions.Compiled | RegexOptions.ExplicitCapture | RegexOptions.Multiline, TimeSpan.FromSeconds(30)); + + var idx = 0; + try { - //See ZkData.Account.IsValidLobbyName - var accountNamePattern = @"[_[\]a-zA-Z0-9]{1,25}"; - var match = - Regex.Match( - logStr, - $@"Sync error for(?<={InfoLogLineStartPattern}Sync error for) {accountNamePattern} in frame \d+ \(got [a-z0-9]+, correct is [a-z0-9]+\){InfoLogLineEndPattern}", - RegexOptions.CultureInvariant | RegexOptions.Compiled | RegexOptions.ExplicitCapture | RegexOptions.Multiline, - TimeSpan.FromSeconds(30)); + while (true) + { + { + var m = negativeFrameRegex.Match(logStr, idx); + if (!m.Success) break; + idx = m.Index; + list.Add(m.Groups["s"].Index); + } + { + var m = nonNegativeFrameRegex.Match(logStr, idx); + if (!m.Success) break; + idx = m.Index; + } + } + return list.ToArray(); + } + catch (RegexMatchTimeoutException) + { + Trace.TraceError("\"[CrashReportHelper] RegexMatchTimeoutException in ReadGameReloads"); + return Array.Empty(); + } + } + private static (int, string)[] ReadGameStateFileNames(string logStr) + { + //See https://github.com/beyond-all-reason/spring/blob/f3ba23635e1462ae2084f10bf9ba777467d16090/rts/System/Sync/DumpState.cpp#L155 - return match.Success ? match.Index : -1; + //[t=00:22:43.353840][f=0003461] [DumpState] using dump-file "ClientGameState--749245531-[3461-3461].txt" + try + { + return + Regex + .Matches( + logStr, + $@"(?<={InfoLogLineStartPattern})\[DumpState\] using dump-file ""(?[^{Regex.Escape(System.IO.Path.DirectorySeparatorChar.ToString())}{Regex.Escape(System.IO.Path.AltDirectorySeparatorChar.ToString())}""]+)""{InfoLogLineEndPattern}", + RegexOptions.CultureInvariant | RegexOptions.Compiled | RegexOptions.ExplicitCapture | RegexOptions.Multiline, + TimeSpan.FromSeconds(30)) + .Cast().Select(m => (m.Index, m.Groups["d"].Value)).Distinct() + .ToArray(); } - catch(RegexMatchTimeoutException) + catch (RegexMatchTimeoutException) { - Trace.TraceError("[CrashReportHelper] RegexMatchTimeoutException in FindFirstDesyncMessage"); - return -1; + Trace.TraceError("\"[CrashReportHelper] RegexMatchTimeoutException in ReadClientStateFileNames"); + return Array.Empty<(int, string)>(); } } - private static string Truncate(string infolog, int maxSize) + private static int[] ReadDesyncs(string logStr) { - var firstDesync = FindFirstDesyncMessage(infolog); - var regionsOfInterest = new List(firstDesync == -1 ? 2 : 3); + //[t=00:22:43.533864][f=0003461] Sync error for mankarse in frame 3451 (got 927a6f33, correct is 6b550dd1) - regionsOfInterest.Add(new TextTruncator.RegionOfInterest { PointOfInterest = 0, StartLimit = 0, EndLimit = infolog.Length }); - if (firstDesync != -1) + //See ZkData.Account.IsValidLobbyName + var accountNamePattern = @"[_[\]a-zA-Z0-9]{1,25}"; + try + { + return + Regex + .Matches( + logStr, + $@"Sync error for(?<={InfoLogLineStartPattern}Sync error for) {accountNamePattern} in frame \d+ \(got [a-z0-9]+, correct is [a-z0-9]+\){InfoLogLineEndPattern}", + RegexOptions.CultureInvariant | RegexOptions.Compiled | RegexOptions.ExplicitCapture | RegexOptions.Multiline, + TimeSpan.FromSeconds(30)) + .Cast().Select(m => m.Index).ToArray(); + } + catch (RegexMatchTimeoutException) { - regionsOfInterest.Add(new TextTruncator.RegionOfInterest { PointOfInterest = firstDesync, StartLimit = 0, EndLimit = infolog.Length }); + Trace.TraceError("\"[CrashReportHelper] RegexMatchTimeoutException in ReadDesyncs"); + return Array.Empty(); } - regionsOfInterest.Add(new TextTruncator.RegionOfInterest { PointOfInterest = infolog.Length, StartLimit = 0, EndLimit = infolog.Length }); + } + + + private static (int, string)[] ReadGameIDs(string logStr) + { + //[t=00:19:00.246149][f=-000001] GameID: 6065f665e92c7942def2c0c17c703e72 - return TextTruncator.Truncate(infolog, maxSize, regionsOfInterest); + try + { + return + Regex + .Matches( + logStr, + $@"GameID:(?<={InfoLogLineStartPattern}GameID:) (?[0-9a-zA-Z]+){InfoLogLineEndPattern}", + RegexOptions.CultureInvariant | RegexOptions.Compiled | RegexOptions.ExplicitCapture | RegexOptions.Multiline, + TimeSpan.FromSeconds(30)) + .Cast().Select(m => { var g = m.Groups["g"]; return (g.Index, g.Value); }).ToArray(); + } + catch (RegexMatchTimeoutException) + { + Trace.TraceError("\"[CrashReportHelper] RegexMatchTimeoutException in ReadGameIDs"); + return Array.Empty<(int, string)>(); + } } public static void CheckAndReportErrors(string logStr, bool springRunOk, string bugReportTitle, string bugReportDescription, string engineVersion) { - var syncError = FindFirstDesyncMessage(logStr) != -1; + var gamesFromLog = new GameFromLogCollection(ReadGameReloads(logStr)); + + gamesFromLog.AddGameStateFileNames(ReadGameStateFileNames(logStr)); + gamesFromLog.AddDesyncs(ReadDesyncs(logStr)); + gamesFromLog.AddGameIDs(ReadGameIDs(logStr)); + + var syncError = gamesFromLog.Games.Any(g => g.HasDesync); if (syncError) Trace.TraceWarning("Sync error detected"); var openGlFail = logStr.Contains("No OpenGL drivers installed.") || @@ -139,11 +371,16 @@ public static void CheckAndReportErrors(string logStr, bool springRunOk, string : luaErr ? CrashType.LuaError : CrashType.Crash; - var ret = ReportCrash(logStr, - crashType, - engineVersion, - bugReportTitle, - bugReportDescription); + var ret = + ReportCrash( + logStr, + crashType, + engineVersion, + bugReportTitle, + bugReportDescription, + gamesFromLog) + .GetAwaiter().GetResult(); + if (ret != null) try { diff --git a/Shared/PlasmaShared/Utils.cs b/Shared/PlasmaShared/Utils.cs index 3309cad711..249f1dc81f 100644 --- a/Shared/PlasmaShared/Utils.cs +++ b/Shared/PlasmaShared/Utils.cs @@ -200,6 +200,35 @@ public static double StdDevSquared(this IEnumerable values) } + public static int LowerBoundIndex(this IReadOnlyList list, T value) where T : IComparable + { + //Requires: + // list is sorted + + //Returns: + // Smallest value of i for which: !(list[i] < value) + // or list.Count, if there is no such value. + + int first = 0; + int len = list.Count; + + while (len > 0) + { + var half = len / 2; + var mid = first + half; + if (list[mid].CompareTo(value) < 0) + { + first = mid + 1; + len = len - half - 1; + } + else + { + len = half; + } + } + + return first; + } public static bool CanRead(string filename)