Merge pull request #83 from mchlkntrv/feature/visual-logs

Implement Structured Console Logging

Author: Burgyn

src/TeaPie.DotnetTool/LoggingSettings.cs

@@ -38,4 +38,9 @@ internal class LoggingSettings : CommandSettings
     [DefaultValue(false)]
     [Description("Runs command silently, without displaying any output. Default: false.")]
     public bool IsQuiet { get; init; }
+
+    [CommandOption("--tree-logging")]
+    [DefaultValue(false)]
+    [Description("Uses tree-structured console output for logs. Default: false.")]
+    public bool UseTreeLogging { get; init; }
 }

src/TeaPie.DotnetTool/TestCommand.cs

@@ -18,7 +18,7 @@ protected override ApplicationBuilder ConfigureApplication(Settings settings)
         appBuilder
             .WithPath(path)
             .WithTemporaryPath(settings.TemporaryPath ?? string.Empty)
-            .WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel, pathToRequestsLogFile)
+            .WithLogging(logLevel, pathToLogFile, settings.LogFileLogLevel, pathToRequestsLogFile, settings.UseTreeLogging)
             .WithEnvironment(settings.Environment ?? string.Empty)
             .WithEnvironmentFile(PathResolver.Resolve(settings.EnvironmentFilePath, string.Empty))
             .WithReportFile(PathResolver.Resolve(settings.ReportFilePath, string.Empty))

src/TeaPie/ApplicationBuilder.cs

@@ -35,6 +35,7 @@ public sealed class ApplicationBuilder
     private string _pathToRequestsLogFile = string.Empty;
 
     private bool _variablesCaching = true;
+    private bool _useTreeLogging = false;
 
     private Func<IServiceProvider, IPipelineStep[]> _pipelineBuildFunction = ApplicationStepsFactory.CreateDefaultPipelineSteps;
 
@@ -62,12 +63,14 @@ public ApplicationBuilder WithLogging(
         LogLevel minimumLevel,
         string pathToLogFile = "",
         LogLevel minimumLevelForLogFile = LogLevel.None,
-        string pathToRequestsLogFile = "")
+        string pathToRequestsLogFile = "",
+        bool useTreeLogging = false)
     {
         _minimumLogLevel = minimumLevel;
         _pathToLogFile = pathToLogFile;
         _minimumLevelForLogFile = minimumLevelForLogFile;
         _pathToRequestsLogFile = pathToRequestsLogFile;
+        _useTreeLogging = useTreeLogging;
         return this;
     }
 
