Better logging + time measurement

DistTestCore/CodexNodeGroup.cs

@@ -73,7 +73,7 @@ namespace DistTestCore
 
         public string Describe()
         {
-            return $"CodexNodeGroup@{Containers.Describe()}-{Setup.Describe()}";
+            return $"<CodexNodeGroup@{Containers.Describe()}-{Setup.Describe()}>";
         }
 
         private OnlineCodexNode CreateOnlineCodexNode(RunningContainer c, ICodexNodeFactory factory)

DistTestCore/CodexSetup.cs

@@ -71,7 +71,7 @@ namespace DistTestCore
         public string Describe()
         {
             var args = string.Join(',', DescribeArgs());
-            return $"{NumberOfNodes} CodexNodes with [{args}]";
+            return $"({NumberOfNodes} CodexNodes with [{args}])";
         }
 
         private IEnumerable<string> DescribeArgs()

DistTestCore/DistTest.cs

@@ -2,27 +2,35 @@
 using DistTestCore.Logs;
 using DistTestCore.Marketplace;
 using DistTestCore.Metrics;
+using KubernetesWorkflow;
 using Logging;
 using NUnit.Framework;
+using Utils;
 
 namespace DistTestCore
 {
     [SetUpFixture]
     public abstract class DistTest
     {
+        private readonly Configuration configuration = new Configuration();
+        private FixtureLog fixtureLog = null!;
         private TestLifecycle lifecycle = null!;
-        private TestLog log = null!;
+        private DateTime testStart = DateTime.MinValue;
 
         [OneTimeSetUp]
         public void GlobalSetup()
         {
             // Previous test run may have been interrupted.
             // Begin by cleaning everything up.
-            CreateNewTestLifecycle();
+            fixtureLog = new FixtureLog(configuration.GetLogConfig());
 
             try
             {
-                lifecycle.DeleteAllResources();
+                Stopwatch.Measure(fixtureLog, "Global setup", () =>
+                {
+                    var wc = new WorkflowCreator(configuration.GetK8sConfiguration());
+                    wc.CreateWorkflow().DeleteAllResources();
+                });                
             }
             catch (Exception ex)
             {
@@ -30,10 +38,11 @@ namespace DistTestCore
                 Error($"Global setup cleanup failed with: {ex}");
                 throw;
             }
-            log.Log("Global setup cleanup successful");
+
-            log.Log($"Codex image: {CodexContainerRecipe.DockerImage}");
+            fixtureLog.Log("Global setup cleanup successful");
-            log.Log($"Prometheus image: {PrometheusContainerRecipe.DockerImage}");
+            fixtureLog.Log($"Codex image: {CodexContainerRecipe.DockerImage}");
-            log.Log($"Geth image: {GethContainerRecipe.DockerImage}");
+            fixtureLog.Log($"Prometheus image: {PrometheusContainerRecipe.DockerImage}");
+            fixtureLog.Log($"Geth image: {GethContainerRecipe.DockerImage}");
         }
 
         [SetUp]
@@ -45,7 +54,6 @@ namespace DistTestCore
             }
             else
             {
-                log.Log($"Run: {TestContext.CurrentContext.Test.Name}");
                 CreateNewTestLifecycle();
             }
         }
