Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add correlationId to log messages #3601

Merged
merged 29 commits into from
Jun 9, 2021
Merged

Add correlationId to log messages #3601

merged 29 commits into from
Jun 9, 2021

Conversation

jo-arroyo
Copy link
Collaborator

@jo-arroyo jo-arroyo commented May 6, 2021

This PR adds the correlation ID to log messages to make it easier to track log messages associated with requests. The correlation ID is either passed in or created per request, and will be added to log messages related to the request and passed down to flow client to use on the client's logger instance. Addresses #3022.

Msal-common

  • Adjusts Logger to allow setting correlation ID on the logger instance from the loggerOptions
  • Change Logger.logMessage() to set correlation ID if present. Precedence goes to the correlation ID passed in the log message, then to the correlation ID set on the Logger instance.
  • Add unit tests for Logger correlation ID changes

Msal-browser

  • Adds the correlation ID to msal-browser log messages related to requests
  • Each request now creates a browserRequestLogger, with the correlation ID set when instantiated. This logger instance is used for all subsequent logs related to the request, and is passed into called functions and interaction handlers where applicable.
    • Note that where the browserRequestLogger is not available, the correlation ID, if available, may still be passed for log messages.
    • This is a stop-gap feature, and may be replace when the Logger is redesigned.
  • Adds the correlation ID to getClientConfiguration, so correlation ID can be set on flow client logger instance
  • Adjusts interaction handler unit tests to account for new browserRequestLogger

Msal-node

  • Adds the correlation ID to msal-node log messages related to requests
  • Adds the correlation ID to buildOauthClientConfiguration, so correlation ID can be set on flow client logger instance
  • Changes cache and storage log messages to logLevel trace to reduce noisiness of verbose level log messages

Screenshot examples of new logs:

Screenshot 2021-06-02 125735

Screenshot 2021-06-02 125840

Note: We realize that we are knowingly taking on tech debt by passing in the correlation ID manually into log messages. In the future, we would like to refactor usage of the Logger so this will no longer be necessary.

@github-actions github-actions bot added msal-browser Related to msal-browser package msal-common Related to msal-common package labels May 7, 2021
@jasonnutter
Copy link
Contributor

Having the correlation id provided on the individual log messages (instead of being set on the logger itself) may be a better approach, to better support multiple concurrent requests.

@sameerag
Copy link
Member

Having the correlation id provided on the individual log messages (instead of being set on the logger itself) may be a better approach, to better support multiple concurrent requests.

I was discussing this with @jo-arroyo! Since every request is a separate instance, will there be a case where parallel requests point to the same logger instance and mess up the correlation-id referenced? If so, we need to track correlation-id separately per request and add it to the logs as an extra parameter. Better yet, have a request logger instance derived from the main class. My guess is this depends on the design of parallel requests.

We can discuss this @jo-arroyo @jasonnutter

@jasonnutter
Copy link
Contributor

Since every request is a separate instance, will there be a case where parallel requests point to the same logger instance and mess up the correlation-id referenced

Not every request is guaranteed to have its own logger instance.

@codecov-commenter
Copy link

codecov-commenter commented May 25, 2021

Codecov Report

Merging #3601 (1bbeace) into dev (2c58d3f) will increase coverage by 0.05%.
The diff coverage is 94.37%.

Flag Coverage Δ *Carryforward flag
msal-angular 95.81% <ø> (ø)
msal-browser 84.64% <98.16%> (+0.08%) ⬆️
msal-common 83.41% <100.00%> (+0.09%) ⬆️
msal-core 73.02% <ø> (ø) Carriedforward from a5d3f0e
msal-node 78.35% <83.72%> (-0.14%) ⬇️
msal-react 93.77% <ø> (ø)

*This pull request uses carry forward flags. Click here to find out more.

Impacted Files Coverage Δ
lib/msal-common/src/config/ClientConfiguration.ts 100.00% <ø> (ø)
...ib/msal-node/src/client/PublicClientApplication.ts 57.69% <50.00%> (ø)
lib/msal-node/src/cache/TokenCache.ts 75.00% <81.81%> (ø)
lib/msal-node/src/client/ClientApplication.ts 74.41% <86.66%> (-0.88%) ⬇️
lib/msal-node/src/cache/NodeStorage.ts 75.00% <88.88%> (ø)
lib/msal-browser/src/app/ClientApplication.ts 90.62% <97.53%> (+0.02%) ⬆️
...ib/msal-browser/src/app/PublicClientApplication.ts 85.71% <100.00%> (+1.33%) ⬆️
...wser/src/interaction_handler/InteractionHandler.ts 87.09% <100.00%> (+0.88%) ⬆️
...al-browser/src/interaction_handler/PopupHandler.ts 85.18% <100.00%> (ø)
...browser/src/interaction_handler/RedirectHandler.ts 92.59% <100.00%> (ø)
... and 3 more

