Switch to JSON-based log entries. (#195)

* Remove Console.WriteLine() in multiple apps and use logger instead. * Switch multiple apps to logger. * Switch to JSON console logger. * Tweak logging structures. * Use common mechanism to configure logging. Signed-off-by: Phillip Hoff <[email protected]>
dapr · Sep 25, 2023 · 9c2f9ed · 9c2f9ed
1 parent 29a2894
commit 9c2f9ed
Show file tree

Hide file tree

Showing 22 changed files with 161 additions and 149 deletions.
diff --git a/Directory.Packages.props b/Directory.Packages.props
@@ -4,6 +4,8 @@
     <PackageVersion Include="Dapr.AspNetCore" Version="1.12.0-rc01" />
     <PackageVersion Include="Dapr.Actors.AspNetCore" Version="1.12.0-rc01" />
     <PackageVersion Include="Dapr.Workflow" Version="1.12.0-rc01" />
+    <PackageVersion Include="Microsoft.Extensions.Hosting" Version="7.0.1" />
+    <PackageVersion Include="Microsoft.Extensions.Logging" Version="7.0.0" />
     <PackageVersion Include="prometheus-net" Version="3.5.0" />
   </ItemGroup>
 </Project>
diff --git a/common/HostBuilderExtensions.cs b/common/HostBuilderExtensions.cs
@@ -0,0 +1,17 @@
+using Microsoft.Extensions.Hosting;
+using Microsoft.Extensions.Logging;
+
+namespace Dapr.Tests.Common;
+
+public static class HostBuilderExtensions
+{
+    public static IHostBuilder ConfigureTestInfraLogging(this IHostBuilder builder)
+    {
+        return builder.ConfigureLogging(
+            (hostingContext, config) =>
+            {
+                config.ClearProviders();
+                config.AddJsonConsole();
+            });
+    }
+}
diff --git a/common/common.csproj b/common/common.csproj
@@ -12,6 +12,8 @@
   </ItemGroup>
 
   <ItemGroup>
+    <PackageReference Include="Microsoft.Extensions.Hosting" />
+    <PackageReference Include="Microsoft.Extensions.Logging" />
     <PackageReference Include="prometheus-net" />
   </ItemGroup>
 

diff --git a/feed-generator/Program.cs b/feed-generator/Program.cs
@@ -9,7 +9,9 @@ namespace FeedGenerator
     using Dapr.Tests.Common;
     using Dapr.Tests.Common.Models;
     using Microsoft.AspNetCore.Hosting;
+    using Microsoft.Extensions.DependencyInjection;
     using Microsoft.Extensions.Hosting;
+    using Microsoft.Extensions.Logging;
     using Prometheus;
     using System;
     using System.Threading.Tasks;
@@ -31,22 +33,26 @@ public class Program
         /// <param name="args">Arguments.</param>
         public static void Main(string[] args)
         {
+            ObservabilityUtils.StartMetricsServer();
+
+            IHost host = CreateHostBuilder(args)
+                .ConfigureTestInfraLogging()
+                .Build();
+
+            var logger = host.Services.GetRequiredService<ILogger<Program>>();
+
             int delayInMilliseconds = 10000;
             if (args.Length != 0 && args[0] != "%LAUNCHER_ARGS%")
             {
                 if (int.TryParse(args[0], out delayInMilliseconds) == false)
                 {
                     string msg = "Could not parse delay";
-                    Console.WriteLine(msg);
+                    logger.LogError(msg);
                     throw new InvalidOperationException(msg);
                 }
             }
 
-            ObservabilityUtils.StartMetricsServer();
-
-            IHost host = CreateHostBuilder(args).Build();
-
-            Task.Run(() => StartMessageGeneratorAsync(delayInMilliseconds));
+            Task.Run(() => StartMessageGeneratorAsync(delayInMilliseconds, logger));
 
             host.Run();
         }
@@ -63,7 +69,7 @@ public static IHostBuilder CreateHostBuilder(string[] args) =>
                     webBuilder.UseStartup<Startup>();
                 });
 
