Skip to content

Add configuration and features to logging#2040

Merged
bnjjj merged 29 commits intodevfrom
bnjjj/feat_1998
Nov 24, 2022
Merged

Add configuration and features to logging#2040
bnjjj merged 29 commits intodevfrom
bnjjj/feat_1998

Conversation

@bnjjj
Copy link
Contributor

@bnjjj bnjjj commented Nov 2, 2022

close #1998

Basic configuration

By default some logs containing sensible data (like request body, response body, headers) are not displayed even if we set the right log level.
For example if you need to display raw responses from one of your subgraph it won't be displayed by default. To enable them you have to configure it thanks to the when_header setting in the new section experimental_logging. It let's you set different headers to enable more logs (request/response headers/body for supergraph and subgraphs) when the request contains these headers with corresponding values/regex.
Here is an example how you can configure it:

telemetry:
  experimental_logging:
    format: json # By default it's "pretty" if you are in an interactive shell session
    display_filename: true # Display filename where the log is coming from. Default: true
    display_line_number: false # Display line number in the file where the log is coming from. Default: true
    # If one of these headers matches we will log supergraph and subgraphs requests/responses
    when_header:
      - name: apollo-router-log-request
        value: my_client
        headers: true # default: false
        body: true # default: false
      # log request for all requests coming from Iphones
      - name: user-agent
        match: ^Mozilla/5.0 (iPhone*
        headers: true

/!\ This PR also upgrade tracing (not to the latest version) because I needed a fix.

TODO:

  • Add tests
  • Configure it with dev mode

bnjjj added 5 commits October 27, 2022 17:44
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
@bnjjj bnjjj self-assigned this Nov 2, 2022
@github-actions

This comment has been minimized.

bnjjj added 4 commits November 2, 2022 16:46
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
bnjjj added 4 commits November 7, 2022 11:17
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
@bnjjj bnjjj requested a review from abernix November 8, 2022 12:06
bnjjj added 7 commits November 8, 2022 13:15
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
@bnjjj bnjjj marked this pull request as ready for review November 8, 2022 17:24
@bnjjj bnjjj requested a review from StephenBarlow as a code owner November 8, 2022 17:24
@bnjjj bnjjj requested a review from SimonSapin November 8, 2022 17:25
@BrynCooke
Copy link
Contributor

Couple of high level observations:

  • It would be nice to not have separate log events for subgraph request and response attributes. It feels like this should be one event for request and one for response.
  • I would expect that events should be at info. Debug events shouldn't need config in our yaml and can already be controlled via RUST_LOG or APOLLO_LOG. What'll happen is that users will configure this but the events won't make it to their APM unless they also set their log level to debug.

Copy link
Contributor

@garypen garypen left a comment

Choose a reason for hiding this comment

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

A lot of this looks great. I've got one extra question: What does the performance data look like for this change? And, not related to this change, but something I think about now and then, does our perf testing actually do any logging?

@bnjjj
Copy link
Contributor Author

bnjjj commented Nov 9, 2022

@gary We have logs enabled in our performance test. So after launching this on performance test it has no impact on the performance. BUT... the logging configuration is not set at all. One thing to keep in mind and also that was the main reason for me to write a tracing Layer is for example when it enters in the enabled method it will be called only one time for each callsite, it means only one time for each log tracing::info/debug/... in our code. If this method returns false it won't go back again in this method because this callsite has been disabled so it won't do the process again and again for each call. It's a little bit different for the on_event_enabled method because in this method we're looking at the value of the subgraph attribute.

bnjjj added 2 commits November 9, 2022 16:10
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
@bnjjj bnjjj requested review from Geal and garypen November 9, 2022 16:12
@bnjjj
Copy link
Contributor Author

bnjjj commented Nov 10, 2022

New configuration suggestion:

# Log every request, but this is never on by default.
logging:
  requests: true

# Explicitly on in --dev, documented as such.
# Also possible to just set it and have it on in production
logging:
  requests:
     with_header_present: apollo-router-log-request

## MAYBE

logging:
  requests:
     when_header_present: apollo-router-log-request
     request_headers: true
     request_body: true
     request_body: true

@bnjjj
Copy link
Contributor Author

bnjjj commented Nov 17, 2022

New suggestion #1998 (comment)

Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
@bnjjj bnjjj added the experimental Related to our experimental features/configurations label Nov 23, 2022
Copy link
Contributor

@garypen garypen left a comment

Choose a reason for hiding this comment

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

Approving, but I'd like to understand if there's a change in behaviour before merging.

Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
@bnjjj bnjjj merged commit f6e0ef8 into dev Nov 24, 2022
@bnjjj bnjjj deleted the bnjjj/feat_1998 branch November 24, 2022 15:15
garypen pushed a commit that referenced this pull request Nov 30, 2022
close #1998 

## Basic configuration

By default some logs containing sensible data (like request body,
response body, headers) are not displayed even if we set the right log
level.
For example if you need to display raw responses from one of your
subgraph it won't be displayed by default. To enable them you have to
configure it thanks to the `when_header` setting in the new section
`experimental_logging`. It let's you set different headers to enable
more logs (request/response headers/body for supergraph and subgraphs)
when the request contains these headers with corresponding values/regex.
Here is an example how you can configure it:

```yaml title="router.yaml"
telemetry:
  experimental_logging:
    format: json # By default it's "pretty" if you are in an interactive shell session
    display_filename: true # Display filename where the log is coming from. Default: true
    display_line_number: false # Display line number in the file where the log is coming from. Default: true
    # If one of these headers matches we will log supergraph and subgraphs requests/responses
    when_header:
      - name: apollo-router-log-request
        value: my_client
        headers: true # default: false
        body: true # default: false
      # log request for all requests coming from Iphones
      - name: user-agent
        match: ^Mozilla/5.0 (iPhone*
        headers: true
```

/!\ This PR also upgrade `tracing` (not to the latest version) because I
needed a fix.


Signed-off-by: Benjamin Coenen <5719034+bnjjj@users.noreply.github.com>
@bnjjj bnjjj mentioned this pull request Dec 5, 2022
@BrynCooke BrynCooke mentioned this pull request Dec 5, 2022
abernix pushed a commit that referenced this pull request May 24, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

component/logging experimental Related to our experimental features/configurations

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Logging configuration to enable/disable specific logs

4 participants