@@ -55,10 +63,7 @@ namespace DistTestCore
         {
             try
             {
-                log.Log($"{TestContext.CurrentContext.Test.Name} = {TestContext.CurrentContext.Result.Outcome.Status}");
+                DisposeTestLifecycle();
-                lifecycle.Log.EndTest();
-                IncludeLogsAndMetricsOnTestFailure();
-                lifecycle.DeleteAllResources();
             }
             catch (Exception ex)
             {
@@ -82,6 +87,8 @@ namespace DistTestCore
             var result = TestContext.CurrentContext.Result;
             if (result.Outcome.Status == NUnit.Framework.Interfaces.TestStatus.Failed)
             {
+                fixtureLog.MarkAsFailed();
+
                 if (IsDownloadingLogsAndMetricsEnabled())
                 {
                     Log("Downloading all CodexNode logs and metrics because of test failure...");
@@ -107,7 +114,29 @@ namespace DistTestCore
 
         private void CreateNewTestLifecycle()
         {
-            lifecycle = new TestLifecycle(new Configuration());
+            Stopwatch.Measure(fixtureLog, $"Setup for {GetCurrentTestName()}", () =>
+            {
+                lifecycle = new TestLifecycle(fixtureLog.CreateTestLog(), configuration);
+                testStart = DateTime.UtcNow;
+            });
+        }
+
+        private void DisposeTestLifecycle()
+        {
+            fixtureLog.Log($"{GetCurrentTestName()} = {GetTestResult()} ({GetTestDuration()})");
+            Stopwatch.Measure(fixtureLog, $"Teardown for {GetCurrentTestName()}", () =>
+            {
+                lifecycle.Log.EndTest();
+                IncludeLogsAndMetricsOnTestFailure();
+                lifecycle.DeleteAllResources();
+                lifecycle = null!;
+            });
+        }
+
+        private string GetTestDuration()
+        {
+            var testDuration = DateTime.UtcNow - testStart;
+            return Time.FormatDuration(testDuration);
         }
 
         private void DownloadAllLogs()
@@ -141,6 +170,16 @@ namespace DistTestCore
             }
         }
 
+        private string GetCurrentTestName()
+        {
+            return $"[{TestContext.CurrentContext.Test.Name}]";
+        }
+
+        private string GetTestResult()
+        {
+            return TestContext.CurrentContext.Result.Outcome.Status.ToString();
+        }
+
         private bool IsDownloadingLogsAndMetricsEnabled()
         {
             var testProperties = TestContext.CurrentContext.Test.Properties;

DistTestCore/Logs/CodexNodeLog.cs

@@ -29,7 +29,7 @@ namespace DistTestCore.Logs
                 line = streamReader.ReadLine();
             }
 
-            Assert.Fail($"Unable to find string '{expectedString}' in CodexNode log file {logFile.FilenameWithoutPath}");
+            Assert.Fail($"Unable to find string '{expectedString}' in CodexNode log file {logFile.FullFilename}");
         }
     }
 }

DistTestCore/Logs/LogDownloadHandler.cs

