Fixes large discovery tests

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)

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()))}");
+                var pairDetails = string.Join(Nl, pairs.SelectMany(p => p.GetResultMessages()));
-                Assert.Fail(string.Join(Environment.NewLine, pairs.Select(p => p.GetMessage())));
+
-                test.Log(string.Join(Environment.NewLine, pairs.Select(p => p.GetMessage())));
+                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<Pair> pairs, Action action)
         {
-            var timeout = DateTime.UtcNow + TimeSpan.FromSeconds(30);
+            var timeout = DateTime.UtcNow + TimeSpan.FromMinutes(5);
-            while (pairs.Any() && timeout > DateTime.UtcNow)
+            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<Pair> 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<string>();
             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.";
+                    $"[{aName} --> {bName}] = {AKnowsB} ({aToBTime.TotalSeconds} seconds)",
-                }
+                    $"[{aName} <-- {bName}] = {BKnowsA} ({bToATime.TotalSeconds} seconds)"
-
+                };
-                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)";
             }
 
             private static TimeSpan Measure(Action action)
@@ -230,6 +223,7 @@ namespace DistTestCore.Helpers
             {
                 lock (a)
                 {
+                    Thread.Sleep(10);
                     var peerId = b.Response.id;
 
                     try

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; }

Logging/BaseLog.cs

@@ -21,11 +21,7 @@ namespace Logging
         {
             get
             {
-                if (logFile == null)
+                if (logFile == null) logFile = new LogFile(GetFullName(), "log");
-                {
-                    logFile = new LogFile(GetFullName(), "log");
-                    WriteLogTag();
-                }
                 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();

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;