Skip to content

Commit 8e4b506

Browse files
seantleonardseantleonard
authored
Structured logging for the Core project (#1665)
## 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); ``` - Updated the CorrelationId creation helpers to no longer include extra formatting such as a space and colon. Now correlationID is just that, the id with no special formatting so that searching for an id in app insights is straightforward. - I did not add a colon manually to every location correlationId shows up in order to avoid cascading changes. - example log event before: `dbug: Azure.DataApiBuilder.Core.AuthenticationHelpers.ClientRoleHeaderAuthenticationMiddleware[0] 233f76e8-7955-4fce-85b3-b47c9ca2cdfa: The request will be executed in the context of the role: Authenticated` - example log event now: `dbug: Azure.DataApiBuilder.Core.AuthenticationHelpers.ClientRoleHeaderAuthenticationMiddleware[0] 233f76e8-7955-4fce-85b3-b47c9ca2cdfa The request will be executed in the context of the role: Authenticated` ## testing - Updates two tests that were dependent on the number of log events during query execution. Because this PR removes redundant log events (some cases where there were 2 events, now there is one event), the counts were wrong. I added more comments describing the tests and what they validate as well as explain the "Magic numbers" that were previously being used. Testing is manual via analyzing the console, no logic changes were made to the engine.
1 parent 653a8f6 commit 8e4b506

13 files changed

Lines changed: 127 additions & 91 deletions

‎src/Core/AuthenticationHelpers/AppServiceAuthentication.cs‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -103,10 +103,11 @@ error is NotSupportedException ||
103103
// Logging the parsing failure exception to the console, but not rethrowing
104104
// nor creating a DataApiBuilder exception because the authentication handler
105105
// will create and send a 401 unauthorized response to the client.
106-
logger.LogError($"Failure processing the AppService EasyAuth header.\n" +
107-
$"{HttpContextExtensions.GetLoggerCorrelationId(context)}" +
108-
$"{error.Message}\n" +
109-
$"{error.StackTrace}");
106+
logger.LogError(
107+
exception: error,
108+
message: "{correlationId} Failure processing the AppService EasyAuth header: {errorMessage}",
109+
HttpContextExtensions.GetLoggerCorrelationId(context),
110+
error.Message);
110111
}
111112
}
112113

‎src/Core/AuthenticationHelpers/ClientRoleHeaderAuthenticationMiddleware.cs‎

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -108,12 +108,15 @@ public async Task InvokeAsync(HttpContext httpContext)
108108
// only in the non-hosted scenario.
109109
if (!_isLateConfigured)
110110
{
111-
string requestAuthStatus = isAuthenticatedRequest ? AuthorizationType.Authenticated.ToString() :
112-
AuthorizationType.Anonymous.ToString();
113-
_logger.LogDebug($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
114-
$"Request authentication state: {requestAuthStatus}.");
115-
_logger.LogDebug($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
116-
$"The request will be executed in the context of {clientDefinedRole} role");
111+
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
112+
string requestAuthStatus = isAuthenticatedRequest ? AuthorizationType.Authenticated.ToString() : AuthorizationType.Anonymous.ToString();
113+
_logger.LogDebug(
114+
message: "{correlationId} Request authentication state: {requestAuthStatus}.",
115+
correlationId,
116+
requestAuthStatus);
117+
_logger.LogDebug("{correlationId} The request will be executed in the context of the role: {clientDefinedRole}",
118+
correlationId,
119+
clientDefinedRole);
117120
}
118121

119122
// When the user is not in the clientDefinedRole and the client role header