-        static internal async void StartMessageGeneratorAsync(int delayInMilliseconds)
+        static internal async void StartMessageGeneratorAsync(int delayInMilliseconds, ILogger<Program> logger)
         {
             // the name of the component and the topic happen to be the same here...
             const string PubsubComponentName = "receivemediapost";
@@ -80,15 +86,15 @@ static internal async void StartMessageGeneratorAsync(int delayInMilliseconds)
 
                 try
                 {
-                    Console.WriteLine("Publishing");
+                    logger.LogInformation("Publishing");
                     using (PublishCallTime.NewTimer())
                     {
                         await client.PublishEventAsync<SocialMediaMessage>(PubsubComponentName, PubsubTopicName, message);
                     }
                 }
                 catch (Exception e)
                 {
-                    Console.WriteLine("Caught {0}", e.ToString());
+                    logger.LogError(e, "Caught {Exception}", e);
                     PublishFailureCount.Inc();
                 }
 

diff --git a/hashtag-actor/Actors/HashTagActor.cs b/hashtag-actor/Actors/HashTagActor.cs
@@ -20,20 +20,10 @@ public class HashTagActor : Actor, IHashTagActor
         /// Initializes a new instance of the <see cref="HashTagActor"/> class.
         /// </summary>
         /// <param name="host">Actor Service hosting the actor.</param>
-        public HashTagActor(ActorHost host)
+        public HashTagActor(ActorHost host, ILogger<HashTagActor> logger)
             : base(host)
         {
-            // TODO: ActorHost may need to have IHostBuilder reference to allow user to interact web host.
-            // For example, getting logger factory given by WebHost
-            var loggerFactory = LoggerFactory.Create(builder =>
-            {
-                builder
-                    .AddFilter("Microsoft", LogLevel.Warning)
-                    .AddFilter("System", LogLevel.Warning)
-                    .AddConsole();
-            });
-
-            this.logger = loggerFactory.CreateLogger<HashTagActor>();
+            this.logger = logger;
         }
 
         /// <inheritdoc/>
@@ -47,13 +37,13 @@ public async Task Increment(string hashtagAndSentiment)
             }
             catch (KeyNotFoundException)
             {
-                this.logger.LogDebug($"{hashtagAndSentiment} does not exist. {hashtagAndSentiment} will be initialized to 0.");
+                this.logger.LogDebug("{HashtagAndSentiment} does not exist. {HashtagAndSentiment} will be initialized to 0.", hashtagAndSentiment);
             }
 
-            this.logger.LogDebug($"{hashtagAndSentiment} = {count}");
+            this.logger.LogDebug("{HashtagAndSentiment} = {Count}", hashtagAndSentiment, count);
             count++;
             await this.StateManager.SetStateAsync<int>(hashtagAndSentiment, count);
-            this.logger.LogInformation($"Incremented {hashtagAndSentiment}.");
+            this.logger.LogInformation("Incremented {HashtagAndSentiment}.", hashtagAndSentiment);
         }
 
         public async Task<int> GetCount(string hashtagAndSentiment)
@@ -62,11 +52,11 @@ public async Task<int> GetCount(string hashtagAndSentiment)
             try
             {
                 count = await this.StateManager.GetStateAsync<int>(hashtagAndSentiment);
-                this.logger.LogInformation($"GetCount for {hashtagAndSentiment} found and it is {count}.");
+                this.logger.LogInformation("GetCount for {HashtagAndSentiment} found and it is {Count}.", hashtagAndSentiment, count);
             }
             catch (KeyNotFoundException)
             {
-                this.logger.LogInformation($"{hashtagAndSentiment} does not exist.");
+                this.logger.LogInformation("{HashtagAndSentiment} does not exist.", hashtagAndSentiment);
             }
 
             return count;

