Merge branch 'master' into feature/rewardbot-tests

Framework/NethereumWorkflow/BlockUtils/BlockTimeFinder.cs

@@ -46,7 +46,7 @@ namespace NethereumWorkflow.BlockUtils
 
         private ulong Log(Func<ulong> operation)
         {
-            var sw = Stopwatch.Begin(log, nameof(BlockTimeFinder));
+            var sw = Stopwatch.Begin(log, nameof(BlockTimeFinder), true);
             var result = operation();
             sw.End($"(Bounds: [{bounds.Genesis.BlockNumber}-{bounds.Current.BlockNumber}] Cache: {cache.Size})");
 

Framework/Utils/Time.cs

@@ -20,6 +20,12 @@ namespace Utils
             task.Wait();
         }
 
+        public static string FormatDuration(TimeSpan? d)
+        {
+            if (d == null) return "[NULL]";
+            return FormatDuration(d.Value);
+        }
+
         public static string FormatDuration(TimeSpan d)
         {
             var result = "";

ProjectPlugins/CodexPlugin/MarketplaceAccess.cs

@@ -38,7 +38,9 @@ namespace CodexPlugin
 
             Log($"Storage requested successfully. PurchaseId: '{response}'.");
 
-            return new StoragePurchaseContract(log, codexAccess, response, purchase);
+            var contract = new StoragePurchaseContract(log, codexAccess, response, purchase);
+            contract.WaitForStorageContractSubmitted();
+            return contract;
         }
 
         public string MakeStorageAvailable(StorageAvailability availability)
@@ -54,7 +56,7 @@ namespace CodexPlugin
 
         private void Log(string msg)
         {
-            log.Log($"{codexAccess.Container.Name} {msg}");
+            log.Log($"{codexAccess.Container.Containers.Single().Name} {msg}");
         }
     }
 
@@ -84,7 +86,10 @@ namespace CodexPlugin
         private readonly ILog log;
         private readonly CodexAccess codexAccess;
         private readonly TimeSpan gracePeriod = TimeSpan.FromSeconds(30);
-        private DateTime? contractStartUtc;
+        private readonly DateTime contractPendingUtc = DateTime.UtcNow;
+        private DateTime? contractSubmittedUtc = DateTime.UtcNow;
+        private DateTime? contractStartedUtc;
+        private DateTime? contractFinishedUtc;
 
         public StoragePurchaseContract(ILog log, CodexAccess codexAccess, string purchaseId, StoragePurchaseRequest purchase)
         {
@@ -97,23 +102,40 @@ namespace CodexPlugin
         public string PurchaseId { get; }
         public StoragePurchaseRequest Purchase { get; }
 
+        public TimeSpan? PendingToSubmitted => contractSubmittedUtc - contractPendingUtc;
+        public TimeSpan? SubmittedToStarted => contractStartedUtc - contractSubmittedUtc;
+        public TimeSpan? SubmittedToFinished => contractFinishedUtc - contractSubmittedUtc;
+
+        public void WaitForStorageContractSubmitted()
+        {
+            WaitForStorageContractState(gracePeriod, "submitted", sleep: 200);
+            contractSubmittedUtc = DateTime.UtcNow;
+            LogSubmittedDuration();
+            AssertDuration(PendingToSubmitted, gracePeriod, nameof(PendingToSubmitted));
+        }
+
         public void WaitForStorageContractStarted()
         {
             var timeout = Purchase.Expiry + gracePeriod;
 
             WaitForStorageContractState(timeout, "started");
-            contractStartUtc = DateTime.UtcNow;
+            contractStartedUtc = DateTime.UtcNow;
+            LogStartedDuration();
+            AssertDuration(SubmittedToStarted, timeout, nameof(SubmittedToStarted));
         }
 
         public void WaitForStorageContractFinished()
         {
-            if (!contractStartUtc.HasValue)
+            if (!contractStartedUtc.HasValue)
             {
                 WaitForStorageContractStarted();
             }
-            var currentContractTime = DateTime.UtcNow - contractStartUtc!.Value;
+            var currentContractTime = DateTime.UtcNow - contractSubmittedUtc!.Value;
             var timeout = (Purchase.Duration - currentContractTime) + gracePeriod;
             WaitForStorageContractState(timeout, "finished");
+            contractFinishedUtc = DateTime.UtcNow;
+            LogFinishedDuration();
+            AssertDuration(SubmittedToFinished, timeout, nameof(SubmittedToFinished));
         }
 
         public StoragePurchase GetPurchaseStatus(string purchaseId)
@@ -121,12 +143,12 @@ namespace CodexPlugin
             return codexAccess.GetPurchaseStatus(purchaseId);
         }
 