@@ -163,7 +166,12 @@ private ApplicationContext GetApplicationContext(IServiceProvider provider)
     private void ConfigureServices()
         => _services.AddTeaPie(
             _isCollectionRun,
-            () => _services.ConfigureLogging(_minimumLogLevel, _pathToLogFile, _minimumLevelForLogFile, _pathToRequestsLogFile));
+            () => _services.ConfigureLogging(
+                _minimumLogLevel,
+                _pathToLogFile,
+                _minimumLevelForLogFile,
+                _pathToRequestsLogFile,
+                _useTreeLogging));
 
     private static TeaPie CreateUserContext(IServiceProvider provider, ApplicationContext applicationContext)
         => TeaPie.Create(

src/TeaPie/ApplicationStepsFactory.cs

@@ -1,4 +1,5 @@
 using TeaPie.Environments;
+using TeaPie.Logging.Tree;
 using TeaPie.Pipelines;
 using TeaPie.Reporting;
 using TeaPie.Scripts;
@@ -11,15 +12,31 @@ namespace TeaPie;
 internal static class ApplicationStepsFactory
 {
     public static IPipelineStep[] CreateDefaultPipelineSteps(IServiceProvider provider)
-        => [provider.GetStep<ResolvePathsStep>(),
+    {
+        IDisposable? initScope = null;
+
+        return [
+            new InlineStep((context, _) =>
+            {
+                initScope = context.Logger.BeginOuterTreeScope();
+                return Task.CompletedTask;
+            }),
+            provider.GetStep<ResolvePathsStep>(),
             provider.GetStep<ExploreStructureStep>(),
             provider.GetStep<TryLoadVariablesStep>(),
             provider.GetStep<InitializeEnvironmentsStep>(),
             provider.GetStep<InitializeApplicationStep>(),
+            new InlineStep((_, _) =>
+            {
+                initScope?.Dispose();
+                initScope = null;
+                return Task.CompletedTask;
+            }),
             provider.GetStep<GenerateStepsForTestCasesStep>(),
             provider.GetStep<ReportTestResultsSummaryStep>(),
             provider.GetStep<SaveVariablesStep>()
         ];
+    }
 
     public static IPipelineStep[] CreateStructureExplorationSteps(IServiceProvider provider)
         => [provider.GetStep<ResolvePathsStep>(),

src/TeaPie/Http/Auth/OAuth2/OAuth2Provider.cs

@@ -4,6 +4,7 @@
 using System.Text.Json.Serialization;
 using TeaPie.Http.Headers;
 using TeaPie.Variables;
+using TeaPie.Logging.Tree;
 
 namespace TeaPie.Http.Auth.OAuth2;
 
@@ -63,13 +64,16 @@ private async Task<string> GetTokenFromRequest()
     {
         ResolveParameters(out var requestContent, out var requestUri);
 
-        LogSendingRequest();
+        using (_logger.BeginTreeScope())
+        {
+            LogSendingRequest();
 
-        var result = await SendRequest(requestContent, requestUri);
+            var result = await SendRequest(requestContent, requestUri);
 
-        CacheToken(result);
+            CacheToken(result);
 
-        return result.AccessToken!;
+            return result.AccessToken!;
+        }
     }
 
     private void LogSendingRequest()

src/TeaPie/Http/ExecuteRequestStep.cs

@@ -2,6 +2,7 @@
 using Polly;
 using TeaPie.Http.Auth;
 using TeaPie.Http.Headers;
+using TeaPie.Logging.Tree;
 using TeaPie.Pipelines;
 using TeaPie.Testing;
 
@@ -53,6 +54,7 @@ private void InsertStepForScheduledTestsIfAny(ApplicationContext context)
         if (_testScheduler.HasScheduledTest())
         {
             _pipeline.InsertSteps(this, context.ServiceProvider.GetStep<ExecuteScheduledTestsStep>());
+
             context.Logger.LogDebug("Tests from test directives were scheduled for execution.");
         }
     }
@@ -67,11 +69,14 @@ private async Task<HttpResponseMessage> ExecuteRequest(
         ResolveAuthProvider(requestExecutionContext);
 
         var client = _clientFactory.CreateClient(nameof(ExecuteRequestStep));
-        var response = await ExecuteRequest(
-            requestExecutionContext, resiliencePipeline, request, client, context.Logger, cancellationToken);
+        using (context.Logger.BeginTreeScope())
+        {
+            var response = await ExecuteRequest(
+                requestExecutionContext, resiliencePipeline, request, client, context.Logger, cancellationToken);
 
-        _authProviderAccessor.SetCurrentProviderToDefault();
-        return response;
+            _authProviderAccessor.SetCurrentProviderToDefault();
+            return response;
+        }
     }
 
     private void ResolveAuthProvider(RequestExecutionContext requestExecutionContext)
@@ -106,9 +111,18 @@ private async Task<HttpResponseMessage> ExecuteRequest(
         return await resiliencePipeline.ExecuteAsync(async token =>
         {
             retryAttemptNumber = UpdateRetryAttemptNumber(logger, retryAttemptNumber);
-            var request = GetMessage(requestExecutionContext, originalMessage, content, ref messageUsed);
-            request.Options.Set(_contextKey, requestExecutionContext);
-            return await client.SendAsync(request, token);
+            var requestToSend = GetMessage(requestExecutionContext, originalMessage, content, ref messageUsed);
+            requestToSend.Options.Set(_contextKey, requestExecutionContext);
+
+            if (retryAttemptNumber > 0)
+            {
+                using (logger.BeginTreeScope())
+                {
+                    return await client.SendAsync(requestToSend, token);
+                }
+            }
+
+            return await client.SendAsync(requestToSend, token);
         }, cancellationToken);
     }
 

src/TeaPie/Http/ParseHttpRequestStep.cs

@@ -1,6 +1,7 @@
 using Microsoft.Extensions.Logging;
 using TeaPie.Http.Parsing;
 using TeaPie.Logging;
+using TeaPie.Logging.Tree;
 using TeaPie.Pipelines;
 using Timer = TeaPie.Logging.Timer;
 
@@ -26,11 +27,14 @@ public async Task Execute(ApplicationContext context, CancellationToken cancella
 
     private void Parse(ApplicationContext context, RequestExecutionContext requestExecutionContext)
     {
-        LogParsingStart(context, requestExecutionContext);
-
-        Timer.Execute(
-            () => _parser.Parse(requestExecutionContext),
-            elapsedTime => LogEndOfParsing(context, requestExecutionContext, elapsedTime));
+        using (context.Logger.BeginTreeScope())
+        {
+            LogParsingStart(context, requestExecutionContext);
+
+            Timer.Execute(
+                () => _parser.Parse(requestExecutionContext),
+                elapsedTime => LogEndOfParsing(context, requestExecutionContext, elapsedTime));
+        }
     }
 
     private static void LogParsingStart(ApplicationContext context, RequestExecutionContext requestExecutionContext)

src/TeaPie/Http/Retrying/ResiliencePipelineProvider.cs

@@ -233,7 +233,7 @@ private void LogUsageOfRetryStrategy(string nameOfFinalStrategy, RetryStrategy f
         sb.AppendLine($"Backoff type: '{finalRetryStrategy.BackoffType.ToString()}'");
         sb.AppendLine($"Delay: {finalRetryStrategy.Delay.ToString()}");
         sb.AppendLine($"Maximal delay: {finalRetryStrategy.MaxDelay?.ToString()}");
-        sb.AppendLine($"Use jitter: {finalRetryStrategy.UseJitter}");
+        sb.Append($"Use jitter: {finalRetryStrategy.UseJitter}");
 
         return sb.ToString();
     }

src/TeaPie/Logging/LoggingInterceptorHandler.cs

@@ -1,4 +1,5 @@
 using Microsoft.Extensions.Logging;
+
 namespace TeaPie.Logging;
 
 internal class LoggingInterceptorHandler(ILogger<LoggingInterceptorHandler> logger) : DelegatingHandler

src/TeaPie/Logging/Setup.cs

@@ -4,6 +4,7 @@
 using Serilog.Events;
 using Serilog.Filters;
 using Serilog.Formatting.Json;
+using TeaPie.Logging.Tree;
 
 namespace TeaPie.Logging;
 
@@ -26,8 +27,10 @@ public static IServiceCollection ConfigureLogging(
         LogLevel minimumLevel,
         string pathToLogFile = "",
         LogLevel minimumLevelForLogFile = LogLevel.Debug,
-        string pathToRequestsLogFile = "")
+        string pathToRequestsLogFile = "",
+        bool useTreeLogging = false)
     {
+        TreeLoggingExtensions.SetTreeLoggingEnabled(useTreeLogging);
         if (minimumLevel == LogLevel.None)
         {
             Log.Logger = Serilog.Core.Logger.None;
@@ -37,9 +40,17 @@ public static IServiceCollection ConfigureLogging(
             var config = new LoggerConfiguration()
                 .MinimumLevel.Is(GetMaximumFromMinimalLevels(minimumLevel, minimumLevelForLogFile))
                 .MinimumLevel.Override("System.Net.Http", ApplyRestrictiveLogLevelRule(minimumLevel))
-                .MinimumLevel.Override("TeaPie.Logging.NuGetLoggerAdapter", ApplyRestrictiveLogLevelRule(minimumLevel));
+                .MinimumLevel.Override("TeaPie.Logging.NuGetLoggerAdapter", ApplyRestrictiveLogLevelRule(minimumLevel))
+                .Enrich.FromLogContext();
 
-            AddConsoleSink(config, minimumLevel);
+            if (useTreeLogging)
+            {
+                AddTreeConsoleSink(config, minimumLevel);
+            }
+            else
+            {
+                AddConsoleSink(config, minimumLevel);
+            }
 
             if (!pathToLogFile.Equals(string.Empty) && minimumLevelForLogFile < LogLevel.None)
             {
@@ -72,6 +83,14 @@ private static void AddConsoleSink(LoggerConfiguration config, LogLevel minimumL
             .WriteTo.Console(restrictedToMinimumLevel: minimumLevel.ToSerilogLogLevel()));
     }
 
+    private static void AddTreeConsoleSink(LoggerConfiguration config, LogLevel minimumLevel)
+    {
+        config
+            .WriteTo.Logger(lc => lc
+                .Filter.ByExcluding(Matching.FromSource("HttpRequests"))
+                .WriteTo.TreeConsole(restrictedToMinimumLevel: minimumLevel.ToSerilogLogLevel()));
+    }
+
     private static void AddLogFileSink(LoggerConfiguration config, string pathToLogFile, LogLevel minimumLevelForLogFile)
     {
         config.WriteTo.Logger(lc => lc