@@ -21,7 +21,7 @@ namespace DistTestCore.Logs
 
         public void Log(Stream stream)
         {
-            log.Write($"{description} -->> {log.FilenameWithoutPath}");
+            log.Write($"{description} -->> {log.FullFilename}");
             log.WriteRaw(description);
             var reader = new StreamReader(stream);
             var line = reader.ReadLine();

DistTestCore/Metrics/MetricsDownloader.cs

@@ -26,7 +26,7 @@ namespace DistTestCore.Metrics
         private void WriteToFile(string nodeName, string[] headers, Dictionary<DateTime, List<string>> map)
         {
             var file = log.CreateSubfile("csv");
-            log.Log($"Downloading metrics for {nodeName} to file {file.FilenameWithoutPath}");
+            log.Log($"Downloading metrics for {nodeName} to file {file.FullFilename}");
 
             file.WriteRaw(string.Join(",", headers));
 

DistTestCore/OnlineCodexNode.cs

@@ -90,7 +90,7 @@ namespace DistTestCore
 
         public string Describe()
         {
-            return $"{Group.Describe()} contains {GetName()}";
+            return $"({Group.Describe()} contains {GetName()})";
         }
 
         private string GetPeerMultiAddress(OnlineCodexNode peer, CodexDebugResponse peerInfo)

DistTestCore/Stopwatch.cs

@@ -0,0 +1,19 @@
+using Logging;
+using Utils;
+
+namespace DistTestCore
+{
+    public class Stopwatch
+    {
+        public static void Measure(BaseLog log, string name, Action action)
+        {
+            var start = DateTime.UtcNow;
+
+            action();
+
+            var duration = DateTime.UtcNow - start;
+
+            log.Log($"{name} ({Time.FormatDuration(duration)})");
+        }
+    }
+}

DistTestCore/TestLifecycle.cs

@@ -8,9 +8,9 @@ namespace DistTestCore
     {
         private readonly WorkflowCreator workflowCreator;
 
-        public TestLifecycle(Configuration configuration)
+        public TestLifecycle(TestLog log, Configuration configuration)
         {
-            Log = new TestLog(configuration.GetLogConfig());
+            Log = log;
             workflowCreator = new WorkflowCreator(configuration.GetK8sConfiguration());
 
             FileManager = new FileManager(Log, configuration);
@@ -37,7 +37,7 @@ namespace DistTestCore
             var description = node.Describe();
             var handler = new LogDownloadHandler(description, subFile);
 
-            Log.Log($"Downloading logs for {description} to file {subFile.FilenameWithoutPath}");
+            Log.Log($"Downloading logs for {description} to file '{subFile.FullFilename}'");
             CodexStarter.DownloadLog(node.CodexAccess.Container, handler);
 
             return new CodexNodeLog(subFile);

Logging/BaseLog.cs

@@ -0,0 +1,36 @@
+namespace Logging
+{
+    public abstract class BaseLog
+    {
+        private bool hasFailed;
+        private LogFile? logFile;
+        
+        protected abstract LogFile CreateLogFile();
+
+        protected LogFile LogFile 
+        {
+            get
+            {
+                if (logFile == null) logFile = CreateLogFile();
+                return logFile;
+            }
+        }
+
+        public void Log(string message)
+        {
+            LogFile.Write(message);
+        }
+
+        public void Error(string message)
+        {
+            Log($"[ERROR] {message}");
+        }
+
+        public void MarkAsFailed()
+        {
+            if (hasFailed) return;
+            hasFailed = true;
+            LogFile.ConcatToFilename("_FAILED");
+        }
+    }
+}

Logging/FixtureLog.cs

@@ -0,0 +1,49 @@
+using NUnit.Framework;
+
+namespace Logging
+{
+    public class FixtureLog : BaseLog
+    {
+        private readonly DateTime start;
+        private readonly string fullName;
+
+        public FixtureLog(LogConfig config)
+        {
+            start = DateTime.UtcNow;
+            var folder = DetermineFolder(config);   // "root/2023-04 /14"
+            var fixtureName = GetFixtureName();     // "11-09-23Z_ExampleTests"
+            fullName = Path.Combine(folder, fixtureName);
+        }
+
+        public TestLog CreateTestLog()
+        {
+            return new TestLog(fullName);
+        }
+
+        protected override LogFile CreateLogFile()
+        {
+            return new LogFile(fullName, "log");
+        }
+
+        private string DetermineFolder(LogConfig config)
+        {
+            return Path.Join(
+               config.LogRoot,
+               $"{start.Year}-{Pad(start.Month)}",
+               Pad(start.Day));
+        }
+
+        private string GetFixtureName()
+        {
+            var test = TestContext.CurrentContext.Test;
+            var className = test.ClassName!.Substring(test.ClassName.LastIndexOf('.') + 1);
+            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');
+        }
+
+    }
+}

Logging/LogFile.cs

@@ -2,29 +2,19 @@
 {
     public class LogFile
     {
-        private readonly DateTime now;
+        private readonly string extension;
-        private string name;
+        private string filename;
-        private readonly string ext;
-        private readonly string filepath;
 
-        public LogFile(LogConfig config, DateTime now, string name, string ext = "log")
+        public LogFile(string filename, string extension)
         {
-            this.now = now;
+            this.filename = filename;
-            this.name = name;
+            this.extension = extension;
-            this.ext = ext;
+            FullFilename = filename + "." + extension;
 
-            filepath = Path.Join(
+            EnsurePathExists(filename);
-                config.LogRoot,
-                $"{now.Year}-{Pad(now.Month)}",
-                Pad(now.Day));
-
-            Directory.CreateDirectory(filepath);
-
-            GenerateFilename();
         }
 
-        public string FullFilename { get; private set; } = string.Empty;
+        public string FullFilename { get; private set; }
-        public string FilenameWithoutPath { get; private set; } = string.Empty;
 
         public void Write(string message)
         {
@@ -47,27 +37,21 @@
         {
             var oldFullName = FullFilename;
 
-            name += toAdd;
+            filename += toAdd;
-
+            FullFilename = filename + "." + extension;
-            GenerateFilename();
 
             File.Move(oldFullName, FullFilename);
         }
 
-        private static string Pad(int n)
-        {
-            return n.ToString().PadLeft(2, '0');
-        }
-
         private static string GetTimestamp()
         {
             return $"[{DateTime.UtcNow.ToString("u")}]";
         }
 
-        private void GenerateFilename()
+        private void EnsurePathExists(string filename)
         {
-            FilenameWithoutPath = $"{Pad(now.Hour)}-{Pad(now.Minute)}-{Pad(now.Second)}Z_{name.Replace('.', '-')}.{ext}";
+            var path = new FileInfo(filename).Directory!.FullName;
-            FullFilename = Path.Combine(filepath, FilenameWithoutPath);
+            Directory.CreateDirectory(path);
         }
     }
 }

Logging/TestLog.cs

@@ -3,39 +3,30 @@ using Utils;
 
 namespace Logging
 {
-    public class TestLog
+    public class TestLog : BaseLog
     {
         private readonly NumberSource subfileNumberSource = new NumberSource(0);
-        private readonly LogFile file;
+        private readonly string methodName;
-        private readonly DateTime now;
+        private readonly string fullName;
-        private readonly LogConfig config;
 
-        public TestLog(LogConfig config)
+        public TestLog(string folder)
         {
-            this.config = config;
+            methodName = GetMethodName();
-            now = DateTime.UtcNow;
+            fullName = Path.Combine(folder, methodName);
 
-            var name = GetTestName();
+            Log($"Begin: {methodName}");
-            file = new LogFile(config, now, name);
-
-            Log($"Begin: {name}");
         }
 
-        public void Log(string message)
+        public LogFile CreateSubfile(string ext = "log")
         {
-            file.Write(message);
+            return new LogFile($"{fullName}_{GetSubfileNumber()}", ext);
-        }
-
-        public void Error(string message)
-        {
-            Log($"[ERROR] {message}");
         }
 
         public void EndTest()
         {
             var result = TestContext.CurrentContext.Result;
 
-            Log($"Finished: {GetTestName()} = {result.Outcome.Status}");
+            Log($"Finished: {methodName} = {result.Outcome.Status}");
             if (!string.IsNullOrEmpty(result.Message))
             {
                 Log(result.Message);
@@ -44,26 +35,24 @@ namespace Logging
 
             if (result.Outcome.Status == NUnit.Framework.Interfaces.TestStatus.Failed)
             {
-                RenameLogFile();
+                MarkAsFailed();
             }
         }
-
+        protected override LogFile CreateLogFile()
-        private void RenameLogFile()
         {
-            file.ConcatToFilename("_FAILED");
+            return new LogFile(fullName, "log");
         }
 
-        public LogFile CreateSubfile(string ext = "log")
+        private string GetMethodName()
-        {
-            return new LogFile(config, now, $"{GetTestName()}_{subfileNumberSource.GetNextNumber().ToString().PadLeft(6, '0')}", ext);
-        }
-
-        private static string GetTestName()
         {
             var test = TestContext.CurrentContext.Test;
-            var className = test.ClassName!.Substring(test.ClassName.LastIndexOf('.') + 1);
             var args = FormatArguments(test);
-            return $"{className}.{test.MethodName}{args}";
+            return $"{test.MethodName}{args}";
+        }
+
+        private string GetSubfileNumber()
+        {
+            return subfileNumberSource.GetNextNumber().ToString().PadLeft(6, '0');
         }
 
         private static string FormatArguments(TestContext.TestAdapter test)

Tests/BasicTests/ExampleTests.cs

@@ -1,69 +1,12 @@
 using DistTestCore;
 using DistTestCore.Codex;
-using KubernetesWorkflow;
 using NUnit.Framework;
 
 namespace Tests.BasicTests
 {
     [TestFixture]
-    public class SimpleTests : DistTest
+    public class ExampleTests : DistTest
     {
-        [Test]
-        public void OneClientTest()
-        {
-            var primary = SetupCodexNodes(1).BringOnline()[0];
-
-            PerformOneClientTest(primary);
-        }
-
-        [Test]
-        public void RestartTest()
-        {
-            var group = SetupCodexNodes(1).BringOnline();
-
-            var setup = group.BringOffline();
-
-            var primary = setup.BringOnline()[0];
-
-            PerformOneClientTest(primary);
-        }
-
-        [Test]
-        public void TwoClientsOnePodTest()
-        {
-            var group = SetupCodexNodes(2).BringOnline();
-
-            var primary = group[0];
-            var secondary = group[1];
-
-            PerformTwoClientTest(primary, secondary);
-        }
-
-        [Test]
-        public void TwoClientsTwoPodsTest()
-        {
-            var primary = SetupCodexNodes(1).BringOnline()[0];
-
-            var secondary = SetupCodexNodes(1).BringOnline()[0];
-
-            PerformTwoClientTest(primary, secondary);
-        }
-
-        [Test]
-        [Ignore("Requires Location map to be configured for k8s cluster.")]
-        public void TwoClientsTwoLocationsTest()
-        {
-            var primary = SetupCodexNodes(1)
-                            .At(Location.BensLaptop)
-                            .BringOnline()[0];
-
-            var secondary = SetupCodexNodes(1)
-                            .At(Location.BensOldGamingMachine)
-                            .BringOnline()[0];
-
-            PerformTwoClientTest(primary, secondary);
-        }
-
         [Test]
         public void CodexLogExample()
         {
@@ -139,29 +82,5 @@ namespace Tests.BasicTests
             //secondary.Marketplace.AssertThatBalance(Is.LessThan(1000), "Contractor was not charged for storage.");
             //primary.Marketplace.AssertThatBalance(Is.GreaterThan(primaryBalance), "Storer was not paid for storage.");
         }
-
-        private void PerformOneClientTest(IOnlineCodexNode primary)
-        {
-            var testFile = GenerateTestFile(1.MB());
-
-            var contentId = primary.UploadFile(testFile);
-
-            var downloadedFile = primary.DownloadContent(contentId);
-
-            testFile.AssertIsEqual(downloadedFile);
-        }
-
-        private void PerformTwoClientTest(IOnlineCodexNode primary, IOnlineCodexNode secondary)
-        {
-            primary.ConnectToPeer(secondary);
-
-            var testFile = GenerateTestFile(1.MB());
-
-            var contentId = primary.UploadFile(testFile);
-
-            var downloadedFile = secondary.DownloadContent(contentId);
-
-            testFile.AssertIsEqual(downloadedFile);
-        }
     }
 }

Tests/BasicTests/OneClientTests.cs

@@ -0,0 +1,41 @@
+using DistTestCore;
+using NUnit.Framework;
+
+namespace Tests.BasicTests
+{
+    [TestFixture]
+    public class OneClientTests : DistTest
+    {
+        [Test]
+        public void OneClientTest()
+        {
+            var primary = SetupCodexNodes(1).BringOnline()[0];
+
+            PerformOneClientTest(primary);
+        }
+
+        [Test]
+        [Ignore("Unstable.")]
+        public void RestartTest()
+        {
+            var group = SetupCodexNodes(1).BringOnline();
+
+            var setup = group.BringOffline();
+
+            var primary = setup.BringOnline()[0];
+
+            PerformOneClientTest(primary);
+        }
+
+        private void PerformOneClientTest(IOnlineCodexNode primary)
+        {
+            var testFile = GenerateTestFile(1.MB());
+
+            var contentId = primary.UploadFile(testFile);
+
+            var downloadedFile = primary.DownloadContent(contentId);
+
+            testFile.AssertIsEqual(downloadedFile);
+        }
+    }
+}

Tests/BasicTests/TwoClientTests.cs

@@ -0,0 +1,59 @@
+using DistTestCore;
+using KubernetesWorkflow;
+using NUnit.Framework;
+
+namespace Tests.BasicTests
+{
+    [TestFixture]
+    public class TwoClientTests : DistTest
+    {
+        [Test]
+        public void TwoClientsOnePodTest()
+        {
+            var group = SetupCodexNodes(2).BringOnline();
+
+            var primary = group[0];
+            var secondary = group[1];
+
+            PerformTwoClientTest(primary, secondary);
+        }
+
+        [Test]
+        public void TwoClientsTwoPodsTest()
+        {
+            var primary = SetupCodexNodes(1).BringOnline()[0];
+
+            var secondary = SetupCodexNodes(1).BringOnline()[0];
+
+            PerformTwoClientTest(primary, secondary);
+        }
+
+        [Test]
+        [Ignore("Requires Location map to be configured for k8s cluster.")]
+        public void TwoClientsTwoLocationsTest()
+        {
+            var primary = SetupCodexNodes(1)
+                            .At(Location.BensLaptop)
+                            .BringOnline()[0];
+
+            var secondary = SetupCodexNodes(1)
+                            .At(Location.BensOldGamingMachine)
+                            .BringOnline()[0];
+
+            PerformTwoClientTest(primary, secondary);
+        }
+
+        private void PerformTwoClientTest(IOnlineCodexNode primary, IOnlineCodexNode secondary)
+        {
+            primary.ConnectToPeer(secondary);
+
+            var testFile = GenerateTestFile(1.MB());
+
+            var contentId = primary.UploadFile(testFile);
+
+            var downloadedFile = secondary.DownloadContent(contentId);
+
+            testFile.AssertIsEqual(downloadedFile);
+        }
+    }
+}

Utils/Time.cs

@@ -12,5 +12,15 @@
             task.Wait();
             return task.Result;
         }
+
+        public static string FormatDuration(TimeSpan d)
+        {
+            var result = "";
+            if (d.Days > 0) result += $"{d.Days} days, ";
+            if (d.Hours > 0) result += $"{d.Hours} hours, ";
+            if (d.Minutes > 0) result += $"{d.Minutes} mins, ";
+            result += $"{d.Seconds} secs";
+            return result;
+        }
     }
 }