-        private void WaitForStorageContractState(TimeSpan timeout, string desiredState)
+        private void WaitForStorageContractState(TimeSpan timeout, string desiredState, int sleep = 1000)
         {
             var lastState = "";
             var waitStart = DateTime.UtcNow;
 
-            log.Log($"Waiting for {Time.FormatDuration(timeout)} for contract '{PurchaseId}' to reach state '{desiredState}'.");
+            Log($"Waiting for {Time.FormatDuration(timeout)} to reach state '{desiredState}'.");
             while (lastState != desiredState)
             {
                 var purchaseStatus = codexAccess.GetPurchaseStatus(PurchaseId);
@@ -137,7 +159,7 @@ namespace CodexPlugin
                     log.Debug("Purchase status: " + statusJson);
                 }
 
-                Thread.Sleep(1000);
+                Thread.Sleep(sleep);
 
                 if (lastState == "errored")
                 {
@@ -149,7 +171,40 @@ namespace CodexPlugin
                     FrameworkAssert.Fail($"Contract did not reach '{desiredState}' within {Time.FormatDuration(timeout)} timeout. {statusJson}");
                 }
             }
-            log.Log($"Contract '{desiredState}'.");
+        }
+
+        private void LogSubmittedDuration()
+        {
+            Log($"Pending to Submitted in {Time.FormatDuration(PendingToSubmitted)} " +
+                $"( < {Time.FormatDuration(gracePeriod)})");
+        }
+
+        private void LogStartedDuration()
+        {
+            Log($"Submitted to Started in {Time.FormatDuration(SubmittedToStarted)} " +
+                $"( < {Time.FormatDuration(Purchase.Expiry + gracePeriod)})");
+        }
+
+        private void LogFinishedDuration()
+        {
+            Log($"Submitted to Finished in {Time.FormatDuration(SubmittedToFinished)} " +
+                $"( < {Time.FormatDuration(Purchase.Duration + gracePeriod)})");
+        }
+
+        private void AssertDuration(TimeSpan? span, TimeSpan max, string message)
+        {
+            if (span == null) throw new ArgumentNullException(nameof(MarketplaceAccess) + ": " + message + " (IsNull)");
+            if (span.Value.TotalDays >= max.TotalSeconds)
+            {
+                throw new Exception(nameof(MarketplaceAccess) + 
+                    $": Duration out of range. Max: {Time.FormatDuration(max)} but was: {Time.FormatDuration(span.Value)} " +
+                    message);
+            }
+        }
+
+        private void Log(string msg)
+        {
+            log.Log($"[{PurchaseId}] {msg}");
         }
     }
 }

Tests/CodexTests/BasicTests/MarketplaceTests.cs

@@ -92,7 +92,7 @@ namespace CodexTests.BasicTests
                 var blockRange = geth.ConvertTimeRangeToBlockRange(GetTestRunTimeRange());
                 var slotFilledEvents = contracts.GetSlotFilledEvents(blockRange);
 
-                Log($"SlotFilledEvents: {slotFilledEvents.Length} - NumSlots: {purchase.MinRequiredNumberOfNodes}");
+                Debug($"SlotFilledEvents: {slotFilledEvents.Length} - NumSlots: {purchase.MinRequiredNumberOfNodes}");
 
                 if (slotFilledEvents.Length != purchase.MinRequiredNumberOfNodes) throw new Exception();
             }, purchase.Expiry + TimeSpan.FromSeconds(10), TimeSpan.FromSeconds(5), "Checking SlotFilled events");