Structured Logging (Service Project) (#1666)

seantleonard · web-flow · commit b5d2cb68949b · 2023-09-06T15:24:19.000-07:00
## Why make this change? - Adds structured logging to the Core project per #1517 ## What is this change? - In instances of ilogger usage, removes interpolated strings and uses structured logging paradigm: - in the `message` parameter, names in curly brackets are names that can be filtered in a log view such as app insights/log analytics. The parameters after message are the variables which supply the values for the names in curly brackets. ```csharp _logger.LogDebug( message: "{correlationId} Request authentication state: {requestAuthStatus}.", HttpContextExtensions.GetLoggerCorrelationId(httpContext), requestAuthStatus); ``` ## testing Testing is manual via analyzing the console, no logic changes were made to the engine.
diff --git a/src/Service/Controllers/ConfigurationController.cs b/src/Service/Controllers/ConfigurationController.cs
@@ -5,6 +5,7 @@
 using System.Threading.Tasks;
 using Azure.DataApiBuilder.Config;
 using Azure.DataApiBuilder.Core.Configurations;
+using Azure.DataApiBuilder.Core.Models;
 using Microsoft.AspNetCore.Mvc;
 using Microsoft.Extensions.Logging;
 
@@ -53,12 +54,17 @@ public async Task<ActionResult> Index([FromBody] ConfigurationPostParametersV2 c
                 }
                 else
                 {
-                    _logger.LogError($"Failed to initialize configuration.");
+                    _logger.LogError(
+                        message: "{correlationId} Failed to initialize configuration.",
+                        HttpContextExtensions.GetLoggerCorrelationId(HttpContext));
                 }
             }
             catch (Exception e)
             {
-                _logger.LogError($"Exception during configuration initialization. {e}");
+                _logger.LogError(
+                    exception: e,
+                    message: "{correlationId} Exception during configuration initialization.",
+                    HttpContextExtensions.GetLoggerCorrelationId(HttpContext));
             }
 
             return BadRequest();
@@ -92,12 +98,17 @@ public async Task<ActionResult> Index([FromBody] ConfigurationPostParameters con
                 }
                 else
                 {
-                    _logger.LogError($"Failed to initialize configuration.");
+                    _logger.LogError(
+                        message: "{correlationId} Failed to initialize configuration.",
+                        HttpContextExtensions.GetLoggerCorrelationId(HttpContext));
                 }
             }
             catch (Exception e)
             {
-                _logger.LogError($"Exception during configuration initialization. {e}");
+                _logger.LogError(
+                    exception: e,
+                    message: "{correlationId} Exception during configuration initialization.",
+                    HttpContextExtensions.GetLoggerCorrelationId(HttpContext));
             }
 
             return BadRequest();
