diff --git a/DistTestCore/BaseStarter.cs b/DistTestCore/BaseStarter.cs index 7d259e7..eb34449 100644 --- a/DistTestCore/BaseStarter.cs +++ b/DistTestCore/BaseStarter.cs @@ -1,4 +1,5 @@ using KubernetesWorkflow; +using Logging; namespace DistTestCore { diff --git a/DistTestCore/Configuration.cs b/DistTestCore/Configuration.cs index b0d1aff..6ce375f 100644 --- a/DistTestCore/Configuration.cs +++ b/DistTestCore/Configuration.cs @@ -21,7 +21,7 @@ namespace DistTestCore public Logging.LogConfig GetLogConfig() { - return new Logging.LogConfig("CodexTestLogs"); + return new Logging.LogConfig("CodexTestLogs", debugEnabled: true); } public string GetFileManagerFolder() diff --git a/DistTestCore/DistTest.cs b/DistTestCore/DistTest.cs index ca3f70b..b24bb5b 100644 --- a/DistTestCore/DistTest.cs +++ b/DistTestCore/DistTest.cs @@ -28,7 +28,7 @@ namespace DistTestCore { Stopwatch.Measure(fixtureLog, "Global setup", () => { - var wc = new WorkflowCreator(configuration.GetK8sConfiguration()); + var wc = new WorkflowCreator(fixtureLog, configuration.GetK8sConfiguration()); wc.CreateWorkflow().DeleteAllResources(); }); } diff --git a/DistTestCore/GethStarter.cs b/DistTestCore/GethStarter.cs index 61d0bce..d933eaa 100644 --- a/DistTestCore/GethStarter.cs +++ b/DistTestCore/GethStarter.cs @@ -33,7 +33,7 @@ namespace DistTestCore private void TransferInitialBalance(MarketplaceNetwork marketplaceNetwork, MarketplaceInitialConfig marketplaceConfig, GethCompanionNodeInfo[] companionNodes) { - var interaction = marketplaceNetwork.StartInteraction(); + var interaction = marketplaceNetwork.StartInteraction(lifecycle.Log); var tokenAddress = marketplaceNetwork.Marketplace.TokenAddress; foreach (var node in companionNodes) diff --git a/DistTestCore/Marketplace/CodexContractsStarter.cs b/DistTestCore/Marketplace/CodexContractsStarter.cs index cbb4862..cb2c414 100644 --- a/DistTestCore/Marketplace/CodexContractsStarter.cs +++ b/DistTestCore/Marketplace/CodexContractsStarter.cs @@ -34,7 +34,7 @@ namespace DistTestCore.Marketplace var marketplaceAddress = extractor.ExtractMarketplaceAddress(); var abi = extractor.ExtractMarketplaceAbi(); - var interaction = bootstrapNode.StartInteraction(); + var interaction = bootstrapNode.StartInteraction(lifecycle.Log); var tokenAddress = interaction.GetTokenAddress(marketplaceAddress); LogEnd("Contracts deployed."); diff --git a/DistTestCore/Marketplace/ContainerInfoExtractor.cs b/DistTestCore/Marketplace/ContainerInfoExtractor.cs index a2f4a96..e3b6144 100644 --- a/DistTestCore/Marketplace/ContainerInfoExtractor.cs +++ b/DistTestCore/Marketplace/ContainerInfoExtractor.cs @@ -1,7 +1,5 @@ -using IdentityModel.OidcClient; -using KubernetesWorkflow; +using KubernetesWorkflow; using Newtonsoft.Json; -using Newtonsoft.Json.Converters; using Newtonsoft.Json.Linq; using Utils; diff --git a/DistTestCore/Marketplace/GethBootstrapNodeInfo.cs b/DistTestCore/Marketplace/GethBootstrapNodeInfo.cs index bfc8440..0c19fbf 100644 --- a/DistTestCore/Marketplace/GethBootstrapNodeInfo.cs +++ b/DistTestCore/Marketplace/GethBootstrapNodeInfo.cs @@ -1,4 +1,5 @@ using KubernetesWorkflow; +using Logging; using NethereumWorkflow; namespace DistTestCore.Marketplace @@ -20,14 +21,14 @@ namespace DistTestCore.Marketplace public string PrivateKey { get; } public Port DiscoveryPort { get; } - public NethereumInteraction StartInteraction() + public NethereumInteraction StartInteraction(BaseLog log) { var ip = RunningContainers.RunningPod.Cluster.IP; var port = RunningContainers.Containers[0].ServicePorts[0].Number; var account = Account; var privateKey = PrivateKey; - var creator = new NethereumInteractionCreator(ip, port, account, privateKey); + var creator = new NethereumInteractionCreator(log, ip, port, account, privateKey); return creator.CreateWorkflow(); } } diff --git a/DistTestCore/Marketplace/GethCompanionNodeInfo.cs b/DistTestCore/Marketplace/GethCompanionNodeInfo.cs index 6fbcd2b..df806e7 100644 --- a/DistTestCore/Marketplace/GethCompanionNodeInfo.cs +++ b/DistTestCore/Marketplace/GethCompanionNodeInfo.cs @@ -1,4 +1,5 @@ using KubernetesWorkflow; +using Logging; using NethereumWorkflow; namespace DistTestCore.Marketplace @@ -16,14 +17,14 @@ namespace DistTestCore.Marketplace public string Account { get; } public string PrivateKey { get; } - public NethereumInteraction StartInteraction() + public NethereumInteraction StartInteraction(BaseLog log) { var ip = RunningContainer.Pod.Cluster.IP; var port = RunningContainer.ServicePorts[0].Number; var account = Account; var privateKey = PrivateKey; - var creator = new NethereumInteractionCreator(ip, port, account, privateKey); + var creator = new NethereumInteractionCreator(log, ip, port, account, privateKey); return creator.CreateWorkflow(); } } diff --git a/DistTestCore/Marketplace/GethCompanionNodeStarter.cs b/DistTestCore/Marketplace/GethCompanionNodeStarter.cs index 133bdac..ad61a9d 100644 --- a/DistTestCore/Marketplace/GethCompanionNodeStarter.cs +++ b/DistTestCore/Marketplace/GethCompanionNodeStarter.cs @@ -43,7 +43,7 @@ namespace DistTestCore.Marketplace { try { - var interaction = node.StartInteraction(); + var interaction = node.StartInteraction(lifecycle.Log); interaction.EnsureSynced(marketplace.Marketplace.Address, marketplace.Marketplace.Abi); } catch (Exception e) diff --git a/DistTestCore/Marketplace/MarketplaceAccess.cs b/DistTestCore/Marketplace/MarketplaceAccess.cs index 42ea1f4..e77635e 100644 --- a/DistTestCore/Marketplace/MarketplaceAccess.cs +++ b/DistTestCore/Marketplace/MarketplaceAccess.cs @@ -103,7 +103,7 @@ namespace DistTestCore.Marketplace public TestToken GetBalance() { - var interaction = marketplaceNetwork.StartInteraction(); + var interaction = marketplaceNetwork.StartInteraction(log); var account = companionNode.Account; var amount = interaction.GetBalance(marketplaceNetwork.Marketplace.TokenAddress, account); var balance = new TestToken(amount); diff --git a/DistTestCore/Marketplace/MarketplaceNetwork.cs b/DistTestCore/Marketplace/MarketplaceNetwork.cs index edd3fa3..8378444 100644 --- a/DistTestCore/Marketplace/MarketplaceNetwork.cs +++ b/DistTestCore/Marketplace/MarketplaceNetwork.cs @@ -1,4 +1,5 @@ -using NethereumWorkflow; +using Logging; +using NethereumWorkflow; namespace DistTestCore.Marketplace { @@ -13,9 +14,9 @@ namespace DistTestCore.Marketplace public GethBootstrapNodeInfo Bootstrap { get; } public MarketplaceInfo Marketplace { get; } - public NethereumInteraction StartInteraction() + public NethereumInteraction StartInteraction(BaseLog log) { - return Bootstrap.StartInteraction(); + return Bootstrap.StartInteraction(log); } } } diff --git a/DistTestCore/Stopwatch.cs b/DistTestCore/Stopwatch.cs deleted file mode 100644 index 878912f..0000000 --- a/DistTestCore/Stopwatch.cs +++ /dev/null @@ -1,36 +0,0 @@ -using Logging; -using Utils; - -namespace DistTestCore -{ - public class Stopwatch - { - private readonly DateTime start = DateTime.UtcNow; - private readonly BaseLog log; - private readonly string name; - - public Stopwatch(BaseLog log, string name) - { - this.log = log; - this.name = name; - } - - public static void Measure(BaseLog log, string name, Action action) - { - var sw = Begin(log, name); - action(); - sw.End(); - } - - public static Stopwatch Begin(BaseLog log, string name) - { - return new Stopwatch(log, name); - } - - public void End(string msg = "") - { - var duration = DateTime.UtcNow - start; - log.Log($"{name} {msg} ({Time.FormatDuration(duration)})"); - } - } -} diff --git a/DistTestCore/TestLifecycle.cs b/DistTestCore/TestLifecycle.cs index 2b243e1..4dddf34 100644 --- a/DistTestCore/TestLifecycle.cs +++ b/DistTestCore/TestLifecycle.cs @@ -11,7 +11,7 @@ namespace DistTestCore public TestLifecycle(TestLog log, Configuration configuration) { Log = log; - workflowCreator = new WorkflowCreator(configuration.GetK8sConfiguration()); + workflowCreator = new WorkflowCreator(log, configuration.GetK8sConfiguration()); FileManager = new FileManager(Log, configuration); CodexStarter = new CodexStarter(this, workflowCreator); diff --git a/KubernetesWorkflow/K8sController.cs b/KubernetesWorkflow/K8sController.cs index 611c8fe..21e8266 100644 --- a/KubernetesWorkflow/K8sController.cs +++ b/KubernetesWorkflow/K8sController.cs @@ -1,18 +1,21 @@ using k8s; using k8s.Models; +using Logging; using Utils; namespace KubernetesWorkflow { public class K8sController { + private readonly BaseLog log; private readonly K8sCluster cluster; private readonly KnownK8sPods knownPods; private readonly WorkflowNumberSource workflowNumberSource; private readonly Kubernetes client; - public K8sController(K8sCluster cluster, KnownK8sPods knownPods, WorkflowNumberSource workflowNumberSource) + public K8sController(BaseLog log, K8sCluster cluster, KnownK8sPods knownPods, WorkflowNumberSource workflowNumberSource) { + this.log = log; this.cluster = cluster; this.knownPods = knownPods; this.workflowNumberSource = workflowNumberSource; @@ -27,6 +30,7 @@ namespace KubernetesWorkflow public RunningPod BringOnline(ContainerRecipe[] containerRecipes, Location location) { + log.Debug(); EnsureTestNamespace(); var deploymentName = CreateDeployment(containerRecipes, location); @@ -38,6 +42,7 @@ namespace KubernetesWorkflow public void Stop(RunningPod pod) { + log.Debug(); if (!string.IsNullOrEmpty(pod.ServiceName)) DeleteService(pod.ServiceName); DeleteDeployment(pod.DeploymentName); WaitUntilDeploymentOffline(pod.DeploymentName); @@ -46,12 +51,14 @@ namespace KubernetesWorkflow public void DownloadPodLog(RunningPod pod, ContainerRecipe recipe, ILogHandler logHandler) { + log.Debug(); using var stream = client.ReadNamespacedPodLog(pod.Name, K8sNamespace, recipe.Name); logHandler.Log(stream); } public string ExecuteCommand(RunningPod pod, string containerName, string command, params string[] args) { + log.Debug($"{containerName}: {command} ({string.Join(",", args)})"); var runner = new CommandRunner(client, K8sNamespace, pod, containerName, command, args); runner.Run(); return runner.GetStdOut(); @@ -59,6 +66,7 @@ namespace KubernetesWorkflow public void DeleteAllResources() { + log.Debug(); DeleteNamespace(); WaitUntilNamespaceDeleted(); @@ -346,7 +354,15 @@ namespace KubernetesWorkflow private void WaitUntil(Func predicate) { - Time.WaitUntil(predicate, cluster.K8sOperationTimeout(), cluster.WaitForK8sServiceDelay()); + var sw = Stopwatch.Begin(log, true); + try + { + Time.WaitUntil(predicate, cluster.K8sOperationTimeout(), cluster.WaitForK8sServiceDelay()); + } + finally + { + sw.End("", 1); + } } #endregion diff --git a/KubernetesWorkflow/KubernetesWorkflow.csproj b/KubernetesWorkflow/KubernetesWorkflow.csproj index 655a8fd..dbfbf96 100644 --- a/KubernetesWorkflow/KubernetesWorkflow.csproj +++ b/KubernetesWorkflow/KubernetesWorkflow.csproj @@ -12,6 +12,7 @@ + diff --git a/KubernetesWorkflow/StartupWorkflow.cs b/KubernetesWorkflow/StartupWorkflow.cs index d37699f..38eb161 100644 --- a/KubernetesWorkflow/StartupWorkflow.cs +++ b/KubernetesWorkflow/StartupWorkflow.cs @@ -1,16 +1,18 @@ -using System.IO; +using Logging; namespace KubernetesWorkflow { public class StartupWorkflow { + private readonly BaseLog log; private readonly WorkflowNumberSource numberSource; private readonly K8sCluster cluster; private readonly KnownK8sPods knownK8SPods; private readonly RecipeComponentFactory componentFactory = new RecipeComponentFactory(); - internal StartupWorkflow(WorkflowNumberSource numberSource, K8sCluster cluster, KnownK8sPods knownK8SPods) + internal StartupWorkflow(BaseLog log, WorkflowNumberSource numberSource, K8sCluster cluster, KnownK8sPods knownK8SPods) { + this.log = log; this.numberSource = numberSource; this.cluster = cluster; this.knownK8SPods = knownK8SPods; @@ -60,13 +62,15 @@ namespace KubernetesWorkflow }); } - private static RunningContainer[] CreateContainers(RunningPod runningPod, ContainerRecipe[] recipes) + private RunningContainer[] CreateContainers(RunningPod runningPod, ContainerRecipe[] recipes) { + log.Debug(); return recipes.Select(r => new RunningContainer(runningPod, r, runningPod.GetServicePortsForContainerRecipe(r))).ToArray(); } private ContainerRecipe[] CreateRecipes(int numberOfContainers, ContainerRecipeFactory recipeFactory, StartupConfig startupConfig) { + log.Debug(); var result = new List(); for (var i = 0; i < numberOfContainers; i++) { @@ -78,14 +82,14 @@ namespace KubernetesWorkflow private void K8s(Action action) { - var controller = new K8sController(cluster, knownK8SPods, numberSource); + var controller = new K8sController(log, cluster, knownK8SPods, numberSource); action(controller); controller.Dispose(); } private T K8s(Func action) { - var controller = new K8sController(cluster, knownK8SPods, numberSource); + var controller = new K8sController(log, cluster, knownK8SPods, numberSource); var result = action(controller); controller.Dispose(); return result; diff --git a/KubernetesWorkflow/WorkflowCreator.cs b/KubernetesWorkflow/WorkflowCreator.cs index 51c1c29..1f54bea 100644 --- a/KubernetesWorkflow/WorkflowCreator.cs +++ b/KubernetesWorkflow/WorkflowCreator.cs @@ -1,4 +1,5 @@ -using Utils; +using Logging; +using Utils; namespace KubernetesWorkflow { @@ -9,10 +10,12 @@ namespace KubernetesWorkflow private readonly NumberSource containerNumberSource = new NumberSource(0); private readonly KnownK8sPods knownPods = new KnownK8sPods(); private readonly K8sCluster cluster; + private readonly BaseLog log; - public WorkflowCreator(Configuration configuration) + public WorkflowCreator(BaseLog log, Configuration configuration) { cluster = new K8sCluster(configuration); + this.log = log; } public StartupWorkflow CreateWorkflow() @@ -21,7 +24,7 @@ namespace KubernetesWorkflow servicePortNumberSource, containerNumberSource); - return new StartupWorkflow(workflowNumberSource, cluster, knownPods); + return new StartupWorkflow(log, workflowNumberSource, cluster, knownPods); } } } diff --git a/Logging/BaseLog.cs b/Logging/BaseLog.cs index e19ec12..adcfb2b 100644 --- a/Logging/BaseLog.cs +++ b/Logging/BaseLog.cs @@ -1,10 +1,19 @@ -namespace Logging +using System.Diagnostics; +using Utils; + +namespace Logging { public abstract class BaseLog { private bool hasFailed; private LogFile? logFile; - + private readonly bool debug; + + protected BaseLog(bool debug) + { + this.debug = debug; + } + protected abstract LogFile CreateLogFile(); protected LogFile LogFile @@ -21,6 +30,15 @@ LogFile.Write(message); } + public void Debug(string message = "", int skipFrames = 0) + { + if (debug) + { + var callerName = DebugStack.GetCallerName(skipFrames); + Log($"(debug)({callerName}) {message}"); + } + } + public void Error(string message) { Log($"[ERROR] {message}"); diff --git a/Logging/FixtureLog.cs b/Logging/FixtureLog.cs index 7bb80ab..1502ec9 100644 --- a/Logging/FixtureLog.cs +++ b/Logging/FixtureLog.cs @@ -6,18 +6,21 @@ namespace Logging { private readonly DateTime start; private readonly string fullName; + private readonly LogConfig config; public FixtureLog(LogConfig config) + : base(config.DebugEnabled) { start = DateTime.UtcNow; var folder = DetermineFolder(config); var fixtureName = GetFixtureName(); fullName = Path.Combine(folder, fixtureName); + this.config = config; } public TestLog CreateTestLog() { - return new TestLog(fullName); + return new TestLog(fullName, config.DebugEnabled); } protected override LogFile CreateLogFile() diff --git a/Logging/LogConfig.cs b/Logging/LogConfig.cs index b7bc937..eb91fdb 100644 --- a/Logging/LogConfig.cs +++ b/Logging/LogConfig.cs @@ -2,11 +2,13 @@ { public class LogConfig { - public LogConfig(string logRoot) + public LogConfig(string logRoot, bool debugEnabled) { LogRoot = logRoot; + DebugEnabled = debugEnabled; } public string LogRoot { get; } + public bool DebugEnabled { get; } } } diff --git a/Logging/Stopwatch.cs b/Logging/Stopwatch.cs new file mode 100644 index 0000000..9f8a346 --- /dev/null +++ b/Logging/Stopwatch.cs @@ -0,0 +1,61 @@ +using Utils; + +namespace Logging +{ + public class Stopwatch + { + private readonly DateTime start = DateTime.UtcNow; + private readonly BaseLog log; + private readonly string name; + private readonly bool debug; + + private Stopwatch(BaseLog log, string name, bool debug) + { + this.log = log; + this.name = name; + this.debug = debug; + } + + public static void Measure(BaseLog log, string name, Action action, bool debug = false) + { + var sw = Begin(log, name, debug); + action(); + sw.End(); + } + + public static Stopwatch Begin(BaseLog log) + { + return Begin(log, ""); + } + + public static Stopwatch Begin(BaseLog log, string name) + { + return Begin(log, name, false); + } + + public static Stopwatch Begin(BaseLog log, bool debug) + { + return Begin(log, "", debug); + } + + public static Stopwatch Begin(BaseLog log, string name, bool debug) + { + return new Stopwatch(log, name, debug); + } + + public void End(string msg = "", int skipFrames = 0) + { + var duration = DateTime.UtcNow - start; + var entry = $"{name} {msg} ({Time.FormatDuration(duration)})"; + + if (debug) + { + log.Debug(entry, 1 + skipFrames); + } + else + { + log.Log(entry); + } + } + } +} diff --git a/Logging/TestLog.cs b/Logging/TestLog.cs index 066d84a..39f70a0 100644 --- a/Logging/TestLog.cs +++ b/Logging/TestLog.cs @@ -9,7 +9,8 @@ namespace Logging private readonly string methodName; private readonly string fullName; - public TestLog(string folder) + public TestLog(string folder, bool debug) + : base(debug) { methodName = GetMethodName(); fullName = Path.Combine(folder, methodName); diff --git a/Nethereum/NethereumInteraction.cs b/Nethereum/NethereumInteraction.cs index ba550b8..0ab3b5a 100644 --- a/Nethereum/NethereumInteraction.cs +++ b/Nethereum/NethereumInteraction.cs @@ -1,4 +1,5 @@ -using Nethereum.ABI.FunctionEncoding.Attributes; +using Logging; +using Nethereum.ABI.FunctionEncoding.Attributes; using Nethereum.Contracts; using Nethereum.Hex.HexTypes; using Nethereum.Web3; @@ -10,17 +11,20 @@ namespace NethereumWorkflow public class NethereumInteraction { private readonly List openTasks = new List(); + private readonly BaseLog log; private readonly Web3 web3; private readonly string rootAccount; - internal NethereumInteraction(Web3 web3, string rootAccount) + internal NethereumInteraction(BaseLog log, Web3 web3, string rootAccount) { + this.log = log; this.web3 = web3; this.rootAccount = rootAccount; } public string GetTokenAddress(string marketplaceAddress) { + log.Debug(marketplaceAddress); var function = new GetTokenFunction(); var handler = web3.Eth.GetContractQueryHandler(); @@ -29,6 +33,7 @@ namespace NethereumWorkflow public void TransferWeiTo(string account, decimal amount) { + log.Debug($"{amount} --> {account}"); if (amount < 1 || string.IsNullOrEmpty(account)) throw new ArgumentException("Invalid arguments for AddToBalance"); var value = ToHexBig(amount); @@ -38,6 +43,7 @@ namespace NethereumWorkflow public void MintTestTokens(string account, decimal amount, string tokenAddress) { + log.Debug($"({tokenAddress}) {amount} --> {account}"); if (amount < 1 || string.IsNullOrEmpty(account)) throw new ArgumentException("Invalid arguments for MintTestTokens"); var function = new MintTokensFunction @@ -52,6 +58,7 @@ namespace NethereumWorkflow public decimal GetBalance(string tokenAddress, string account) { + log.Debug($"({tokenAddress}) {account}"); var function = new GetTokenBalanceFunction { Owner = account @@ -77,6 +84,7 @@ namespace NethereumWorkflow private void WaitUntilSynced() { + log.Debug(); Time.WaitUntil(() => { var sync = Time.Wait(web3.Eth.Syncing.SendRequestAsync()); @@ -89,6 +97,7 @@ namespace NethereumWorkflow private void WaitForContract(string marketplaceAddress, string marketplaceAbi) { + log.Debug(); Time.WaitUntil(() => { try diff --git a/Nethereum/NethereumInteractionCreator.cs b/Nethereum/NethereumInteractionCreator.cs index 654a0bd..ff7e9fd 100644 --- a/Nethereum/NethereumInteractionCreator.cs +++ b/Nethereum/NethereumInteractionCreator.cs @@ -1,16 +1,19 @@ -using Nethereum.Web3; +using Logging; +using Nethereum.Web3; namespace NethereumWorkflow { public class NethereumInteractionCreator { + private readonly BaseLog log; private readonly string ip; private readonly int port; private readonly string rootAccount; private readonly string privateKey; - public NethereumInteractionCreator(string ip, int port, string rootAccount, string privateKey) + public NethereumInteractionCreator(BaseLog log, string ip, int port, string rootAccount, string privateKey) { + this.log = log; this.ip = ip; this.port = port; this.rootAccount = rootAccount; @@ -19,7 +22,7 @@ namespace NethereumWorkflow public NethereumInteraction CreateWorkflow() { - return new NethereumInteraction(CreateWeb3(), rootAccount); + return new NethereumInteraction(log, CreateWeb3(), rootAccount); } private Web3 CreateWeb3() diff --git a/Utils/DebugStack.cs b/Utils/DebugStack.cs new file mode 100644 index 0000000..d10a378 --- /dev/null +++ b/Utils/DebugStack.cs @@ -0,0 +1,12 @@ +using System.Diagnostics; + +namespace Utils +{ + public class DebugStack + { + public static string GetCallerName(int skipFrames = 0) + { + return new StackFrame(2 + skipFrames, true).GetMethod()!.Name; + } + } +}