From f50b8dfc833db2afbcd0d389802f4e0edfb4ecde Mon Sep 17 00:00:00 2001 From: benbierens Date: Tue, 18 Jul 2023 09:02:41 +0200 Subject: [PATCH 1/8] Sets up StatusLog --- Logging/FixtureLog.cs | 35 ++--------------- Logging/NameUtils.cs | 60 ++++++++++++++++++++++++++++ Logging/StatusLog.cs | 91 +++++++++++++++++++++++++++++++++++++++++++ Logging/TestLog.cs | 21 +--------- 4 files changed, 155 insertions(+), 52 deletions(-) create mode 100644 Logging/NameUtils.cs create mode 100644 Logging/StatusLog.cs diff --git a/Logging/FixtureLog.cs b/Logging/FixtureLog.cs index e386f01..809ff38 100644 --- a/Logging/FixtureLog.cs +++ b/Logging/FixtureLog.cs @@ -1,20 +1,14 @@ -using NUnit.Framework; - -namespace Logging +namespace Logging { public class FixtureLog : BaseLog { - private readonly DateTime start; private readonly string fullName; private readonly LogConfig config; - public FixtureLog(LogConfig config, string name = "") + public FixtureLog(LogConfig config, DateTime start, string name = "") : base(config.DebugEnabled) { - start = DateTime.UtcNow; - var folder = DetermineFolder(config); - var fixtureName = GetFixtureName(name); - fullName = Path.Combine(folder, fixtureName); + fullName = NameUtils.GetFixtureFullName(config, start, name); this.config = config; } @@ -32,28 +26,5 @@ namespace Logging { return fullName; } - - private string DetermineFolder(LogConfig config) - { - return Path.Join( - config.LogRoot, - $"{start.Year}-{Pad(start.Month)}", - Pad(start.Day)); - } - - private string GetFixtureName(string name) - { - var test = TestContext.CurrentContext.Test; - var className = test.ClassName!.Substring(test.ClassName.LastIndexOf('.') + 1); - if (!string.IsNullOrEmpty(name)) className = name; - - return $"{Pad(start.Hour)}-{Pad(start.Minute)}-{Pad(start.Second)}Z_{className.Replace('.', '-')}"; - } - - private static string Pad(int n) - { - return n.ToString().PadLeft(2, '0'); - } - } } diff --git a/Logging/NameUtils.cs b/Logging/NameUtils.cs new file mode 100644 index 0000000..0a5fcbe --- /dev/null +++ b/Logging/NameUtils.cs @@ -0,0 +1,60 @@ +using NUnit.Framework; + +namespace Logging +{ + public static class NameUtils + { + public static string GetTestMethodName(string name = "") + { + if (!string.IsNullOrEmpty(name)) return name; + var test = TestContext.CurrentContext.Test; + var args = FormatArguments(test); + return ReplaceInvalidCharacters($"{test.MethodName}{args}"); + } + + public static string GetFixtureFullName(LogConfig config, DateTime start, string name) + { + var folder = DetermineFolder(config, start); + var fixtureName = GetFixtureName(name, start); + return Path.Combine(folder, fixtureName); + } + + public static string GetRawFixtureName() + { + var test = TestContext.CurrentContext.Test; + var className = test.ClassName!.Substring(test.ClassName.LastIndexOf('.') + 1); + return className.Replace('.', '-'); + } + + private static string FormatArguments(TestContext.TestAdapter test) + { + if (test.Arguments == null || !test.Arguments.Any()) return ""; + return $"[{string.Join(',', test.Arguments)}]"; + } + + private static string ReplaceInvalidCharacters(string name) + { + return name.Replace(":", "_"); + } + + private static string DetermineFolder(LogConfig config, DateTime start) + { + return Path.Join( + config.LogRoot, + $"{start.Year}-{Pad(start.Month)}", + Pad(start.Day)); + } + + private static string GetFixtureName(string name, DateTime start) + { + var className = GetRawFixtureName(); + if (!string.IsNullOrEmpty(name)) className = name; + return $"{Pad(start.Hour)}-{Pad(start.Minute)}-{Pad(start.Second)}Z_{className.Replace('.', '-')}"; + } + + private static string Pad(int n) + { + return n.ToString().PadLeft(2, '0'); + } + } +} diff --git a/Logging/StatusLog.cs b/Logging/StatusLog.cs new file mode 100644 index 0000000..5af7542 --- /dev/null +++ b/Logging/StatusLog.cs @@ -0,0 +1,91 @@ +using Newtonsoft.Json; + +namespace Logging +{ + public class StatusLog + { + private readonly object fileLock = new object(); + private readonly string fullName; + private readonly string fixtureName; + private readonly string codexId; + + public StatusLog(LogConfig config, DateTime start, string codexId, string name = "") + { + fullName = NameUtils.GetFixtureFullName(config, start, name); + fixtureName = NameUtils.GetRawFixtureName(); + this.codexId = codexId; + } + + public void TestPassed() + { + Write("successful"); + } + + public void TestFailed() + { + Write("failed"); + } + + private void Write(string status) + { + Write(new StatusLogJson + { + time = DateTime.UtcNow.ToString("u"), + runid = GetRunId(), + status = status, + testid = GetTestId(), + codexid = codexId, + fixturename = fixtureName, + testname = GetTestName() + }); + } + + private string GetTestName() + { + return NameUtils.GetTestMethodName(); + } + + private string GetTestId() + { + return GetEnvVar("TESTID"); + } + + private string GetRunId() + { + return GetEnvVar("RUNID"); + } + + private string GetEnvVar(string name) + { + var v = Environment.GetEnvironmentVariable(name); + if (string.IsNullOrEmpty(v)) return $"'{name}' not set!"; + return v; + } + + private void Write(StatusLogJson json) + { + try + { + lock (fileLock) + { + File.AppendAllLines(fullName, new[] { JsonConvert.SerializeObject(json) }); + } + } + catch (Exception ex) + { + Console.WriteLine("Unable to write to status log: " + ex); + } + } + } + + public class StatusLogJson + { + public string time { get; set; } = string.Empty; + public string runid { get; set; } = string.Empty; + public string status { get; set; } = string.Empty; + public string testid { get; set; } = string.Empty; + public string codexid { get; set; } = string.Empty; + public string fixturename { get; set; } = string.Empty; + public string testname { get; set; } = string.Empty; + } +} diff --git a/Logging/TestLog.cs b/Logging/TestLog.cs index 1bf5d41..a8d3249 100644 --- a/Logging/TestLog.cs +++ b/Logging/TestLog.cs @@ -10,7 +10,7 @@ namespace Logging public TestLog(string folder, bool debug, string name = "") : base(debug) { - methodName = GetMethodName(name); + methodName = NameUtils.GetTestMethodName(name); fullName = Path.Combine(folder, methodName); Log($"*** Begin: {methodName}"); @@ -37,24 +37,5 @@ namespace Logging { return fullName; } - - private string GetMethodName(string name) - { - if (!string.IsNullOrEmpty(name)) return name; - var test = TestContext.CurrentContext.Test; - var args = FormatArguments(test); - return ReplaceInvalidCharacters($"{test.MethodName}{args}"); - } - - private static string FormatArguments(TestContext.TestAdapter test) - { - if (test.Arguments == null || !test.Arguments.Any()) return ""; - return $"[{string.Join(',', test.Arguments)}]"; - } - - private static string ReplaceInvalidCharacters(string name) - { - return name.Replace(":", "_"); - } } } From 009ce1e9f3d27c3e8042ffc705f4ed26b46725db Mon Sep 17 00:00:00 2001 From: benbierens Date: Tue, 18 Jul 2023 09:47:44 +0200 Subject: [PATCH 2/8] Wires up the status log. --- ContinuousTests/Configuration.cs | 6 ++++-- ContinuousTests/ContinuousTestRunner.cs | 2 +- ContinuousTests/SingleTestRun.cs | 2 +- ContinuousTests/StartupChecker.cs | 2 +- DistTestCore/DistTest.cs | 7 ++++++- Logging/StatusLog.cs | 14 ++------------ 6 files changed, 15 insertions(+), 18 deletions(-) diff --git a/ContinuousTests/Configuration.cs b/ContinuousTests/Configuration.cs index dd122cb..1cfb697 100644 --- a/ContinuousTests/Configuration.cs +++ b/ContinuousTests/Configuration.cs @@ -57,9 +57,11 @@ namespace ContinuousTests private static void PrintHelp() { var nl = Environment.NewLine; - Console.WriteLine("CodexNetDownloader lets you download all container logs given a codex-deployment.json file." + nl); + Console.WriteLine("ContinuousTests will run a set of tests against a codex deployment given a codex-deployment.json file." + nl + + "The tests will run in an endless loop unless otherwise specified, using the test-specific timing values." + nl); - Console.WriteLine("CodexNetDownloader assumes you are running this tool from *inside* the Kubernetes cluster. " + + + Console.WriteLine("ContinuousTests assumes you are running this tool from *inside* the Kubernetes cluster. " + "If you are not running this from a container inside the cluster, add the argument '--external'." + nl); } } diff --git a/ContinuousTests/ContinuousTestRunner.cs b/ContinuousTests/ContinuousTestRunner.cs index 5be4ff8..d7ac7d9 100644 --- a/ContinuousTests/ContinuousTestRunner.cs +++ b/ContinuousTests/ContinuousTestRunner.cs @@ -24,7 +24,7 @@ namespace ContinuousTests startupChecker.Check(); var taskFactory = new TaskFactory(); - var overviewLog = new FixtureLog(new LogConfig(config.LogPath, false), "Overview"); + var overviewLog = new FixtureLog(new LogConfig(config.LogPath, false), DateTime.UtcNow, "Overview"); overviewLog.Log("Continuous tests starting..."); var allTests = testFactory.CreateTests(); diff --git a/ContinuousTests/SingleTestRun.cs b/ContinuousTests/SingleTestRun.cs index f8e6583..b065c77 100644 --- a/ContinuousTests/SingleTestRun.cs +++ b/ContinuousTests/SingleTestRun.cs @@ -32,7 +32,7 @@ namespace ContinuousTests this.handle = handle; this.cancelToken = cancelToken; testName = handle.Test.GetType().Name; - fixtureLog = new FixtureLog(new LogConfig(config.LogPath, true), testName); + fixtureLog = new FixtureLog(new LogConfig(config.LogPath, true), DateTime.UtcNow, testName); nodes = CreateRandomNodes(handle.Test.RequiredNumberOfNodes); dataFolder = config.DataPath + "-" + Guid.NewGuid(); diff --git a/ContinuousTests/StartupChecker.cs b/ContinuousTests/StartupChecker.cs index a2e1e1f..f6a470c 100644 --- a/ContinuousTests/StartupChecker.cs +++ b/ContinuousTests/StartupChecker.cs @@ -19,7 +19,7 @@ namespace ContinuousTests public void Check() { - var log = new FixtureLog(new LogConfig(config.LogPath, false), "StartupChecks"); + var log = new FixtureLog(new LogConfig(config.LogPath, false), DateTime.UtcNow, "StartupChecks"); log.Log("Starting continuous test run..."); log.Log("Checking configuration..."); PreflightCheck(config); diff --git a/DistTestCore/DistTest.cs b/DistTestCore/DistTest.cs index e2a5c77..76c966a 100644 --- a/DistTestCore/DistTest.cs +++ b/DistTestCore/DistTest.cs @@ -16,6 +16,7 @@ namespace DistTestCore private readonly Configuration configuration = new Configuration(); private readonly Assembly[] testAssemblies; private readonly FixtureLog fixtureLog; + private readonly StatusLog statusLog; private readonly object lifecycleLock = new object(); private readonly Dictionary lifecycles = new Dictionary(); @@ -24,7 +25,10 @@ namespace DistTestCore var assemblies = AppDomain.CurrentDomain.GetAssemblies(); testAssemblies = assemblies.Where(a => a.FullName!.ToLowerInvariant().Contains("test")).ToArray(); - fixtureLog = new FixtureLog(configuration.GetLogConfig()); + var logConfig = configuration.GetLogConfig(); + var startTime = DateTime.UtcNow; + fixtureLog = new FixtureLog(logConfig, startTime); + statusLog = new StatusLog(logConfig, startTime, CodexContainerRecipe.DockerImage); PeerConnectionTestHelpers = new PeerConnectionTestHelpers(this); PeerDownloadTestHelpers = new PeerDownloadTestHelpers(this); @@ -196,6 +200,7 @@ namespace DistTestCore { var lifecycle = Get(); fixtureLog.Log($"{GetCurrentTestName()} = {GetTestResult()} ({lifecycle.GetTestDuration()})"); + statusLog.ConcludeTest(GetTestResult()); Stopwatch.Measure(fixtureLog, $"Teardown for {GetCurrentTestName()}", () => { lifecycle.Log.EndTest(); diff --git a/Logging/StatusLog.cs b/Logging/StatusLog.cs index 5af7542..4d852ee 100644 --- a/Logging/StatusLog.cs +++ b/Logging/StatusLog.cs @@ -16,23 +16,13 @@ namespace Logging this.codexId = codexId; } - public void TestPassed() - { - Write("successful"); - } - - public void TestFailed() - { - Write("failed"); - } - - private void Write(string status) + public void ConcludeTest(string resultStatus) { Write(new StatusLogJson { time = DateTime.UtcNow.ToString("u"), runid = GetRunId(), - status = status, + status = resultStatus, testid = GetTestId(), codexid = codexId, fixturename = fixtureName, From fa1057ddfd4f3b031bec05d89c5aa5d75021eed4 Mon Sep 17 00:00:00 2001 From: benbierens Date: Tue, 18 Jul 2023 10:39:27 +0200 Subject: [PATCH 3/8] Sets correct output filename for status log. --- Logging/StatusLog.cs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Logging/StatusLog.cs b/Logging/StatusLog.cs index 4d852ee..44af462 100644 --- a/Logging/StatusLog.cs +++ b/Logging/StatusLog.cs @@ -11,7 +11,7 @@ namespace Logging public StatusLog(LogConfig config, DateTime start, string codexId, string name = "") { - fullName = NameUtils.GetFixtureFullName(config, start, name); + fullName = NameUtils.GetFixtureFullName(config, start, name) + "_STATUS.log"; fixtureName = NameUtils.GetRawFixtureName(); this.codexId = codexId; } From 07776dc6fb065dbbe6f1aebe8e05c50ad94575db Mon Sep 17 00:00:00 2001 From: benbierens Date: Tue, 18 Jul 2023 11:04:14 +0200 Subject: [PATCH 4/8] Adds log tag to each log file. --- Logging/BaseLog.cs | 14 +++++++++++++- Logging/NameUtils.cs | 23 +++++++++++++++++++++++ Logging/StatusLog.cs | 28 +++------------------------- 3 files changed, 39 insertions(+), 26 deletions(-) diff --git a/Logging/BaseLog.cs b/Logging/BaseLog.cs index 14656e3..6ff6da5 100644 --- a/Logging/BaseLog.cs +++ b/Logging/BaseLog.cs @@ -21,7 +21,11 @@ namespace Logging { get { - if (logFile == null) logFile = new LogFile(GetFullName(), "log"); + if (logFile == null) + { + logFile = new LogFile(GetFullName(), "log"); + WriteLogTag(); + } return logFile; } } @@ -73,6 +77,14 @@ namespace Logging return new LogFile($"{GetFullName()}_{GetSubfileNumber()}", ext); } + private void WriteLogTag() + { + var runId = NameUtils.GetRunId(); + var category = NameUtils.GetCategoryName(); + var name = NameUtils.GetTestMethodName(); + LogFile.WriteRaw($"{runId} {category} {name}"); + } + private string ApplyReplacements(string str) { foreach (var replacement in replacements) diff --git a/Logging/NameUtils.cs b/Logging/NameUtils.cs index 0a5fcbe..aee7d84 100644 --- a/Logging/NameUtils.cs +++ b/Logging/NameUtils.cs @@ -26,6 +26,29 @@ namespace Logging return className.Replace('.', '-'); } + public static string GetCategoryName() + { + var test = TestContext.CurrentContext.Test; + return test.ClassName!.Substring(0, test.ClassName.LastIndexOf('.')); + } + + public static string GetTestId() + { + return GetEnvVar("TESTID"); + } + + public static string GetRunId() + { + return GetEnvVar("RUNID"); + } + + private static string GetEnvVar(string name) + { + var v = Environment.GetEnvironmentVariable(name); + if (string.IsNullOrEmpty(v)) return $"EnvVar'{name}'NotSet"; + return v; + } + private static string FormatArguments(TestContext.TestAdapter test) { if (test.Arguments == null || !test.Arguments.Any()) return ""; diff --git a/Logging/StatusLog.cs b/Logging/StatusLog.cs index 44af462..06c9f22 100644 --- a/Logging/StatusLog.cs +++ b/Logging/StatusLog.cs @@ -21,37 +21,15 @@ namespace Logging Write(new StatusLogJson { time = DateTime.UtcNow.ToString("u"), - runid = GetRunId(), + runid = NameUtils.GetRunId(), status = resultStatus, - testid = GetTestId(), + testid = NameUtils.GetTestId(), codexid = codexId, fixturename = fixtureName, - testname = GetTestName() + testname = NameUtils.GetTestMethodName() }); } - private string GetTestName() - { - return NameUtils.GetTestMethodName(); - } - - private string GetTestId() - { - return GetEnvVar("TESTID"); - } - - private string GetRunId() - { - return GetEnvVar("RUNID"); - } - - private string GetEnvVar(string name) - { - var v = Environment.GetEnvironmentVariable(name); - if (string.IsNullOrEmpty(v)) return $"'{name}' not set!"; - return v; - } - private void Write(StatusLogJson json) { try From d6d32bf8e6037dee047d5c7503d0d2f600f4338f Mon Sep 17 00:00:00 2001 From: benbierens Date: Tue, 18 Jul 2023 13:18:26 +0200 Subject: [PATCH 5/8] Adds category to status log. Updates timestamp format --- Logging/LogFile.cs | 2 +- Logging/StatusLog.cs | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/Logging/LogFile.cs b/Logging/LogFile.cs index 349e7c6..8c0ff2f 100644 --- a/Logging/LogFile.cs +++ b/Logging/LogFile.cs @@ -49,7 +49,7 @@ private static string GetTimestamp() { - return $"[{DateTime.UtcNow.ToString("u")}]"; + return $"[{DateTime.UtcNow.ToString("o")}]"; } private void EnsurePathExists(string filename) diff --git a/Logging/StatusLog.cs b/Logging/StatusLog.cs index 06c9f22..a62c70a 100644 --- a/Logging/StatusLog.cs +++ b/Logging/StatusLog.cs @@ -20,11 +20,12 @@ namespace Logging { Write(new StatusLogJson { - time = DateTime.UtcNow.ToString("u"), + time = DateTime.UtcNow.ToString("o"), runid = NameUtils.GetRunId(), status = resultStatus, testid = NameUtils.GetTestId(), codexid = codexId, + category = NameUtils.GetCategoryName(), fixturename = fixtureName, testname = NameUtils.GetTestMethodName() }); @@ -53,6 +54,7 @@ namespace Logging public string status { get; set; } = string.Empty; public string testid { get; set; } = string.Empty; public string codexid { get; set; } = string.Empty; + public string category { get; set; } = string.Empty; public string fixturename { get; set; } = string.Empty; public string testname { get; set; } = string.Empty; } From bfefba9633469e90a1960bc8213bfd33e8bf185a Mon Sep 17 00:00:00 2001 From: benbierens Date: Tue, 18 Jul 2023 14:26:21 +0200 Subject: [PATCH 6/8] Fixes large discovery tests --- DistTestCore/DistTest.cs | 1 + .../Helpers/PeerConnectionTestHelpers.cs | 52 ++++++++----------- DistTestCore/TestLifecycle.cs | 2 + Logging/BaseLog.cs | 8 +-- Logging/StatusLog.cs | 4 +- 5 files changed, 30 insertions(+), 37 deletions(-) diff --git a/DistTestCore/DistTest.cs b/DistTestCore/DistTest.cs index 76c966a..9f4dc1e 100644 --- a/DistTestCore/DistTest.cs +++ b/DistTestCore/DistTest.cs @@ -187,6 +187,7 @@ namespace DistTestCore private void CreateNewTestLifecycle() { var testName = GetCurrentTestName(); + fixtureLog.WriteLogTag(); Stopwatch.Measure(fixtureLog, $"Setup for {testName}", () => { lock (lifecycleLock) diff --git a/DistTestCore/Helpers/PeerConnectionTestHelpers.cs b/DistTestCore/Helpers/PeerConnectionTestHelpers.cs index 93c8f21..7b326ff 100644 --- a/DistTestCore/Helpers/PeerConnectionTestHelpers.cs +++ b/DistTestCore/Helpers/PeerConnectionTestHelpers.cs @@ -6,6 +6,7 @@ namespace DistTestCore.Helpers { public class PeerConnectionTestHelpers { + private static string Nl = Environment.NewLine; private readonly Random random = new Random(); private readonly DistTest test; @@ -40,9 +41,11 @@ namespace DistTestCore.Helpers if (pairs.Any()) { - test.Log($"Unsuccessful! Peers are not fully-connected: {string.Join(",", nodes.Select(n => n.GetName()))}"); - Assert.Fail(string.Join(Environment.NewLine, pairs.Select(p => p.GetMessage()))); - test.Log(string.Join(Environment.NewLine, pairs.Select(p => p.GetMessage()))); + var pairDetails = string.Join(Nl, pairs.SelectMany(p => p.GetResultMessages())); + + test.Log($"Connections failed:{Nl}{pairDetails}"); + + Assert.Fail(string.Join(Nl, pairs.SelectMany(p => p.GetResultMessages()))); } else { @@ -52,18 +55,19 @@ namespace DistTestCore.Helpers private static void RetryWhilePairs(List pairs, Action action) { - var timeout = DateTime.UtcNow + TimeSpan.FromSeconds(30); - while (pairs.Any() && timeout > DateTime.UtcNow) + var timeout = DateTime.UtcNow + TimeSpan.FromMinutes(5); + while (pairs.Any(p => p.Inconclusive) && timeout > DateTime.UtcNow) { action(); - if (pairs.Any()) Time.Sleep(TimeSpan.FromSeconds(2)); + Time.Sleep(TimeSpan.FromSeconds(2)); } } private void CheckAndRemoveSuccessful(List pairs) { - var checkTasks = pairs.Select(p => Task.Run(() => + // For large sets, don't try and do all of them at once. + var checkTasks = pairs.Take(20).Select(p => Task.Run(() => { ApplyRandomDelay(); p.Check(); @@ -71,14 +75,16 @@ namespace DistTestCore.Helpers Task.WaitAll(checkTasks); + var pairDetails = new List(); foreach (var pair in pairs.ToArray()) { if (pair.Success) { - test.Log(pair.GetMessage()); + pairDetails.AddRange(pair.GetResultMessages()); pairs.Remove(pair); } } + test.Log($"Connections successful:{Nl}{string.Join(Nl, pairDetails)}"); } private static Entry[] CreateEntries(IOnlineCodexNode[] nodes) @@ -89,7 +95,7 @@ namespace DistTestCore.Helpers if (incorrectDiscoveryEndpoints.Any()) { Assert.Fail("Some nodes contain peer records with incorrect discovery ip/port information: " + - string.Join(Environment.NewLine, incorrectDiscoveryEndpoints)); + string.Join(Nl, incorrectDiscoveryEndpoints)); } return entries; @@ -181,6 +187,7 @@ namespace DistTestCore.Helpers public PeerConnectionState AKnowsB { get; private set; } public PeerConnectionState BKnowsA { get; private set; } public bool Success { get { return AKnowsB == PeerConnectionState.Connection && BKnowsA == PeerConnectionState.Connection; } } + public bool Inconclusive { get { return AKnowsB == PeerConnectionState.Unknown || BKnowsA == PeerConnectionState.Unknown; } } public void Check() { @@ -188,35 +195,21 @@ namespace DistTestCore.Helpers bToATime = Measure(() => BKnowsA = Knows(B, A)); } - public string GetMessage() - { - return GetResultMessage() + GetTimePostfix(); - } - public override string ToString() { - return $"[{GetMessage()}]"; + return $"[{string.Join(",", GetResultMessages())}]"; } - private string GetResultMessage() + public string[] GetResultMessages() { var aName = A.ToString(); var bName = B.ToString(); - if (Success) + return new[] { - return $"{aName} and {bName} know each other."; - } - - return $"[{aName}-->{bName}] = {AKnowsB} AND [{aName}<--{bName}] = {BKnowsA}"; - } - - private string GetTimePostfix() - { - var aName = A.ToString(); - var bName = B.ToString(); - - return $" ({aName}->{bName}: {aToBTime.TotalMinutes} seconds, {bName}->{aName}: {bToATime.TotalSeconds} seconds)"; + $"[{aName} --> {bName}] = {AKnowsB} ({aToBTime.TotalSeconds} seconds)", + $"[{aName} <-- {bName}] = {BKnowsA} ({bToATime.TotalSeconds} seconds)" + }; } private static TimeSpan Measure(Action action) @@ -230,6 +223,7 @@ namespace DistTestCore.Helpers { lock (a) { + Thread.Sleep(10); var peerId = b.Response.id; try diff --git a/DistTestCore/TestLifecycle.cs b/DistTestCore/TestLifecycle.cs index 5249960..50b665a 100644 --- a/DistTestCore/TestLifecycle.cs +++ b/DistTestCore/TestLifecycle.cs @@ -25,6 +25,8 @@ namespace DistTestCore PrometheusStarter = new PrometheusStarter(this, workflowCreator); GethStarter = new GethStarter(this, workflowCreator); testStart = DateTime.UtcNow; + + Log.WriteLogTag(); } public BaseLog Log { get; } diff --git a/Logging/BaseLog.cs b/Logging/BaseLog.cs index 6ff6da5..1164d1b 100644 --- a/Logging/BaseLog.cs +++ b/Logging/BaseLog.cs @@ -21,11 +21,7 @@ namespace Logging { get { - if (logFile == null) - { - logFile = new LogFile(GetFullName(), "log"); - WriteLogTag(); - } + if (logFile == null) logFile = new LogFile(GetFullName(), "log"); return logFile; } } @@ -77,7 +73,7 @@ namespace Logging return new LogFile($"{GetFullName()}_{GetSubfileNumber()}", ext); } - private void WriteLogTag() + public void WriteLogTag() { var runId = NameUtils.GetRunId(); var category = NameUtils.GetCategoryName(); diff --git a/Logging/StatusLog.cs b/Logging/StatusLog.cs index a62c70a..0913023 100644 --- a/Logging/StatusLog.cs +++ b/Logging/StatusLog.cs @@ -20,7 +20,7 @@ namespace Logging { Write(new StatusLogJson { - time = DateTime.UtcNow.ToString("o"), + @timestamp = DateTime.UtcNow.ToString("o"), runid = NameUtils.GetRunId(), status = resultStatus, testid = NameUtils.GetTestId(), @@ -49,7 +49,7 @@ namespace Logging public class StatusLogJson { - public string time { get; set; } = string.Empty; + public string @timestamp { get; set; } = string.Empty; public string runid { get; set; } = string.Empty; public string status { get; set; } = string.Empty; public string testid { get; set; } = string.Empty; From bbf66bb0f00481de362a4ee1326861f8a090198e Mon Sep 17 00:00:00 2001 From: benbierens Date: Tue, 18 Jul 2023 16:07:52 +0200 Subject: [PATCH 7/8] Cleanup of full connectivity helpers --- .../Helpers/FullConnectivityHelper.cs | 211 +++++++++++++++ .../Helpers/PeerConnectionTestHelpers.cs | 247 +++--------------- .../Helpers/PeerDownloadTestHelpers.cs | 73 +++--- 3 files changed, 273 insertions(+), 258 deletions(-) create mode 100644 DistTestCore/Helpers/FullConnectivityHelper.cs diff --git a/DistTestCore/Helpers/FullConnectivityHelper.cs b/DistTestCore/Helpers/FullConnectivityHelper.cs new file mode 100644 index 0000000..afa3442 --- /dev/null +++ b/DistTestCore/Helpers/FullConnectivityHelper.cs @@ -0,0 +1,211 @@ +using DistTestCore.Codex; +using NUnit.Framework; +using Utils; + +namespace DistTestCore.Helpers +{ + public interface IFullConnectivityImplementation + { + string Description(); + string ValidateEntry(FullConnectivityHelper.Entry entry, FullConnectivityHelper.Entry[] allEntries); + FullConnectivityHelper.PeerConnectionState Check(FullConnectivityHelper.Entry from, FullConnectivityHelper.Entry to); + } + + public class FullConnectivityHelper + { + private static string Nl = Environment.NewLine; + private readonly DistTest test; + private readonly IFullConnectivityImplementation implementation; + + public FullConnectivityHelper(DistTest test, IFullConnectivityImplementation implementation) + { + this.test = test; + this.implementation = implementation; + } + + public void AssertFullyConnected(IEnumerable nodes) + { + AssertFullyConnected(nodes.ToArray()); + } + + private void AssertFullyConnected(IOnlineCodexNode[] nodes) + { + test.Log($"Asserting '{implementation.Description()}' for nodes: '{string.Join(",", nodes.Select(n => n.GetName()))}'..."); + var entries = CreateEntries(nodes); + var pairs = CreatePairs(entries); + + RetryWhilePairs(pairs, () => + { + CheckAndRemoveSuccessful(pairs); + }); + + if (pairs.Any()) + { + var pairDetails = string.Join(Nl, pairs.SelectMany(p => p.GetResultMessages())); + + test.Log($"Connections failed:{Nl}{pairDetails}"); + + Assert.Fail(string.Join(Nl, pairs.SelectMany(p => p.GetResultMessages()))); + } + else + { + test.Log($"'{implementation.Description()}' = Success! for nodes: {string.Join(",", nodes.Select(n => n.GetName()))}"); + } + } + + private static void RetryWhilePairs(List pairs, Action action) + { + var timeout = DateTime.UtcNow + TimeSpan.FromMinutes(5); + while (pairs.Any(p => p.Inconclusive) && timeout > DateTime.UtcNow) + { + action(); + + Time.Sleep(TimeSpan.FromSeconds(2)); + } + } + + private void CheckAndRemoveSuccessful(List pairs) + { + // For large sets, don't try and do all of them at once. + var selectedPair = pairs.Take(20).ToArray(); + var pairDetails = new List(); + + foreach (var pair in selectedPair) + { + test.ScopedTestFiles(pair.Check); + + if (pair.Success) + { + pairDetails.AddRange(pair.GetResultMessages()); + pairs.Remove(pair); + } + } + + test.Log($"Connections successful:{Nl}{string.Join(Nl, pairDetails)}"); + } + + private Entry[] CreateEntries(IOnlineCodexNode[] nodes) + { + var entries = nodes.Select(n => new Entry(n)).ToArray(); + + var errors = entries + .Select(e => implementation.ValidateEntry(e, entries)) + .Where(s => !string.IsNullOrEmpty(s)) + .ToArray(); + + if (errors.Any()) + { + Assert.Fail("Some node entries failed to validate: " + string.Join(Nl, errors)); + } + + return entries; + } + + private List CreatePairs(Entry[] entries) + { + return CreatePairsIterator(entries).ToList(); + } + + private IEnumerable CreatePairsIterator(Entry[] entries) + { + for (var x = 0; x < entries.Length; x++) + { + for (var y = x + 1; y < entries.Length; y++) + { + yield return new Pair(implementation, entries[x], entries[y]); + } + } + } + + public class Entry + { + public Entry(IOnlineCodexNode node) + { + Node = node; + Response = node.GetDebugInfo(); + } + + public IOnlineCodexNode Node { get; } + public CodexDebugResponse Response { get; } + + public override string ToString() + { + if (Response == null || string.IsNullOrEmpty(Response.id)) return "UNKNOWN"; + return Response.id; + } + } + + public enum PeerConnectionState + { + Unknown, + Connection, + NoConnection, + } + + public class Pair + { + private TimeSpan aToBTime = TimeSpan.FromSeconds(0); + private TimeSpan bToATime = TimeSpan.FromSeconds(0); + private readonly IFullConnectivityImplementation implementation; + + public Pair(IFullConnectivityImplementation implementation, Entry a, Entry b) + { + this.implementation = implementation; + A = a; + B = b; + } + + public Entry A { get; } + public Entry B { get; } + public PeerConnectionState AKnowsB { get; private set; } + public PeerConnectionState BKnowsA { get; private set; } + public bool Success { get { return AKnowsB == PeerConnectionState.Connection && BKnowsA == PeerConnectionState.Connection; } } + public bool Inconclusive { get { return AKnowsB == PeerConnectionState.Unknown || BKnowsA == PeerConnectionState.Unknown; } } + + public void Check() + { + aToBTime = Measure(() => AKnowsB = Check(A, B)); + bToATime = Measure(() => BKnowsA = Check(B, A)); + } + + public override string ToString() + { + return $"[{string.Join(",", GetResultMessages())}]"; + } + + public string[] GetResultMessages() + { + var aName = A.ToString(); + var bName = B.ToString(); + + return new[] + { + $"[{aName} --> {bName}] = {AKnowsB} ({aToBTime.TotalSeconds} seconds)", + $"[{aName} <-- {bName}] = {BKnowsA} ({bToATime.TotalSeconds} seconds)" + }; + } + + private static TimeSpan Measure(Action action) + { + var start = DateTime.UtcNow; + action(); + return DateTime.UtcNow - start; + } + + private PeerConnectionState Check(Entry from, Entry to) + { + Thread.Sleep(10); + + try + { + return implementation.Check(from, to); + } + catch + { + // Didn't get a conclusive answer. Try again later. + return PeerConnectionState.Unknown; + } + } + } + } +} diff --git a/DistTestCore/Helpers/PeerConnectionTestHelpers.cs b/DistTestCore/Helpers/PeerConnectionTestHelpers.cs index 7b326ff..fa07b06 100644 --- a/DistTestCore/Helpers/PeerConnectionTestHelpers.cs +++ b/DistTestCore/Helpers/PeerConnectionTestHelpers.cs @@ -1,251 +1,66 @@ using DistTestCore.Codex; -using NUnit.Framework; -using Utils; +using static DistTestCore.Helpers.FullConnectivityHelper; namespace DistTestCore.Helpers { - public class PeerConnectionTestHelpers + public class PeerConnectionTestHelpers : IFullConnectivityImplementation { - private static string Nl = Environment.NewLine; - private readonly Random random = new Random(); - private readonly DistTest test; + private readonly FullConnectivityHelper helper; public PeerConnectionTestHelpers(DistTest test) { - this.test = test; + helper = new FullConnectivityHelper(test, this); } public void AssertFullyConnected(IEnumerable nodes) { - var n = nodes.ToArray(); - - AssertFullyConnected(n); - - for (int i = 0; i < 5; i++) - { - Time.Sleep(TimeSpan.FromSeconds(30)); - AssertFullyConnected(n); - } + helper.AssertFullyConnected(nodes); } - private void AssertFullyConnected(IOnlineCodexNode[] nodes) + public string Description() { - test.Log($"Asserting peers are fully-connected for nodes: '{string.Join(",", nodes.Select(n => n.GetName()))}'..."); - var entries = CreateEntries(nodes); - var pairs = CreatePairs(entries); - - RetryWhilePairs(pairs, () => - { - CheckAndRemoveSuccessful(pairs); - }); - - if (pairs.Any()) - { - var pairDetails = string.Join(Nl, pairs.SelectMany(p => p.GetResultMessages())); - - test.Log($"Connections failed:{Nl}{pairDetails}"); - - Assert.Fail(string.Join(Nl, pairs.SelectMany(p => p.GetResultMessages()))); - } - else - { - test.Log($"Success! Peers are fully-connected: {string.Join(",", nodes.Select(n => n.GetName()))}"); - } + return "Peer Discovery"; } - private static void RetryWhilePairs(List pairs, Action action) + public string ValidateEntry(Entry entry, Entry[] allEntries) { - var timeout = DateTime.UtcNow + TimeSpan.FromMinutes(5); - while (pairs.Any(p => p.Inconclusive) && timeout > DateTime.UtcNow) + var result = string.Empty; + foreach (var peer in entry.Response.table.nodes) { - action(); - - Time.Sleep(TimeSpan.FromSeconds(2)); - } - } - - private void CheckAndRemoveSuccessful(List pairs) - { - // For large sets, don't try and do all of them at once. - var checkTasks = pairs.Take(20).Select(p => Task.Run(() => - { - ApplyRandomDelay(); - p.Check(); - })).ToArray(); - - Task.WaitAll(checkTasks); - - var pairDetails = new List(); - foreach (var pair in pairs.ToArray()) - { - if (pair.Success) + var expected = GetExpectedDiscoveryEndpoint(allEntries, peer); + if (expected != peer.address) { - pairDetails.AddRange(pair.GetResultMessages()); - pairs.Remove(pair); + result += $"Node:{entry.Node.GetName()} has incorrect peer table entry. Was: '{peer.address}', expected: '{expected}'. "; } } - test.Log($"Connections successful:{Nl}{string.Join(Nl, pairDetails)}"); + return result; } - private static Entry[] CreateEntries(IOnlineCodexNode[] nodes) + public PeerConnectionState Check(Entry from, Entry to) { - var entries = nodes.Select(n => new Entry(n)).ToArray(); - var incorrectDiscoveryEndpoints = entries.SelectMany(e => e.GetInCorrectDiscoveryEndpoints(entries)).ToArray(); + var peerId = to.Response.id; - if (incorrectDiscoveryEndpoints.Any()) + var response = from.Node.GetDebugPeer(peerId); + if (!response.IsPeerFound) { - Assert.Fail("Some nodes contain peer records with incorrect discovery ip/port information: " + - string.Join(Nl, incorrectDiscoveryEndpoints)); + return PeerConnectionState.NoConnection; } - - return entries; + if (!string.IsNullOrEmpty(response.peerId) && response.addresses.Any()) + { + return PeerConnectionState.Connection; + } + return PeerConnectionState.Unknown; } - private static List CreatePairs(Entry[] entries) + private static string GetExpectedDiscoveryEndpoint(Entry[] allEntries, CodexDebugTableNodeResponse node) { - return CreatePairsIterator(entries).ToList(); - } + var peer = allEntries.SingleOrDefault(e => e.Response.table.localNode.peerId == node.peerId); + if (peer == null) return $"peerId: {node.peerId} is not known."; - private static IEnumerable CreatePairsIterator(Entry[] entries) - { - for (var x = 0; x < entries.Length; x++) - { - for (var y = x + 1; y < entries.Length; y++) - { - yield return new Pair(entries[x], entries[y]); - } - } - } - - private void ApplyRandomDelay() - { - // Calling all the nodes all at the same time is not exactly nice. - Time.Sleep(TimeSpan.FromMicroseconds(random.Next(10, 1000))); - } - - public class Entry - { - public Entry(IOnlineCodexNode node) - { - Node = node; - Response = node.GetDebugInfo(); - } - - public IOnlineCodexNode Node { get; } - public CodexDebugResponse Response { get; } - - public IEnumerable GetInCorrectDiscoveryEndpoints(Entry[] allEntries) - { - foreach (var peer in Response.table.nodes) - { - var expected = GetExpectedDiscoveryEndpoint(allEntries, peer); - if (expected != peer.address) - { - yield return $"Node:{Node.GetName()} has incorrect peer table entry. Was: '{peer.address}', expected: '{expected}'"; - } - } - } - - public override string ToString() - { - if (Response == null || string.IsNullOrEmpty(Response.id)) return "UNKNOWN"; - return Response.id; - } - - private static string GetExpectedDiscoveryEndpoint(Entry[] allEntries, CodexDebugTableNodeResponse node) - { - var peer = allEntries.SingleOrDefault(e => e.Response.table.localNode.peerId == node.peerId); - if (peer == null) return $"peerId: {node.peerId} is not known."; - - var n = (OnlineCodexNode)peer.Node; - var ip = n.CodexAccess.Container.Pod.PodInfo.Ip; - var discPort = n.CodexAccess.Container.Recipe.GetPortByTag(CodexContainerRecipe.DiscoveryPortTag); - return $"{ip}:{discPort.Number}"; - } - } - - public enum PeerConnectionState - { - Unknown, - Connection, - NoConnection, - } - - public class Pair - { - private TimeSpan aToBTime = TimeSpan.FromSeconds(0); - private TimeSpan bToATime = TimeSpan.FromSeconds(0); - - public Pair(Entry a, Entry b) - { - A = a; - B = b; - } - - public Entry A { get; } - public Entry B { get; } - public PeerConnectionState AKnowsB { get; private set; } - public PeerConnectionState BKnowsA { get; private set; } - public bool Success { get { return AKnowsB == PeerConnectionState.Connection && BKnowsA == PeerConnectionState.Connection; } } - public bool Inconclusive { get { return AKnowsB == PeerConnectionState.Unknown || BKnowsA == PeerConnectionState.Unknown; } } - - public void Check() - { - aToBTime = Measure(() => AKnowsB = Knows(A, B)); - bToATime = Measure(() => BKnowsA = Knows(B, A)); - } - - public override string ToString() - { - return $"[{string.Join(",", GetResultMessages())}]"; - } - - public string[] GetResultMessages() - { - var aName = A.ToString(); - var bName = B.ToString(); - - return new[] - { - $"[{aName} --> {bName}] = {AKnowsB} ({aToBTime.TotalSeconds} seconds)", - $"[{aName} <-- {bName}] = {BKnowsA} ({bToATime.TotalSeconds} seconds)" - }; - } - - private static TimeSpan Measure(Action action) - { - var start = DateTime.UtcNow; - action(); - return DateTime.UtcNow - start; - } - - private PeerConnectionState Knows(Entry a, Entry b) - { - lock (a) - { - Thread.Sleep(10); - var peerId = b.Response.id; - - try - { - var response = a.Node.GetDebugPeer(peerId); - if (!response.IsPeerFound) - { - return PeerConnectionState.NoConnection; - } - if (!string.IsNullOrEmpty(response.peerId) && response.addresses.Any()) - { - return PeerConnectionState.Connection; - } - } - catch - { - } - - // Didn't get a conclusive answer. Try again later. - return PeerConnectionState.Unknown; - } - } + var n = (OnlineCodexNode)peer.Node; + var ip = n.CodexAccess.Container.Pod.PodInfo.Ip; + var discPort = n.CodexAccess.Container.Recipe.GetPortByTag(CodexContainerRecipe.DiscoveryPortTag); + return $"{ip}:{discPort.Number}"; } } } diff --git a/DistTestCore/Helpers/PeerDownloadTestHelpers.cs b/DistTestCore/Helpers/PeerDownloadTestHelpers.cs index 2626d5f..ffb7d52 100644 --- a/DistTestCore/Helpers/PeerDownloadTestHelpers.cs +++ b/DistTestCore/Helpers/PeerDownloadTestHelpers.cs @@ -1,74 +1,63 @@ -using DistTestCore.Codex; -using NUnit.Framework; +using static DistTestCore.Helpers.FullConnectivityHelper; namespace DistTestCore.Helpers { - public class PeerDownloadTestHelpers + public class PeerDownloadTestHelpers : IFullConnectivityImplementation { + private readonly FullConnectivityHelper helper; private readonly DistTest test; + private ByteSize testFileSize; public PeerDownloadTestHelpers(DistTest test) { + helper = new FullConnectivityHelper(test, this); + testFileSize = 1.MB(); this.test = test; } public void AssertFullDownloadInterconnectivity(IEnumerable nodes, ByteSize testFileSize) { - test.Log($"Asserting full download interconnectivity for nodes: '{string.Join(",", nodes.Select(n => n.GetName()))}'..."); - var start = DateTime.UtcNow; - - foreach (var node in nodes) - { - var uploader = node; - var downloaders = nodes.Where(n => n != uploader).ToArray(); - - test.ScopedTestFiles(() => - { - PerformTest(uploader, downloaders, testFileSize); - }); - } - - test.Log($"Success! Full download interconnectivity for nodes: {string.Join(",", nodes.Select(n => n.GetName()))}"); - var timeTaken = DateTime.UtcNow - start; - - AssertTimePerMB(timeTaken, nodes.Count(), testFileSize); + this.testFileSize = testFileSize; + helper.AssertFullyConnected(nodes); } - private void AssertTimePerMB(TimeSpan timeTaken, int numberOfNodes, ByteSize size) + public string Description() { - var numberOfDownloads = numberOfNodes * (numberOfNodes - 1); - var timePerDownload = timeTaken / numberOfDownloads; - float sizeInMB = size.ToMB(); - var timePerMB = timePerDownload / sizeInMB; - - test.Log($"Performed {numberOfDownloads} downloads of {size} in {timeTaken.TotalSeconds} seconds, for an average of {timePerMB.TotalSeconds} seconds per MB."); - - Assert.That(timePerMB, Is.LessThan(CodexContainerRecipe.MaxDownloadTimePerMegabyte), "MaxDownloadTimePerMegabyte performance threshold breached."); + return "Download Connectivity"; } - private void PerformTest(IOnlineCodexNode uploader, IOnlineCodexNode[] downloaders, ByteSize testFileSize) + public string ValidateEntry(Entry entry, Entry[] allEntries) { - // Generate 1 test file per downloader. - var files = downloaders.Select(d => GenerateTestFile(uploader, d, testFileSize)).ToArray(); + return string.Empty; + } - // Upload all the test files to the uploader. - var contentIds = files.Select(uploader.UploadFile).ToArray(); + public PeerConnectionState Check(Entry from, Entry to) + { + var expectedFile = GenerateTestFile(from.Node, to.Node); - // Each downloader should retrieve its own test file. - for (var i = 0; i < downloaders.Length; i++) + var contentId = from.Node.UploadFile(expectedFile); + + try { - var expectedFile = files[i]; - var downloadedFile = downloaders[i].DownloadContent(contentIds[i], $"{expectedFile.Label}DOWNLOADED"); - + var downloadedFile = to.Node.DownloadContent(contentId, expectedFile.Label + "_downloaded"); expectedFile.AssertIsEqual(downloadedFile); + return PeerConnectionState.Connection; } + catch + { + // Should an exception occur during the download or file-content assertion, + // We consider that as no-connection for the purpose of this test. + return PeerConnectionState.NoConnection; + } + + // Should an exception occur during upload, then this try is inconclusive and we try again next loop. } - private TestFile GenerateTestFile(IOnlineCodexNode uploader, IOnlineCodexNode downloader, ByteSize testFileSize) + private TestFile GenerateTestFile(IOnlineCodexNode uploader, IOnlineCodexNode downloader) { var up = uploader.GetName().Replace("<", "").Replace(">", ""); var down = downloader.GetName().Replace("<", "").Replace(">", ""); - var label = $"FROM{up}TO{down}"; + var label = $"~from:{up}-to:{down}~"; return test.GenerateTestFile(testFileSize, label); } } From 344c004299422c4576febbd354569bb94a020a46 Mon Sep 17 00:00:00 2001 From: benbierens Date: Fri, 21 Jul 2023 09:20:28 +0200 Subject: [PATCH 8/8] Adds test duration to status log --- DistTestCore/DistTest.cs | 6 ++++-- Logging/StatusLog.cs | 6 ++++-- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/DistTestCore/DistTest.cs b/DistTestCore/DistTest.cs index 9f4dc1e..3560d5d 100644 --- a/DistTestCore/DistTest.cs +++ b/DistTestCore/DistTest.cs @@ -200,8 +200,10 @@ namespace DistTestCore private void DisposeTestLifecycle() { var lifecycle = Get(); - fixtureLog.Log($"{GetCurrentTestName()} = {GetTestResult()} ({lifecycle.GetTestDuration()})"); - statusLog.ConcludeTest(GetTestResult()); + var testResult = GetTestResult(); + var testDuration = lifecycle.GetTestDuration(); + fixtureLog.Log($"{GetCurrentTestName()} = {testResult} ({testDuration})"); + statusLog.ConcludeTest(testResult, testDuration); Stopwatch.Measure(fixtureLog, $"Teardown for {GetCurrentTestName()}", () => { lifecycle.Log.EndTest(); diff --git a/Logging/StatusLog.cs b/Logging/StatusLog.cs index 0913023..740a564 100644 --- a/Logging/StatusLog.cs +++ b/Logging/StatusLog.cs @@ -16,7 +16,7 @@ namespace Logging this.codexId = codexId; } - public void ConcludeTest(string resultStatus) + public void ConcludeTest(string resultStatus, string testDuration) { Write(new StatusLogJson { @@ -27,7 +27,8 @@ namespace Logging codexid = codexId, category = NameUtils.GetCategoryName(), fixturename = fixtureName, - testname = NameUtils.GetTestMethodName() + testname = NameUtils.GetTestMethodName(), + testduration = testDuration }); } @@ -57,5 +58,6 @@ namespace Logging public string category { get; set; } = string.Empty; public string fixturename { get; set; } = string.Empty; public string testname { get; set; } = string.Empty; + public string testduration { get; set;} = string.Empty; } }