Logging request info with Apollo Router

[marc-barry]

We are migrating from Apollo Server to Apollo Router. With Server we have pretty exhaustive logging about subgraph requests and other details. But switching to Apollo Router it appears we don't even get request logs. The documentation for logging isn't super intuitive as it seems to lead one to believe that log output can be customized. Even when navigating to and reading https://www.apollographql.com/docs/router/configuration/logging/#json-formatted-logging I cannot figure out how to enable json formatted logs.

In any regard, it would be super helpful for us to get some parity for logging which is closer to what we have today. Something like logging operation_name, subgraph and status would be a start. That is what it outputs for Prometheus metrics. Does anyone know if there is any way to get request logs out of Router?

[marc-barry]

I'm wondering if providing something like "apollo_router=info,router=info,apollo_router_core=info,apollo_spaceport=info,tower_http=info,reqwest_tracing=info" for APOLLO_ROUTER_LOG would work. I'm trying to follow how https://docs.rs/env_logger/latest/env_logger/ actually works with having zero Rust experience.

[bnjjj]

This discussion might be related to #1840 we will add more configuration options for logging in the future. Feel free to give ideas or feedback about what you liked in the gateway and also what you would like to have. But we definitely want to improve the logging experience

[bnjjj]

Actually to do this you are already able to do it just by writing a rhai script https://www.apollographql.com/docs/router/customizations/rhai-api/#entry-point-hooks on the supergraph.map_response you're able to rewrite the GraphQL response and so the errors.

[bnjjj]

Also you can also take a look at these subtasks I created about logging #1981 and #1998 feel free to give feedback and ask for more if needed.
cc @marc-barry

[agwisniewska]

ok, thanks for your help. Am I able to use nodejs function (custom logger) somehow inside the .rhai script? Or only those ?

[bnjjj]

No, only those listed in the rhai example you provided.

[bnjjj]

@marc-barry Could you tell me which log level do you set in production for your gateway ?

[marc-barry]

At this time there is no way to control the logging of Apollo Router at a finer granularity than what is provided out of the box. One could build a custom Apollo Router and modify the code base but this is challenging for small teams and those who don't have in-house Rust development skills. The best thing one can do is track issues like #1840 and/or labels like component/logging .

[Meemaw]

One common usecase for more thorough logging is logging subgraph error responses. Currently, its very "hard/weird" to achieve that, as when_header configuration seems to focus mostly for the incoming requests, and not so much on the responses.

I propose something along these lines:

when_error:
   body: true
   ...

[Meemaw]

This would still require some custom header to be introduced to all clients?

Would like to simply log body for all subgraph error responses.

[osamra-rbi]

Agreed with @Meemaw
Don't want to have to do any weird header stuff here, just want simple error logging from the subgraphs

[bnjjj]

You don't need to add specific headers to your clients to achieve that. Actually if you want to enable it for all request you can just use the header origin and match on ˋ.*` and you will enable these logs for every requests

[Meemaw]

That would work. It's a bit weird API, but assuming it's easier to maintain for you.

[osamra-rbi]

You don't need to add specific headers to your clients to achieve that. Actually if you want to enable it for all request you can just use the header origin and match on ˋ.*` and you will enable these logs for every requests

Ah true, I guess this is fine then

[lleadbet]

One addition that would be nice is the ability to not only set the value of the logged information, but the loglevel as well- for example, if the header of User-Agent showing an iPhone might be a DEBUG statement vs. INFO, and errors shown as, well, ERROR.

[marc-barry]

We have enabled Apollo Router logging with the following configuration:

telemetry:
  experimental_logging:
    format: json # By default it's "pretty"
    when_header:
      - name: user-agent
        match: .*
        headers: true
        body: false

This pretty much logs everything. But one problem we have is that it is logging our auth headers as well. I'd prefer to not log that single header and also not log cookie. I can't seem to figure out how to filter certain headers from logging. It seems all or nothing.

[bnjjj]

Yes, we don't have option to redact specific headers. We think that this feature is mostly useful for debugging, not something you should always enable. What's your usecase ?

[marc-barry]

We have logging of request start/stop in Apollo Server which has data like trace-identifier, status, subgraph and operation_name. The sub-graphs and operation names are owned by different teams. We develop a holistic observability view from the data which links together logs, metrics and tracing. Thus, when there is a problem in the system we can easily identify the team, alert the team and determine which part of the backend systems has issues. Observability is really about the three pillars of logs, metrics and traces and thus to build an observable system with good operational characteristics you really all of them.