‎src/Core/AuthenticationHelpers/StaticWebAppsAuthentication.cs‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -89,10 +89,11 @@ error is NotSupportedException ||
8989
// Does not raise or rethrow a DataApiBuilder exception because
9090
// the authentication handler caller will return a 401 unauthorized
9191
// response to the client.
92-
logger.LogError($"Failure processing the StaticWebApps EasyAuth header.\n" +
93-
$"{HttpContextExtensions.GetLoggerCorrelationId(context)}" +
94-
$"{error.Message}\n" +
95-
$"{error.StackTrace}");
92+
logger.LogError(
93+
exception: error,
94+
message: "{correlationId} Failure processing the StaticWebApps EasyAuth header due to:\n{errorMessage}",
95+
HttpContextExtensions.GetLoggerCorrelationId(context),
96+
error.Message);
9697
}
9798

9899
return identity;

‎src/Core/Configurations/RuntimeConfigValidator.cs‎

Lines changed: 30 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -624,7 +624,7 @@ public static bool IsValidDatabasePolicyForAction(EntityAction permission)
624624
/// <exception cref="DataApiBuilderException">Throws exception whenever some validation fails.</exception>
625625
public void ValidateRelationshipsInConfig(RuntimeConfig runtimeConfig, ISqlMetadataProvider sqlMetadataProvider)
626626
{
627-
_logger.LogInformation("Validating Relationship Section in Config...");
627+
_logger.LogInformation("Validating entity relationships.");
628628

629629
// Loop through each entity in the config and verify its relationship.
630630
foreach ((string entityName, Entity entity) in runtimeConfig.Entities)
@@ -717,9 +717,21 @@ public void ValidateRelationshipsInConfig(RuntimeConfig runtimeConfig, ISqlMetad
717717
string referencingTargetColumns = relationship.LinkingTargetFields is not null ? string.Join(",", relationship.LinkingTargetFields) :
718718
sqlMetadataProvider.PairToFkDefinition!.TryGetValue(linkedTargetRelationshipPair, out fKDef) ?
719719
string.Join(",", fKDef.ReferencingColumns) : string.Empty;
720-
_logger.LogDebug($"{entityName}: {sourceDBOName}({referencedSourceColumns}) related to {cardinality} " +
721-
$"{relationship.TargetEntity}: {targetDBOName}({referencedTargetColumns}) by " +
722-
$"{relationship.LinkingObject}(linking.source.fields: {referencingSourceColumns}), (linking.target.fields: {referencingTargetColumns})");
720+
721+
_logger.LogDebug(
722+
message: "{entityName}: {sourceDBOName}({referencedSourceColumns}) is related to {cardinality} " +
723+
"{relationship.TargetEntity}: {targetDBOName}({referencedTargetColumns}) by " +
724+
"{relationship.LinkingObject}(linking.source.fields: {referencingSourceColumns}), (linking.target.fields: {referencingTargetColumns})",
725+
entityName,
726+
sourceDBOName,
727+
referencedSourceColumns,
728+
cardinality,
729+
relationship.TargetEntity,
730+
targetDBOName,
731+
referencedTargetColumns,
732+
relationship.LinkingObject,
733+
referencingSourceColumns,
734+
referencingTargetColumns);
723735
}
724736
}
725737

@@ -729,9 +741,9 @@ public void ValidateRelationshipsInConfig(RuntimeConfig runtimeConfig, ISqlMetad
729741
if (!sqlMetadataProvider.VerifyForeignKeyExistsInDB(sourceDatabaseObject, targetDatabaseObject))
730742
{
731743
throw new DataApiBuilderException(
732-
message: $"Could not find relationship between entities: {entityName} and {relationship.TargetEntity}.",
733-
statusCode: HttpStatusCode.ServiceUnavailable,
734-
subStatusCode: DataApiBuilderException.SubStatusCodes.ConfigValidationError);
744+
message: $"Could not find relationship between entities: {entityName} and {relationship.TargetEntity}.",
745+
statusCode: HttpStatusCode.ServiceUnavailable,
746+
subStatusCode: DataApiBuilderException.SubStatusCodes.ConfigValidationError);
735747
}
736748
}
737749