diff --git a/src/Service/Controllers/RestController.cs b/src/Service/Controllers/RestController.cs
@@ -246,15 +246,21 @@ private async Task<IActionResult> HandleOperation(
             }
             catch (DataApiBuilderException ex)
             {
-                _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.Message}");
-                _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.StackTrace}");
+                _logger.LogError(
+                    exception: ex,
+                    message: "{correlationId} Error handling REST request.",
+                    HttpContextExtensions.GetLoggerCorrelationId(HttpContext));
+
                 Response.StatusCode = (int)ex.StatusCode;
                 return ErrorResponse(ex.SubStatusCode.ToString(), ex.Message, ex.StatusCode);
             }
             catch (Exception ex)
             {
-                _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.Message}");
-                _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.StackTrace}");
+                _logger.LogError(
+                    exception: ex,
+                    message: "{correlationId} Internal server error occured during REST request processing.",
+                    HttpContextExtensions.GetLoggerCorrelationId(HttpContext));
+
                 Response.StatusCode = (int)HttpStatusCode.InternalServerError;
                 return ErrorResponse(
                     DataApiBuilderException.SubStatusCodes.UnexpectedError.ToString(),
@@ -277,9 +283,10 @@ private EntityActionOperation DeterminePatchPutSemantics(EntityActionOperation o
             {
                 if (!string.Equals(HttpContext.Request.Headers["If-Match"], "*"))
                 {
-                    throw new DataApiBuilderException(message: "Etags not supported, use '*'",
-                                                   statusCode: HttpStatusCode.BadRequest,
-                                                   subStatusCode: DataApiBuilderException.SubStatusCodes.BadRequest);
+                    throw new DataApiBuilderException(
+                        message: "Etags not supported, use '*'",
+                        statusCode: HttpStatusCode.BadRequest,
+                        subStatusCode: DataApiBuilderException.SubStatusCodes.BadRequest);
                 }
 
                 switch (operation)
diff --git a/src/Service/Startup.cs b/src/Service/Startup.cs
@@ -255,15 +255,13 @@ private void AddGraphQLService(IServiceCollection services)
                     {
                         if (error.Exception is not null)
                         {
-                            _logger.LogError(error.Exception.Message);
-                            _logger.LogError(error.Exception.StackTrace);
+                            _logger.LogError(exception: error.Exception, message: "A GraphQL request execution error occurred.");
                             return error.WithMessage(error.Exception.Message);
                         }
 
                         if (error.Code is not null)
                         {
-                            _logger.LogError(error.Code);
-                            _logger.LogError(error.Message);
+                            _logger.LogError(message: "Error code: {errorCode}\nError message: {errorMessage}", error.Code, error.Message);
                             return error.WithMessage(error.Message);
                         }
 
@@ -592,7 +590,7 @@ private async Task<bool> PerformOnConfigChangeAsync(IApplicationBuilder app)
 
                 if (graphQLSchemaCreator is null || restService is null)
                 {
-                    _logger.LogError($"Endpoint service initialization failed");
+                    _logger.LogError("Endpoint service initialization failed.");
                 }
 
                 if (runtimeConfig.Runtime.Host.Mode == HostMode.Development)
@@ -614,15 +612,15 @@ private async Task<bool> PerformOnConfigChangeAsync(IApplicationBuilder app)
                 }
                 catch (DataApiBuilderException dabException)
                 {
-                    _logger.LogError($"{dabException.Message}");
+                    _logger.LogError(exception: dabException, message: "OpenAPI Documentor initialization failed.");
                 }
 
-                _logger.LogInformation($"Successfully completed runtime initialization.");
+                _logger.LogInformation("Successfully completed runtime initialization.");
                 return true;
             }
             catch (Exception ex)
             {
-                _logger.LogError(ex, $"Unable to complete runtime initialization. Refer to exception for error details.");
+                _logger.LogError(exception: ex, message: "Unable to complete runtime initialization. Refer to exception for error details.");
                 return false;
             }
         }

Original file line number	Diff line number	Diff line change
`@@ -5,6 +5,7 @@`
`5`	`5`	`using System.Threading.Tasks;`
`6`	`6`	`using Azure.DataApiBuilder.Config;`
`7`	`7`	`using Azure.DataApiBuilder.Core.Configurations;`
	`8`	`+using Azure.DataApiBuilder.Core.Models;`
`8`	`9`	`using Microsoft.AspNetCore.Mvc;`
`9`	`10`	`using Microsoft.Extensions.Logging;`
`10`	`11`
`@@ -53,12 +54,17 @@ public async Task<ActionResult> Index([FromBody] ConfigurationPostParametersV2 c`
`53`	`54`	`}`
`54`	`55`	`else`
`55`	`56`	`{`
`56`		`- _logger.LogError($"Failed to initialize configuration.");`
	`57`	`+ _logger.LogError(`
	`58`	`+ message: "{correlationId} Failed to initialize configuration.",`
	`59`	`+ HttpContextExtensions.GetLoggerCorrelationId(HttpContext));`
`57`	`60`	`}`
`58`	`61`	`}`
`59`	`62`	`catch (Exception e)`
`60`	`63`	`{`
`61`		`- _logger.LogError($"Exception during configuration initialization. {e}");`
	`64`	`+ _logger.LogError(`
	`65`	`+ exception: e,`
	`66`	`+ message: "{correlationId} Exception during configuration initialization.",`
	`67`	`+ HttpContextExtensions.GetLoggerCorrelationId(HttpContext));`
`62`	`68`	`}`
`63`	`69`
`64`	`70`	`return BadRequest();`
`@@ -92,12 +98,17 @@ public async Task<ActionResult> Index([FromBody] ConfigurationPostParameters con`
`92`	`98`	`}`
`93`	`99`	`else`
`94`	`100`	`{`
`95`		`- _logger.LogError($"Failed to initialize configuration.");`
	`101`	`+ _logger.LogError(`
	`102`	`+ message: "{correlationId} Failed to initialize configuration.",`
	`103`	`+ HttpContextExtensions.GetLoggerCorrelationId(HttpContext));`
`96`	`104`	`}`
`97`	`105`	`}`
`98`	`106`	`catch (Exception e)`
`99`	`107`	`{`
`100`		`- _logger.LogError($"Exception during configuration initialization. {e}");`
	`108`	`+ _logger.LogError(`
	`109`	`+ exception: e,`
	`110`	`+ message: "{correlationId} Exception during configuration initialization.",`
	`111`	`+ HttpContextExtensions.GetLoggerCorrelationId(HttpContext));`
`101`	`112`	`}`
`102`	`113`
`103`	`114`	`return BadRequest();`
Original file line number	Diff line number	Diff line change
`@@ -246,15 +246,21 @@ private async Task<IActionResult> HandleOperation(`
`246`	`246`	`}`
`247`	`247`	`catch (DataApiBuilderException ex)`
`248`	`248`	`{`
`249`		`- _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.Message}");`
`250`		`- _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.StackTrace}");`
	`249`	`+ _logger.LogError(`
	`250`	`+ exception: ex,`
	`251`	`+ message: "{correlationId} Error handling REST request.",`
	`252`	`+ HttpContextExtensions.GetLoggerCorrelationId(HttpContext));`
	`253`	`+`
`251`	`254`	`Response.StatusCode = (int)ex.StatusCode;`
`252`	`255`	`return ErrorResponse(ex.SubStatusCode.ToString(), ex.Message, ex.StatusCode);`
`253`	`256`	`}`
`254`	`257`	`catch (Exception ex)`
`255`	`258`	`{`
`256`		`- _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.Message}");`
`257`		`- _logger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContext)}{ex.StackTrace}");`
	`259`	`+ _logger.LogError(`
	`260`	`+ exception: ex,`
	`261`	`+ message: "{correlationId} Internal server error occured during REST request processing.",`
	`262`	`+ HttpContextExtensions.GetLoggerCorrelationId(HttpContext));`
	`263`	`+`
`258`	`264`	`Response.StatusCode = (int)HttpStatusCode.InternalServerError;`
`259`	`265`	`return ErrorResponse(`
`260`	`266`	`DataApiBuilderException.SubStatusCodes.UnexpectedError.ToString(),`
`@@ -277,9 +283,10 @@ private EntityActionOperation DeterminePatchPutSemantics(EntityActionOperation o`
`277`	`283`	`{`
`278`	`284`	`if (!string.Equals(HttpContext.Request.Headers["If-Match"], "*"))`
`279`	`285`	`{`
`280`		`- throw new DataApiBuilderException(message: "Etags not supported, use '*'",`
`281`		`- statusCode: HttpStatusCode.BadRequest,`
`282`		`- subStatusCode: DataApiBuilderException.SubStatusCodes.BadRequest);`
	`286`	`+ throw new DataApiBuilderException(`
	`287`	`+ message: "Etags not supported, use '*'",`
	`288`	`+ statusCode: HttpStatusCode.BadRequest,`
	`289`	`+ subStatusCode: DataApiBuilderException.SubStatusCodes.BadRequest);`
`283`	`290`	`}`
`284`	`291`
`285`	`292`	`switch (operation)`
Original file line number	Diff line number	Diff line change
`@@ -255,15 +255,13 @@ private void AddGraphQLService(IServiceCollection services)`
`255`	`255`	`{`
`256`	`256`	`if (error.Exception is not null)`
`257`	`257`	`{`
`258`		`- _logger.LogError(error.Exception.Message);`
`259`		`- _logger.LogError(error.Exception.StackTrace);`
	`258`	`+ _logger.LogError(exception: error.Exception, message: "A GraphQL request execution error occurred.");`
`260`	`259`	`return error.WithMessage(error.Exception.Message);`
`261`	`260`	`}`
`262`	`261`
`263`	`262`	`if (error.Code is not null)`
`264`	`263`	`{`
`265`		`- _logger.LogError(error.Code);`
`266`		`- _logger.LogError(error.Message);`
	`264`	`+ _logger.LogError(message: "Error code: {errorCode}\nError message: {errorMessage}", error.Code, error.Message);`
`267`	`265`	`return error.WithMessage(error.Message);`
`268`	`266`	`}`
`269`	`267`
`@@ -592,7 +590,7 @@ private async Task<bool> PerformOnConfigChangeAsync(IApplicationBuilder app)`
`592`	`590`
`593`	`591`	`if (graphQLSchemaCreator is null \|\| restService is null)`
`594`	`592`	`{`
`595`		`- _logger.LogError($"Endpoint service initialization failed");`
	`593`	`+ _logger.LogError("Endpoint service initialization failed.");`
`596`	`594`	`}`
`597`	`595`
`598`	`596`	`if (runtimeConfig.Runtime.Host.Mode == HostMode.Development)`
`@@ -614,15 +612,15 @@ private async Task<bool> PerformOnConfigChangeAsync(IApplicationBuilder app)`
`614`	`612`	`}`
`615`	`613`	`catch (DataApiBuilderException dabException)`
`616`	`614`	`{`
`617`		`- _logger.LogError($"{dabException.Message}");`
	`615`	`+ _logger.LogError(exception: dabException, message: "OpenAPI Documentor initialization failed.");`
`618`	`616`	`}`
`619`	`617`
`620`		`- _logger.LogInformation($"Successfully completed runtime initialization.");`
	`618`	`+ _logger.LogInformation("Successfully completed runtime initialization.");`
`621`	`619`	`return true;`
`622`	`620`	`}`
`623`	`621`	`catch (Exception ex)`
`624`	`622`	`{`
`625`		`- _logger.LogError(ex, $"Unable to complete runtime initialization. Refer to exception for error details.");`
	`623`	`+ _logger.LogError(exception: ex, message: "Unable to complete runtime initialization. Refer to exception for error details.");`
`626`	`624`	`return false;`
`627`	`625`	`}`
`628`	`626`	`}`