diff --git a/Framework/NethereumWorkflow/BlockUtils/BlockTimeFinder.cs b/Framework/NethereumWorkflow/BlockUtils/BlockTimeFinder.cs index a8e67f4..d9a6ac2 100644 --- a/Framework/NethereumWorkflow/BlockUtils/BlockTimeFinder.cs +++ b/Framework/NethereumWorkflow/BlockUtils/BlockTimeFinder.cs @@ -46,7 +46,7 @@ namespace NethereumWorkflow.BlockUtils private ulong Log(Func 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})"); diff --git a/Framework/Utils/Time.cs b/Framework/Utils/Time.cs index 85cfb1a..10caaf4 100644 --- a/Framework/Utils/Time.cs +++ b/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 = ""; diff --git a/ProjectPlugins/CodexPlugin/MarketplaceAccess.cs b/ProjectPlugins/CodexPlugin/MarketplaceAccess.cs index 4f8ca1e..8944d95 100644 --- a/ProjectPlugins/CodexPlugin/MarketplaceAccess.cs +++ b/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}"); } } } diff --git a/Tests/CodexTests/BasicTests/MarketplaceTests.cs b/Tests/CodexTests/BasicTests/MarketplaceTests.cs index 6365d8b..7cff4aa 100644 --- a/Tests/CodexTests/BasicTests/MarketplaceTests.cs +++ b/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");