diff --git a/hashtag-actor/Program.cs b/hashtag-actor/Program.cs
@@ -24,12 +24,7 @@ public static void Main(string[] args)
         public static IHostBuilder CreateHostBuilder(string[] args)
         {
             var hostBuilder = Host.CreateDefaultBuilder(args)
-                .ConfigureLogging((hostingContext, config) =>
-                {
-                    config.ClearProviders();
-                    config.AddConsole();
-
-                })
+                .ConfigureTestInfraLogging()
                 .ConfigureWebHostDefaults(webBuilder =>
                 {
                     var appSettings = new ConfigurationBuilder()

diff --git a/hashtag-actor/Startup.cs b/hashtag-actor/Startup.cs
@@ -33,7 +33,6 @@ public void ConfigureServices(IServiceCollection services)
         // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
         public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
         {
-            Console.WriteLine("Configure");
             if (env.EnvironmentName.Contains(".dev"))
             {
                 app.UseDeveloperExceptionPage();

diff --git a/hashtag-counter/Controllers/HashTagController.cs b/hashtag-counter/Controllers/HashTagController.cs
@@ -28,21 +28,23 @@ public class HashTagController : ControllerBase
 
         private readonly IConfiguration configuration;
 
-        public HashTagController(IConfiguration config)
+        private readonly ILogger<HashTagController> logger;
+
+        public HashTagController(IConfiguration config, ILogger<HashTagController> logger)
         {
-            Console.WriteLine("ctor.");
             this.configuration = config;
+            this.logger = logger;
         }
 
         [HttpPost("messagebinding")]
         public async Task<IActionResult> PostMessageBinding([FromBody]SocialMediaMessage message)
         {
-            Console.WriteLine("enter messagebinding");
+            this.logger.LogDebug("enter messagebinding");
 
             var duration = DateTime.UtcNow - message.PreviousAppTimestamp;
             BindingDuration.Set(duration.TotalSeconds);
 
-            Console.WriteLine($"{message.CreationDate}, {message.CorrelationId}, {message.MessageId}, {message.Message}, {message.Sentiment}");
+            this.logger.LogInformation("{CreationDate}, {CorrelationId}, {MessageId}, {Message}, {Sentiment}", message.CreationDate, message.CorrelationId, message.MessageId, message.Message, message.Sentiment);
 
             int indexOfHash = message.Message.LastIndexOf('#');
             string hashTag = message.Message.Substring(indexOfHash + 1);
@@ -51,16 +53,16 @@ public async Task<IActionResult> PostMessageBinding([FromBody]SocialMediaMessage
             var actorId = new ActorId(key);
             var proxy = ActorProxy.Create<IHashTagActor>(actorId, "HashTagActor");
 
-            Console.WriteLine($"Increasing {key}.");
+            this.logger.LogInformation("Increasing {Key}.", key);
             Exception ex = null;
             try
             {
                 await proxy.Increment(key);
-                Console.WriteLine($"Increasing {key} successful.");
+                this.logger.LogInformation("Increasing {Key} successful.", key);
             }
             catch (Exception e)
             {
-                Console.WriteLine($"Increasing {key} failed with {e}");
+                this.logger.LogError(e, "Increasing {Key} failed with {Exception}", key, e);
                 ex = e;
                 ActorMethodFailureCount.Inc();
             }

diff --git a/hashtag-counter/Program.cs b/hashtag-counter/Program.cs
@@ -24,12 +24,7 @@ public static void Main(string[] args)
 
         public static IHostBuilder CreateHostBuilder(string[] args) {
             var hostBuilder = Host.CreateDefaultBuilder(args)
-                .ConfigureLogging((hostingContext, config) =>
-                {
-                    config.ClearProviders();
-                    config.AddConsole();
-
-                })
+                .ConfigureTestInfraLogging()
                 .ConfigureWebHostDefaults(webBuilder =>
                 {
                     var appSettings = new ConfigurationBuilder()

diff --git a/hashtag-counter/Startup.cs b/hashtag-counter/Startup.cs
@@ -27,15 +27,13 @@ public Startup(IConfiguration configuration)
         // This method gets called by the runtime. Use this method to add services to the container.
         public void ConfigureServices(IServiceCollection services)
         {
-            Console.WriteLine("ConfigureServices()");
             services.AddControllers();
 
         }
 
         // This method gets called by the runtime. Use this method to configure the HTTP request pipeline.
         public void Configure(IApplicationBuilder app, IWebHostEnvironment env)
         {
-            Console.WriteLine("Configure");
             if (env.EnvironmentName.Contains(".dev"))
             {
                 app.UseDeveloperExceptionPage();

diff --git a/message-analyzer/Program.cs b/message-analyzer/Program.cs
@@ -29,8 +29,6 @@ public class MessageAnalyzer
         /// <param name="args">Arguments.</param>
         public static void Main(string[] args)
         {
-            Console.WriteLine("Enter main");
-
             ObservabilityUtils.StartMetricsServer();
 
             CreateHostBuilder(args).Build().Run();
@@ -43,12 +41,7 @@ public static void Main(string[] args)
         /// <returns>Returns IHostbuilder.</returns>
         public static IHostBuilder CreateHostBuilder(string[] args) =>
             Host.CreateDefaultBuilder(args)
-                .ConfigureLogging((hostingContext, config) =>
-                {
-                    config.ClearProviders();
-                    config.AddConsole();
-
-                })
+                .ConfigureTestInfraLogging()
                 .ConfigureWebHostDefaults(webBuilder =>
                 {
                     var appSettings = new ConfigurationBuilder()

diff --git a/message-analyzer/Startup.cs b/message-analyzer/Startup.cs
@@ -14,6 +14,7 @@ namespace MessageAnalyzer
     using Microsoft.Extensions.Configuration;
     using Microsoft.Extensions.DependencyInjection;
     using Microsoft.Extensions.Hosting;
+    using Microsoft.Extensions.Logging;
     using Prometheus;
     using System;
     using System.Text.Json;
@@ -108,9 +109,9 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, JsonSeri
             });
 
             // Receive a "Post" object from the previous app in the pipeline.
-            async Task ReceiveMediaPost(HttpContext context)
+            async Task ReceiveMediaPost(HttpContext context, ILogger<Startup> logger)
             {
-                Console.WriteLine("Enter ReceiveMediaPost");
+                logger.LogDebug("Enter ReceiveMediaPost");
                 var client = context.RequestServices.GetRequiredService<DaprClient>();
 
                 var message = await JsonSerializer.DeserializeAsync<SocialMediaMessage>(context.Request.Body, serializerOptions);
@@ -121,7 +122,7 @@ async Task ReceiveMediaPost(HttpContext context)
 
                 // update with a sentiment
                 message.Sentiment = GenerateRandomSentiment();
-                Console.WriteLine($"....Invoking binding {BindingName} with message {message.Message} and sentiment {message.Sentiment}");
+                logger.LogInformation("....Invoking binding {BindingName} with message {Message} and sentiment {Sentiment}", BindingName, message.Message, message.Sentiment);
 
                 // overwrite the timestamp so the next app can use it
                 message.PreviousAppTimestamp = DateTime.UtcNow;
@@ -131,12 +132,12 @@ async Task ReceiveMediaPost(HttpContext context)
                     using (OutputBindingCallTime.NewTimer())
                     {
                         await client.InvokeBindingAsync<SocialMediaMessage>(BindingName, "create", message);
-                        Console.WriteLine("Invoke binding \"create\" completed successfully");
+                        logger.LogInformation("Invoke binding \"create\" completed successfully");
                     }
                 }
                 catch (Exception e)
                 {
-                    Console.WriteLine("Caught {0}", e);
+                    logger.LogError(e, "Caught {Exception}", e);
                     BindingApiFailureCount.Inc();
                 }
             }

diff --git a/pubsub-workflow/Controllers/PubsubController.cs b/pubsub-workflow/Controllers/PubsubController.cs
@@ -6,6 +6,7 @@
 using Dapr;
 using Dapr.Client;
 using Microsoft.AspNetCore.Mvc;
+using Microsoft.Extensions.Logging;
 using System;
 using System.Threading.Tasks;
 
@@ -19,12 +20,19 @@ public class PubsubController : ControllerBase
         internal static DateTime lastSlowCall = DateTime.Now;
         internal static DateTime lastGlacialCall = DateTime.Now;
 
+        private readonly ILogger<PubsubController> logger;
+
+        public PubsubController(ILogger<PubsubController> logger)
+        {
+            this.logger = logger;
+        }
+
         [Topic("longhaul-sb-rapid", "rapidtopic")]
         [HttpPost("rapidMessage")]
         public IActionResult RapidMessageHandler() {
             var lastHit = lastRapidCall;
             lastRapidCall = DateTime.Now;
-            Console.WriteLine($"Rapid subscription hit at {lastRapidCall}, previous hit at {lastHit}");
+            this.logger.LogInformation("Rapid subscription hit at {LastRapidCall}, previous hit at {LastHit}", lastRapidCall, lastHit);
             return Ok();
         }
 
@@ -33,7 +41,7 @@ public IActionResult RapidMessageHandler() {
         public IActionResult MediumMessageHandler() {
             var lastHit = lastMediumCall;
             lastMediumCall = DateTime.Now;
-            Console.WriteLine($"Medium subscription hit at {lastMediumCall}, previous hit at {lastHit}");
+            this.logger.LogInformation("Medium subscription hit at {LastMediumCall}, previous hit at {LastHit}", lastMediumCall, lastHit);
             return Ok();
         }
 
@@ -42,7 +50,7 @@ public IActionResult MediumMessageHandler() {
         public IActionResult SlowMessageHandler() {
             var lastHit = lastSlowCall;
             lastSlowCall = DateTime.Now;
-            Console.WriteLine($"Slow subscription hit at {lastSlowCall}, previous hit at {lastHit}");
+            this.logger.LogInformation("Slow subscription hit at {LastSlowCall}, previous hit at {LastHit}", lastSlowCall, lastHit);
             return Ok();
         }
 
@@ -51,7 +59,7 @@ public IActionResult SlowMessageHandler() {
         public IActionResult GlacialMessageHandler() {
             var lastHit = lastGlacialCall;
             lastGlacialCall = DateTime.Now;
-            Console.WriteLine($"Glacial subscription hit at {lastGlacialCall}, previous hit at {lastHit}");
+            this.logger.LogInformation("Glacial subscription hit at {LastGlacialCall}, previous hit at {LastHit}", lastGlacialCall, lastHit);
             return Ok();
         }
     }