Skip to content

Commit

Permalink
Improve parsing of infolog_full.txt
Browse files Browse the repository at this point in the history 
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.
  • Loading branch information
@Mankarse
Mankarse committed Apr 1, 2024
1 parent 1b26c92 commit 7a17fec
Show file tree
Hide file tree
Showing 2 changed files with 305 additions and 39 deletions.
315 changes: 276 additions & 39 deletions ChobbyLauncher/CrashReportHelper.cs
View file
Original file line number Diff line number Diff line change
@@ -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;
Expand All @@ -12,7 +10,6 @@
using Octokit;
using PlasmaShared;
using ZkData;
using FileMode = System.IO.FileMode;

namespace ChobbyLauncher
{
Expand All @@ -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<string> GameStateFileNames { get; set; }

//Perhaps in future versions, these could be added?
//PlayerName
//DemoFileName
//MapName
//ModName
}

private sealed class GameFromLogCollection
{
public IReadOnlyList<GameFromLog> Games { get; private set; }
public GameFromLogCollection(IEnumerable<int> startIndexes)
{
Games = startIndexes.Select(idx => new GameFromLog { StartIdxInLog = idx }).ToArray();
}

private readonly struct GameStartList : IReadOnlyList<int>
{
private readonly GameFromLogCollection _this;
public GameStartList(GameFromLogCollection v) => _this = v;

int IReadOnlyList<int>.this[int index] => _this.Games[index].StartIdxInLog;

int IReadOnlyCollection<int>.Count { get => _this.Games.Count; }

IEnumerator<int> IEnumerable<int>.GetEnumerator() => _this.Games.Select(g => g.StartIdxInLog).GetEnumerator();

System.Collections.IEnumerator System.Collections.IEnumerable.GetEnumerator() => ((IEnumerable<int>)this).GetEnumerator();
}
public IReadOnlyList<int> 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<string>();
}

game.GameStateFileNames.Add(file.Item2);
}
}
public void AddDesyncs(IEnumerable<int> 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<TextTruncator.RegionOfInterest> MakeRegionsOfInterest(int stringLength, IEnumerable<int> pointsOfInterest, IReadOnlyList<int> 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<TextTruncator.RegionOfInterest>();

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<Issue> 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<int>();

var negativeFrameRegex = new Regex(@"f=-(?<=(?<s>^)\[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<int>();
}
}
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 ""(?<d>[^{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<Match>().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<TextTruncator.RegionOfInterest>(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<Match>().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<int>();
}
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:) (?<g>[0-9a-zA-Z]+){InfoLogLineEndPattern}",
RegexOptions.CultureInvariant | RegexOptions.Compiled | RegexOptions.ExplicitCapture | RegexOptions.Multiline,
TimeSpan.FromSeconds(30))
.Cast<Match>().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.") ||
Expand Down Expand Up @@ -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
{
Expand Down
Loading

0 comments on commit 7a17fec

Please sign in to comment.