@@ -753,8 +765,17 @@ public void ValidateRelationshipsInConfig(RuntimeConfig runtimeConfig, ISqlMetad
753765
string.Join(",", fKDef.ReferencedColumns) :
754766
sqlMetadataProvider.PairToFkDefinition!.TryGetValue(targetSourceRelationshipPair, out fKDef) ?
755767
string.Join(",", fKDef.ReferencingColumns) : string.Empty;
756-
_logger.LogDebug($"{entityName}: {sourceDBOName}({sourceColumns}) is related to {cardinality} " +
757-
$"{relationship.TargetEntity}: {targetDBOName}({targetColumns}).");
768+
769+
_logger.LogDebug(
770+
message: "{entityName}: {sourceDBOName}({sourceColumns}) is related to {cardinality} {relationshipTargetEntity}: {targetDBOName}({targetColumns}).",
771+
entityName,
772+
sourceDBOName,
773+
sourceColumns,
774+
cardinality,
775+
relationship.TargetEntity,
776+
targetDBOName,
777+
targetColumns
778+
);
758779
}
759780
}
760781
}

‎src/Core/Models/HttpContextExtensions.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,7 @@ public static class HttpContextExtensions
4343
public static string GetLoggerCorrelationId(HttpContext? context)
4444
{
4545
Guid? correlationId = context is not null ? GetCorrelationId(context) : null;
46-
return correlationId is not null ? $"{correlationId.ToString()!}: " : "";
46+
return correlationId is not null ? $"{correlationId}" : "";
4747
}
4848
}
4949
}

‎src/Core/Models/RestRequestContexts/RestRequestContext.cs‎

