Skip to content

Structured logging for the Core project#1665

Merged
seantleonard merged 9 commits intomainfrom
dev/seantleonard/structuredlogging02
Sep 7, 2023
Merged

Structured logging for the Core project#1665
seantleonard merged 9 commits intomainfrom
dev/seantleonard/structuredlogging02

Conversation

@seantleonard
Copy link
Copy Markdown
Contributor

@seantleonard seantleonard commented Aug 28, 2023

Why make this change?

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.
_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.

Copy link
Copy Markdown
Contributor

@aaronpowell aaronpowell left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Minor nit's in there.

My only question, would it be better to put the correlationId with some kind of delimiter around it (like [] or a : suffix) so that it'd be easier to write a regex to find?

Comment thread src/Core/AuthenticationHelpers/ClientRoleHeaderAuthenticationMiddleware.cs Outdated
Comment thread src/Core/Resolvers/MySqlQueryExecutor.cs Outdated
…ultiple calls to getCorrelationId extension method. Updated instance of inconsistent correlationId variable used in message contents and removed redundant inclusion of exception message in log message when exception is already provided as argument.
@seantleonard seantleonard added this to the 0.9rc milestone Sep 6, 2023
Comment thread src/Core/AuthenticationHelpers/AppServiceAuthentication.cs
Comment thread src/Core/Configurations/RuntimeConfigValidator.cs Outdated
Comment thread src/Core/Services/MetadataProviders/SqlMetadataProvider.cs
…lqueryexecutor. Because this PR reduces the number of redundant logging events in places (2 events are now 1 event) these tests broke. This changeset does not address the validity of checking number of logger executions as a means to validate functionality.
@seantleonard seantleonard merged commit 8e4b506 into main Sep 7, 2023
@seantleonard seantleonard deleted the dev/seantleonard/structuredlogging02 branch September 7, 2023 23:23
rohkhann pushed a commit that referenced this pull request Sep 11, 2023
## 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.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants