From e9d84a5cf74dbf70b3cdb6825a9d2d76443589e9 Mon Sep 17 00:00:00 2001 From: benbierens Date: Wed, 19 Apr 2023 10:42:08 +0200 Subject: [PATCH] Better logging for json errors and node actions. --- DistTestCore/ByteSize.cs | 10 +++++++ DistTestCore/Codex/CodexAccess.cs | 1 - DistTestCore/DistTest.cs | 6 ++--- DistTestCore/Http.cs | 26 +++++++++++++++---- DistTestCore/Logs/CodexNodeLog.cs | 6 +++-- DistTestCore/Logs/LogDownloadHandler.cs | 6 +++-- DistTestCore/Marketplace/MarketplaceAccess.cs | 20 +++++++------- DistTestCore/Metrics/MetricsAccess.cs | 26 ++++++++++++------- DistTestCore/Metrics/MetricsAccessFactory.cs | 6 +++-- DistTestCore/OnlineCodexNode.cs | 2 +- DistTestCore/PrometheusStarter.cs | 2 +- DistTestCore/TestLifecycle.cs | 4 +-- DistTestCore/Tokens.cs | 25 ++++++++++++++++++ Logging/TestLog.cs | 4 +-- Tests/BasicTests/ExampleTests.cs | 4 +-- 15 files changed, 105 insertions(+), 43 deletions(-) diff --git a/DistTestCore/ByteSize.cs b/DistTestCore/ByteSize.cs index 2a41e94..dc288bc 100644 --- a/DistTestCore/ByteSize.cs +++ b/DistTestCore/ByteSize.cs @@ -9,6 +9,16 @@ public long SizeInBytes { get; } + public override bool Equals(object? obj) + { + return obj is ByteSize size && SizeInBytes == size.SizeInBytes; + } + + public override int GetHashCode() + { + return HashCode.Combine(SizeInBytes); + } + public override string ToString() { return $"{SizeInBytes} bytes"; diff --git a/DistTestCore/Codex/CodexAccess.cs b/DistTestCore/Codex/CodexAccess.cs index 00ac2f2..ae84a91 100644 --- a/DistTestCore/Codex/CodexAccess.cs +++ b/DistTestCore/Codex/CodexAccess.cs @@ -1,5 +1,4 @@ using KubernetesWorkflow; -using Newtonsoft.Json; namespace DistTestCore.Codex { diff --git a/DistTestCore/DistTest.cs b/DistTestCore/DistTest.cs index 972a539..ca3f70b 100644 --- a/DistTestCore/DistTest.cs +++ b/DistTestCore/DistTest.cs @@ -40,9 +40,9 @@ namespace DistTestCore } fixtureLog.Log("Global setup cleanup successful"); - fixtureLog.Log($"Codex image: {CodexContainerRecipe.DockerImage}"); - fixtureLog.Log($"Prometheus image: {PrometheusContainerRecipe.DockerImage}"); - fixtureLog.Log($"Geth image: {GethContainerRecipe.DockerImage}"); + fixtureLog.Log($"Codex image: '{CodexContainerRecipe.DockerImage}'"); + fixtureLog.Log($"Prometheus image: '{PrometheusContainerRecipe.DockerImage}'"); + fixtureLog.Log($"Geth image: '{GethContainerRecipe.DockerImage}'"); } [SetUp] diff --git a/DistTestCore/Http.cs b/DistTestCore/Http.cs index 0d242cf..62ccbfb 100644 --- a/DistTestCore/Http.cs +++ b/DistTestCore/Http.cs @@ -35,20 +35,22 @@ namespace DistTestCore public T HttpGetJson(string route) { - return JsonConvert.DeserializeObject(HttpGetString(route))!; + var json = HttpGetString(route); + return TryJsonDeserialize(json); } public TResponse HttpPostJson(string route, TRequest body) { - return Retry(() => + var json = Retry(() => { using var client = GetClient(); var url = GetUrl() + route; using var content = JsonContent.Create(body); var result = Time.Wait(client.PostAsync(url, content)); - var json = Time.Wait(result.Content.ReadAsStringAsync()); - return JsonConvert.DeserializeObject(json)!; + return Time.Wait(result.Content.ReadAsStringAsync()); }); + + return TryJsonDeserialize(json); } public string HttpPostStream(string route, Stream stream) @@ -98,13 +100,27 @@ namespace DistTestCore retryCounter++; if (retryCounter > Timing.HttpCallRetryCount()) { - Assert.Fail(exception.Message); + Assert.Fail(exception.ToString()); throw; } } } } + private static T TryJsonDeserialize(string json) + { + try + { + return JsonConvert.DeserializeObject(json)!; + } + catch (Exception exception) + { + var msg = $"Failed to deserialize JSON: '{json}' with exception: {exception}"; + Assert.Fail(msg); + throw new InvalidOperationException(msg, exception); + } + } + private static HttpClient GetClient() { var client = new HttpClient(); diff --git a/DistTestCore/Logs/CodexNodeLog.cs b/DistTestCore/Logs/CodexNodeLog.cs index 3b65241..6dd658f 100644 --- a/DistTestCore/Logs/CodexNodeLog.cs +++ b/DistTestCore/Logs/CodexNodeLog.cs @@ -11,10 +11,12 @@ namespace DistTestCore.Logs public class CodexNodeLog : ICodexNodeLog { private readonly LogFile logFile; + private readonly OnlineCodexNode owner; - public CodexNodeLog(LogFile logFile) + public CodexNodeLog(LogFile logFile, OnlineCodexNode owner) { this.logFile = logFile; + this.owner = owner; } public void AssertLogContains(string expectedString) @@ -29,7 +31,7 @@ namespace DistTestCore.Logs line = streamReader.ReadLine(); } - Assert.Fail($"Unable to find string '{expectedString}' in CodexNode log file {logFile.FullFilename}"); + Assert.Fail($"{owner.GetName()} Unable to find string '{expectedString}' in CodexNode log file {logFile.FullFilename}"); } } } diff --git a/DistTestCore/Logs/LogDownloadHandler.cs b/DistTestCore/Logs/LogDownloadHandler.cs index 9cc1012..2c7dc9f 100644 --- a/DistTestCore/Logs/LogDownloadHandler.cs +++ b/DistTestCore/Logs/LogDownloadHandler.cs @@ -5,10 +5,12 @@ namespace DistTestCore.Logs { public class LogDownloadHandler : LogHandler, ILogHandler { + private readonly OnlineCodexNode node; private readonly LogFile log; - public LogDownloadHandler(string description, LogFile log) + public LogDownloadHandler(OnlineCodexNode node, string description, LogFile log) { + this.node = node; this.log = log; log.Write($"{description} -->> {log.FullFilename}"); @@ -17,7 +19,7 @@ namespace DistTestCore.Logs public CodexNodeLog CreateCodexNodeLog() { - return new CodexNodeLog(log); + return new CodexNodeLog(log, node); } protected override void ProcessLine(string line) diff --git a/DistTestCore/Marketplace/MarketplaceAccess.cs b/DistTestCore/Marketplace/MarketplaceAccess.cs index 713081e..881ce93 100644 --- a/DistTestCore/Marketplace/MarketplaceAccess.cs +++ b/DistTestCore/Marketplace/MarketplaceAccess.cs @@ -44,10 +44,10 @@ namespace DistTestCore.Marketplace }; Log($"Requesting storage for: {contentId.Id}... (" + - $"pricePerBytePerSecond: {pricePerBytePerSecond}," + - $"requiredCollateral: {requiredCollateral}," + - $"minRequiredNumberOfNodes: {minRequiredNumberOfNodes}," + - $"proofProbability: {proofProbability}," + + $"pricePerBytePerSecond: {pricePerBytePerSecond}, " + + $"requiredCollateral: {requiredCollateral}, " + + $"minRequiredNumberOfNodes: {minRequiredNumberOfNodes}, " + + $"proofProbability: {proofProbability}, " + $"duration: {Time.FormatDuration(duration)})"); var response = codexAccess.RequestStorage(request, contentId.Id); @@ -68,10 +68,10 @@ namespace DistTestCore.Marketplace }; Log($"Making storage available... (" + - $"size: {size}," + - $"minPricePerBytePerSecond: {minPricePerBytePerSecond}," + - $"maxCollateral: {maxCollateral}," + - $"maxDuration: {Time.FormatDuration(maxDuration)}"); + $"size: {size}, " + + $"minPricePerBytePerSecond: {minPricePerBytePerSecond}, " + + $"maxCollateral: {maxCollateral}, " + + $"maxDuration: {Time.FormatDuration(maxDuration)})"); var response = codexAccess.SalesAvailability(request); @@ -103,14 +103,14 @@ namespace DistTestCore.Marketplace var amount = interaction.GetBalance(marketplaceNetwork.Marketplace.TokenAddress, account); var balance = new TestToken(amount); - Log($"Balance of {codexAccess.Container.GetName()}({account}) is {balance}."); + Log($"Balance of {account} is {balance}."); return balance; } private void Log(string msg) { - log.Log(msg); + log.Log($"{codexAccess.Container.GetName()} {msg}"); } } diff --git a/DistTestCore/Metrics/MetricsAccess.cs b/DistTestCore/Metrics/MetricsAccess.cs index e5bd2b3..fffaea8 100644 --- a/DistTestCore/Metrics/MetricsAccess.cs +++ b/DistTestCore/Metrics/MetricsAccess.cs @@ -1,4 +1,5 @@ using KubernetesWorkflow; +using Logging; using NUnit.Framework; using NUnit.Framework.Constraints; using Utils; @@ -10,22 +11,15 @@ namespace DistTestCore.Metrics void AssertThat(string metricName, IResolveConstraint constraint, string message = ""); } - public class MetricsUnavailable : IMetricsAccess - { - public void AssertThat(string metricName, IResolveConstraint constraint, string message = "") - { - Assert.Fail("Incorrect test setup: Metrics were not enabled for this group of Codex nodes. Add 'EnableMetrics()' after 'SetupCodexNodes()' to enable it."); - throw new InvalidOperationException(); - } - } - public class MetricsAccess : IMetricsAccess { + private readonly TestLog log; private readonly MetricsQuery query; private readonly RunningContainer node; - public MetricsAccess(MetricsQuery query, RunningContainer node) + public MetricsAccess(TestLog log, MetricsQuery query, RunningContainer node) { + this.log = log; this.query = query; this.node = node; } @@ -34,6 +28,9 @@ namespace DistTestCore.Metrics { var metricSet = GetMetricWithTimeout(metricName); var metricValue = metricSet.Values[0].Value; + + log.Log($"{node.GetName()} metric '{metricName}' = {metricValue}"); + Assert.That(metricValue, constraint, message); } @@ -67,4 +64,13 @@ namespace DistTestCore.Metrics return result.Sets.LastOrDefault(); } } + + public class MetricsUnavailable : IMetricsAccess + { + public void AssertThat(string metricName, IResolveConstraint constraint, string message = "") + { + Assert.Fail("Incorrect test setup: Metrics were not enabled for this group of Codex nodes. Add 'EnableMetrics()' after 'SetupCodexNodes()' to enable it."); + throw new InvalidOperationException(); + } + } } diff --git a/DistTestCore/Metrics/MetricsAccessFactory.cs b/DistTestCore/Metrics/MetricsAccessFactory.cs index fcf5dfb..dad95b8 100644 --- a/DistTestCore/Metrics/MetricsAccessFactory.cs +++ b/DistTestCore/Metrics/MetricsAccessFactory.cs @@ -17,17 +17,19 @@ namespace DistTestCore.Metrics public class CodexNodeMetricsAccessFactory : IMetricsAccessFactory { + private readonly TestLifecycle lifecycle; private readonly RunningContainers prometheusContainer; - public CodexNodeMetricsAccessFactory(RunningContainers prometheusContainer) + public CodexNodeMetricsAccessFactory(TestLifecycle lifecycle, RunningContainers prometheusContainer) { + this.lifecycle = lifecycle; this.prometheusContainer = prometheusContainer; } public IMetricsAccess CreateMetricsAccess(RunningContainer codexContainer) { var query = new MetricsQuery(prometheusContainer); - return new MetricsAccess(query, codexContainer); + return new MetricsAccess(lifecycle.Log, query, codexContainer); } } } diff --git a/DistTestCore/OnlineCodexNode.cs b/DistTestCore/OnlineCodexNode.cs index bf0dfdf..a0d7542 100644 --- a/DistTestCore/OnlineCodexNode.cs +++ b/DistTestCore/OnlineCodexNode.cs @@ -91,7 +91,7 @@ namespace DistTestCore public string Describe() { - return $"({Group.Describe()} contains {GetName()})"; + return $"({GetName()} in {Group.Describe()})"; } private string GetPeerMultiAddress(OnlineCodexNode peer, CodexDebugResponse peerInfo) diff --git a/DistTestCore/PrometheusStarter.cs b/DistTestCore/PrometheusStarter.cs index 936c876..eb66efc 100644 --- a/DistTestCore/PrometheusStarter.cs +++ b/DistTestCore/PrometheusStarter.cs @@ -26,7 +26,7 @@ namespace DistTestCore LogEnd("Metrics server started."); - return new CodexNodeMetricsAccessFactory(runningContainers); + return new CodexNodeMetricsAccessFactory(lifecycle, runningContainers); } private string GeneratePrometheusConfig(RunningContainer[] nodes) diff --git a/DistTestCore/TestLifecycle.cs b/DistTestCore/TestLifecycle.cs index 2257610..3158f4e 100644 --- a/DistTestCore/TestLifecycle.cs +++ b/DistTestCore/TestLifecycle.cs @@ -35,12 +35,12 @@ namespace DistTestCore { var subFile = Log.CreateSubfile(); var description = node.Describe(); - var handler = new LogDownloadHandler(description, subFile); + var handler = new LogDownloadHandler(node, description, subFile); Log.Log($"Downloading logs for {description} to file '{subFile.FullFilename}'"); CodexStarter.DownloadLog(node.CodexAccess.Container, handler); - return new CodexNodeLog(subFile); + return new CodexNodeLog(subFile, node); } } } diff --git a/DistTestCore/Tokens.cs b/DistTestCore/Tokens.cs index 3f92852..07d1692 100644 --- a/DistTestCore/Tokens.cs +++ b/DistTestCore/Tokens.cs @@ -8,6 +8,21 @@ } public decimal Wei { get; } + + public override bool Equals(object? obj) + { + return obj is Ether ether && Wei == ether.Wei; + } + + public override int GetHashCode() + { + return HashCode.Combine(Wei); + } + + public override string ToString() + { + return $"{Wei} Wei"; + } } public class TestToken @@ -19,6 +34,16 @@ public decimal Amount { get; } + public override bool Equals(object? obj) + { + return obj is TestToken token && Amount == token.Amount; + } + + public override int GetHashCode() + { + return HashCode.Combine(Amount); + } + public override string ToString() { return $"{Amount} TestTokens"; diff --git a/Logging/TestLog.cs b/Logging/TestLog.cs index 8c4dc17..066d84a 100644 --- a/Logging/TestLog.cs +++ b/Logging/TestLog.cs @@ -14,7 +14,7 @@ namespace Logging methodName = GetMethodName(); fullName = Path.Combine(folder, methodName); - Log($"Begin: {methodName}"); + Log($"*** Begin: {methodName}"); } public LogFile CreateSubfile(string ext = "log") @@ -26,7 +26,7 @@ namespace Logging { var result = TestContext.CurrentContext.Result; - Log($"Finished: {methodName} = {result.Outcome.Status}"); + Log($"*** Finished: {methodName} = {result.Outcome.Status}"); if (!string.IsNullOrEmpty(result.Message)) { Log(result.Message); diff --git a/Tests/BasicTests/ExampleTests.cs b/Tests/BasicTests/ExampleTests.cs index 9c43ab1..dc86bfa 100644 --- a/Tests/BasicTests/ExampleTests.cs +++ b/Tests/BasicTests/ExampleTests.cs @@ -41,7 +41,7 @@ namespace Tests.BasicTests primary.ConnectToPeer(secondary); primary2.ConnectToPeer(secondary2); - Thread.Sleep(TimeSpan.FromMinutes(5)); + Thread.Sleep(TimeSpan.FromMinutes(2)); primary.Metrics.AssertThat("libp2p_peers", Is.EqualTo(1)); primary2.Metrics.AssertThat("libp2p_peers", Is.EqualTo(1)); @@ -55,7 +55,7 @@ namespace Tests.BasicTests .EnableMarketplace(initialBalance: 234.TestTokens()) .BringOnline()[0]; - Assert.That(primary.Marketplace.GetBalance(), Is.EqualTo(234)); + primary.Marketplace.AssertThatBalance(Is.EqualTo(234.TestTokens())); var secondary = SetupCodexNodes(1) .EnableMarketplace(initialBalance: 1000.TestTokens())