Lines changed: 5 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -151,10 +151,11 @@ public void CalculateCumulativeColumns(ILogger logger, HttpContext context)
151151
{
152152
// Exception not rethrown as returning false here is gracefully handled by caller,
153153
// which will result in a 403 Unauthorized response to the client.
154-
logger.LogError($"ERROR IN ODATA_AST_COLUMN_VISITOR TRAVERSAL\n" +
155-
$"{HttpContextExtensions.GetLoggerCorrelationId(context)}" +
156-
$"{e.Message}\n" +
157-
$"{e.StackTrace}");
154+
logger.LogError(
155+
exception: e,
156+
message: "{correlationId} Error in ODATA_AST_COLUMN_VISITOR traversal due to:\n{e.Message}",
157+
HttpContextExtensions.GetLoggerCorrelationId(context),
158+
e.Message);
158159

159160
throw new DataApiBuilderException(
160161
message: "$filter query parameter is not well formed.",

‎src/Core/Resolvers/MsSqlQueryExecutor.cs‎

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -172,15 +172,15 @@ private bool IsDefaultAccessTokenValid()
172172
{
173173
try
174174
{
175-
_defaultAccessToken =
176-
await AzureCredential.GetTokenAsync(
177-
new TokenRequestContext(new[] { DATABASE_SCOPE }));
175+
_defaultAccessToken = await AzureCredential.GetTokenAsync(new TokenRequestContext(new[] { DATABASE_SCOPE }));
178176
}
179177
catch (CredentialUnavailableException ex)
180178
{
181-
QueryExecutorLogger.LogWarning($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContextAccessor.HttpContext)}" +
182-
$"Attempt to retrieve a managed identity access token using DefaultAzureCredential" +
183-
$" failed due to: \n{ex}");
179+
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(HttpContextAccessor.HttpContext);
180+
QueryExecutorLogger.LogWarning(
181+
message: "{correlationId} Failed to retrieve a managed identity access token using DefaultAzureCredential due to:\n{errorMessage}",
182+
correlationId,
183+
ex.Message);
184184
}
185185

186186
return _defaultAccessToken?.Token;

‎src/Core/Resolvers/MySqlQueryExecutor.cs‎

Lines changed: 7 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -146,8 +146,7 @@ private static bool ShouldManagedIdentityAccessBeAttempted(MySqlConnectionString
146146
/// <returns>True if valid, false otherwise.</returns>
147147
private bool IsDefaultAccessTokenValid()
148148
{
149-
return _defaultAccessToken is not null &&
150-
((AccessToken)_defaultAccessToken).ExpiresOn.CompareTo(DateTimeOffset.Now) > 0;
149+
return _defaultAccessToken is not null && ((AccessToken)_defaultAccessToken).ExpiresOn.CompareTo(DateTimeOffset.Now) > 0;
151150
}
152151

153152
/// <summary>
@@ -161,15 +160,15 @@ private bool IsDefaultAccessTokenValid()
161160
{
162161
try
163162
{
164-
_defaultAccessToken =
165-
await AzureCredential.GetTokenAsync(
166-
new TokenRequestContext(new[] { DATABASE_SCOPE }));
163+
_defaultAccessToken = await AzureCredential.GetTokenAsync(new TokenRequestContext(new[] { DATABASE_SCOPE }));
167164
}
168165
catch (CredentialUnavailableException ex)
169166
{
170-
QueryExecutorLogger.LogWarning($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContextAccessor.HttpContext)}" +
171-
$"Attempt to retrieve a managed identity access token using DefaultAzureCredential" +
172-
$" failed due to: \n{ex}");
167+
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(HttpContextAccessor.HttpContext);
168+
QueryExecutorLogger.LogWarning(
169+
exception: ex,
170+
message: "{correlationId} Failed to retrieve a managed identity access token using DefaultAzureCredential.",
171+
correlationId);
173172
}
174173

175174
return _defaultAccessToken?.Token;

‎src/Core/Resolvers/PostgreSqlExecutor.cs‎

Lines changed: 8 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -164,12 +164,14 @@ await AzureCredential.GetTokenAsync(
164164
// so a bunch of different exceptions could occur in that scenario
165165
catch (Exception ex)
166166
{
167-
QueryExecutorLogger.LogWarning($"{HttpContextExtensions.GetLoggerCorrelationId(HttpContextAccessor.HttpContext)}" +
168-
$"No password detected in the connection string. Attempt to retrieve " +
169-
$"a managed identity access token using DefaultAzureCredential failed due to: \n{ex}\n" +
170-
(firstAttemptAtDefaultAccessToken ?
171-
$"If authentication with DefaultAzureCrendential is not intended, this warning can be safely ignored." :
172-
string.Empty));
167+
string messagePrefix = "{correlationId} No password detected in the connection string. Attempt to retrieve a managed identity access token using DefaultAzureCredential failed due to:\n{errorMessage}";
168+
string messageSuffix = (firstAttemptAtDefaultAccessToken ? $"If authentication with DefaultAzureCrendential is not intended, this warning can be safely ignored." : string.Empty);
169+
string message = messagePrefix + messageSuffix;
170+
QueryExecutorLogger.LogWarning(
171+
exception: ex,
172+
message: message,
173+
HttpContextExtensions.GetLoggerCorrelationId(HttpContextAccessor.HttpContext),
174+
ex.Message);
173175

174176
// the config doesn't contain an identity token
175177
// and a default identity token cannot be obtained

‎src/Core/Resolvers/QueryExecutor.cs‎

Lines changed: 24 additions & 26 deletions
Original file line numberDiff line numberDiff line change
@@ -56,8 +56,7 @@ public QueryExecutor(DbExceptionParser dbExceptionParser,
5656
sleepDurationProvider: (attempt) => TimeSpan.FromSeconds(Math.Pow(2, attempt)),
5757
onRetry: (exception, backOffTime) =>
5858
{
59-
QueryExecutorLogger.LogError(exception.Message);
60-
QueryExecutorLogger.LogError(exception.StackTrace);
59+
QueryExecutorLogger.LogError(exception: exception, message: "Error during query execution, retrying.");
6160
});
6261
}
6362

@@ -96,23 +95,18 @@ public QueryExecutor(DbExceptionParser dbExceptionParser,
9695
// When IsLateConfigured is true we are in a hosted scenario and do not reveal query information.
9796
if (!ConfigProvider.IsLateConfigured)
9897
{
99-
QueryExecutorLogger.LogDebug($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
100-
$"Executing query: \n{sqltext}");
98+
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
99+
QueryExecutorLogger.LogDebug("{correlationId} Executing query: {queryText}", correlationId, sqltext);
101100
}
102101

103-
TResult? result =
104-
await ExecuteQueryAgainstDbAsync(conn,
105-
sqltext,
106-
parameters,
107-
dataReaderHandler,
108-
httpContext,
109-
args);
102+
TResult? result = await ExecuteQueryAgainstDbAsync(conn, sqltext, parameters, dataReaderHandler, httpContext, args);
103+
110104
if (retryAttempt > 1)
111105
{
106+
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
107+
int maxRetries = _maxRetryCount + 1;
112108
// This implies that the request got successfully executed during one of retry attempts.
113-
QueryExecutorLogger.LogInformation($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
114-
$"Request executed successfully in {retryAttempt} attempt of" +
115-
$"{_maxRetryCount + 1} available attempts.");
109+
QueryExecutorLogger.LogInformation("{correlationId} Request executed successfully in {retryAttempt} attempt of {maxRetries} available attempts.", correlationId, retryAttempt, maxRetries);
116110
}
117111

118112
return result;
@@ -125,10 +119,11 @@ await ExecuteQueryAgainstDbAsync(conn,
125119
}
126120
else
127121
{
128-
QueryExecutorLogger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
129-
$"{e.Message}");
130-
QueryExecutorLogger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
131-
$"{e.StackTrace}");
122+
QueryExecutorLogger.LogError(
123+
exception: e,
124+
message: "{correlationId} Query execution error due to:\n{errorMessage}",
125+
HttpContextExtensions.GetLoggerCorrelationId(httpContext),
126+
e.Message);
132127

133128
// Throw custom DABException
134129
throw DbExceptionParser.Parse(e);
@@ -191,10 +186,12 @@ await ExecuteQueryAgainstDbAsync(conn,
191186
}
192187
catch (DbException e)
193188
{
194-
QueryExecutorLogger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
195-
$"{e.Message}");
196-
QueryExecutorLogger.LogError($"{HttpContextExtensions.GetLoggerCorrelationId(httpContext)}" +
197-
$"{e.StackTrace}");
189+
string correlationId = HttpContextExtensions.GetLoggerCorrelationId(httpContext);
190+
QueryExecutorLogger.LogError(
191+
exception: e,
192+
message: "{correlationId} Query execution error due to:\n{errorMessage}",
193+
correlationId,
194+
e.Message);
198195
throw DbExceptionParser.Parse(e);
199196
}
200197
}
@@ -228,8 +225,10 @@ public async Task<bool> ReadAsync(DbDataReader reader)
228225
}
229226
catch (DbException e)
230227
{
231-
QueryExecutorLogger.LogError(e.Message);
232-
QueryExecutorLogger.LogError(e.StackTrace);
228+
QueryExecutorLogger.LogError(
229+
exception: e,
230+
message: "Query execution error due to:\n{errorMessage}",
231+
e.Message);
233232
throw DbExceptionParser.Parse(e);
234233
}
235234
}
@@ -238,8 +237,7 @@ public async Task<bool> ReadAsync(DbDataReader reader)
238237
public async Task<DbResultSet>
239238
ExtractResultSetFromDbDataReader(DbDataReader dbDataReader, List<string>? args = null)
240239
{
241-
DbResultSet dbResultSet =
242-
new(resultProperties: GetResultProperties(dbDataReader).Result ?? new());
240+
DbResultSet dbResultSet = new(resultProperties: GetResultProperties(dbDataReader).Result ?? new());
243241

244242
while (await ReadAsync(dbDataReader))
245243
{

0 commit comments

Comments
 (0)