@github-actions github-actions bot added the msal-node Related to msal-node package label May 26, 2021
@jo-arroyo jo-arroyo marked this pull request as ready for review June 2, 2021 20:15
@tnorling
Copy link
Collaborator

tnorling commented Jun 2, 2021

Did you consider generating a new logger instance per request (instead of using a single class property) and passing that down? It sounds like we can't avoid passing something down to functions if we want logging, I wonder if passing the logger instance would be better than passing the correlationId and then also needing to provide name and version on each message. Thoughts?

@jasonnutter
Copy link
Contributor

jasonnutter commented Jun 2, 2021

Did you consider generating a new logger instance per request (instead of using a single class property) and passing that down? It sounds like we can't avoid passing something down to functions if we want logging, I wonder if passing the logger instance would be better than passing the correlationId and then also needing to provide name and version on each message. Thoughts?

In the future (i.e. v3), I would like to have a model where when a request is made, the first thing that happens is the library creates a client instance (e.g. SilentFlowClient, AuthCodeClient), and then everything downstream happens in that client, including log messages (as today each flow client includes its own logger). For example, today for a silent request, some things happen in the SilentFlowClient, but there are many things that do not. If everything for a given request happened in its client, it would be easy to pass the correlation id for that request into the client and attach it to the logger, and all log messages related to that request use the client's logger.

@tnorling
Copy link
Collaborator

tnorling commented Jun 2, 2021

In the future (i.e. v3), I would like to have a model where when a request is made, the first thing that happens is the library creates a client instance (e.g. SilentFlowClient, AuthCodeClient), and then everything downstream happens in that client.

I'm actually working on a prototype for something very similar to this as we speak...FWIW I don't think it necessarily needs to wait until v3, but we'll see

If everything for a given request happened in its client, it would be easy to pass the correlation id for that request into the client and attach it to the logger, and all log messages related to that request use the client's logger.

Agreed, however, everything does happen downstream from the API that was called. We could instantiate a new logger instance each time an API is called and pass this down to whatever functions need to use the logger (which we're already doing in many cases today). I'm not personally a fan of passing the correlationId down everywhere because once you're outside PCA you'll need to provide this in addition to the logger. Is there something I'm overlooking that would not make this feasible today?

const authorizationCodeClient = new AuthorizationCodeClient(
authClientConfig
);
this.logger.verbose("Auth code client created", validRequest.correlationId);
Copy link
Collaborator Author

Choose a reason for hiding this comment

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

As there are not many logs in msal-node that use the flow client logger, I've decided to use the global logger for now with the updated correlation ID instead of instantiating a new nodeRequestLogger instance for each request. This can, of course, be changed in future PRs as the Logger changes.

Copy link
Collaborator

@tnorling tnorling left a comment

Choose a reason for hiding this comment

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

Just one last comment and then I think this looks great!

lib/msal-browser/src/app/ClientApplication.ts Outdated Show resolved Hide resolved
Co-authored-by: Jason Nutter <janutter@microsoft.com>
Copy link
Collaborator

@tnorling tnorling left a comment

Choose a reason for hiding this comment

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

Looks good! Thanks for addressing feedback

Copy link
Member

@sameerag sameerag left a comment

Choose a reason for hiding this comment

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

Lgtm. Can you please log a ADO item for node logger enhancements? When we add debug I want to address this.

@jo-arroyo jo-arroyo merged commit 0e04ce3 into dev Jun 9, 2021
@jo-arroyo jo-arroyo deleted the add-correlation-id-logs branch June 9, 2021 19:26
@jo-arroyo jo-arroyo added this to the @azure/msal-common@4.3.1 milestone Jun 9, 2021
@ghost
Copy link

ghost commented Jun 29, 2021

🎉@azure/msal-common@v4.4.0 has been released which incorporates this pull request.:tada:

We recommend upgrading to the latest version of @azure/msal-browser or @azure/msal-node to take advantage of this change.

Handy links:

@ghost
Copy link

ghost commented Jun 29, 2021

🎉@azure/msal-node@v1.2.0 has been released which incorporates this pull request.:tada:

Handy links:

@ghost
Copy link

ghost commented Jun 29, 2021

🎉@azure/msal-browser@v2.15.0 has been released which incorporates this pull request.:tada:

Handy links:

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
msal-browser Related to msal-browser package msal-common Related to msal-common package msal-node Related to msal-node package
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Could ILoggerCallback's message include correlationId if correlationId was provided to the request?
5 participants