We know very little about Rust and Rhai and so we are investigating whether it is possible for us to build the above functionality discussed above or if we simply have to stick with Apollo Server due to the ease of customization it affords us (i.e. a language ecosystem we have developers within).

[carldunham]

What about filtering out introspection queries (or filtering in/out by operation name)? This type of logging is most useful during development and troubleshooting, and that often means the sandbox, which can be chatty.

[thrawny]

When logging from a rust plugin, is it possible to not have the log output include so much extra data? For example the full query body that gets added in the field “graphql.document”. Good to have the option to keep log lines really tight.

tracing::info!("hello");

{
  "timestamp": "2023-05-04T09:07:04.549535Z",
  "level": "INFO",
  "message": "hello",
  "span": {
    "apollo_private.field_level_instrumentation_ratio": 0.01,
    "apollo_private.graphql.variables": "...",
    "graphql.document": "...",
    "graphql.operation.name": "...",
    "otel.kind": "INTERNAL",
    "name": "supergraph"
  },
  "spans": [
    {
      "http.flavor": "HTTP/1.1",
      "http.method": "POST",
      "http.route": "/",
      "otel.kind": "SERVER",
      "name": "request"
    },
    {
      "apollo_private.http.request_headers": "{}",
      "client.name": "jonas",
      "client.version": "",
      "http.flavor": "HTTP/1.1",
      "http.method": "POST",
      "http.route": "/",
      "otel.kind": "INTERNAL",
      "trace_id": "0ae619c191850a762fadf23da2c28abb",
      "name": "router"
    },
    {
      "apollo_private.field_level_instrumentation_ratio": 0.01,
      "apollo_private.graphql.variables": "...",
      "graphql.document": "...",
      "graphql.operation.name": "...",
      "otel.kind": "INTERNAL",
      "name": "supergraph"
    }
  ]
}

[WolffRuoff]

This extra data is also included when using log_error in custom Rhai scripts which is flooding our logs. We would really appreciate a way to exclude it 🙂

[glasser]

A simple way to enable JSON-formatted logs for now is to make stdout not be a tty by running router | cat.

[bnjjj]

You don't need to do that, you can just configure it in the configuration file using format in that example https://www.apollographql.com/docs/router/configuration/logging#basic-configuration

[glasser]

Ah thanks; I was avoiding "experimental_" but that probably wasn't necessary!

[dbarranco]

hey!
I've been taking a look at the logging related documentation for a couple of days and I think I am unable to achieve what I wanted to do with Apollo Router for my production environment.

In our production environment, we have Envoy configuring the X-Request-ID HTTP header automatically when a new request is passed through. Nowadays I'm configuring Apollo Router to pass that HTTP header to the different subgraphs we have, which works fine.

My use case would be that I'd like to make Apollo Router to log, in a JSON structured format, a field with request_id: <request-id-value> so I could leverage some features from the observability tool we're using so we can just filter logs from our production services with request_id: <request-id-value>.

At the moment, I've tried to:

1. Add a Rhai script to add that HTTP header into the logs, although for the JSON structured logging the actual values will be added under the message log field:

{"timestamp":"2023-11-15T16:08:15.965193Z","level":"INFO","message":"request_id: xxxxxx-....`

Which does not really work for our use case, I'd expect to see:

{"timestamp":"2023-11-15T16:08:15.965193Z","level":"INFO","request_id":"xxxxxx-`, "message":" . . ."

2. Tried to follow the Apollo Router tracing, although I wasn't able to get nothing working from there.

---

We haven't really got yet into tracing, so nowadays we're just trying to aggregate all logs related to a single user request in production :/

@marc-barry do you think this makes sense?
Is there anything on our side we could try?

[bnjjj]

Ok right now we're working on that PR which will let you add any span attributes you want and so it will also be included in logs. It can be something coming from headers, something static, something from context... So it will answer your issue. We plan to merge that PR this week so might be available in a stable release in few weeks. Does it sound good to you ?

[danpayne17]

Looks like telemetry.experimental_logging.when_header was removed from 1.35.0 of the router? Is this feature going to be re-introduced or do we need to replicate its behavior ourselves with Rhai script?

[bnjjj]

It has been moved to another section:

telemetry:
  exporters:
    logging:
      experimental_when_header:
        - name: "content-type"
          match: ".*"
          headers: true
          body: true

but it's not documented. I'll create an issue for that

[danpayne17]

Love this feature. Would be nice if we had a little more granularity to be able to exclude certain headers from getting logged. For example, our JWT tokens are really large so it would be nice to log them once for the supergraph headers but then exclude them from subgraph header logging.