Adds debug logging support

DistTestCore/BaseStarter.cs

@@ -1,4 +1,5 @@
 using KubernetesWorkflow;
+using Logging;
 
 namespace DistTestCore
 {

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()

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

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)

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.");

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;
 

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

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

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)

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

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

DistTestCore/Stopwatch.cs

@@ -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)})");
-        }
-    }
-}

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

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<bool> 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

KubernetesWorkflow/KubernetesWorkflow.csproj

@@ -12,6 +12,7 @@
   </ItemGroup>
 
   <ItemGroup>
+    <ProjectReference Include="..\Logging\Logging.csproj" />
     <ProjectReference Include="..\Utils\Utils.csproj" />
   </ItemGroup>
 

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<ContainerRecipe>();
             for (var i = 0; i < numberOfContainers; i++)
             {
@@ -78,14 +82,14 @@ namespace KubernetesWorkflow
 
         private void K8s(Action<K8sController> action)
         {
-            var controller = new K8sController(cluster, knownK8SPods, numberSource);
+            var controller = new K8sController(log, cluster, knownK8SPods, numberSource);
             action(controller);
             controller.Dispose();
         }
 
         private T K8s<T>(Func<K8sController, T> action)
         {
-            var controller = new K8sController(cluster, knownK8SPods, numberSource);
+            var controller = new K8sController(log, cluster, knownK8SPods, numberSource);
             var result = action(controller);
             controller.Dispose();
             return result;

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

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

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()

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

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

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

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<Task> openTasks = new List<Task>();
+        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<GetTokenFunction>();
@@ -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

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()

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