Allow configuration of logging (tracing subscriber)

[hrkfdn]

Describe the solution you'd like Currently there is no way to configure the tracing_subscriber Subscriber implementation that's set up here: https://github.com/apollographql/router/blob/23d6a9fc479119e8c9cd4bc88383f81fb7efa337/apollo-router/src/executable.rs#L194-L213

There are limited configuration options using the environment variables support by tracing, but more specific changes are not possible. In our case we need a different structure for the JSON log output. It would be nice if the subscriber could be accessed/configured, at least when building a custom router binary.

Describe alternatives you've considered I've looked at the plugin API and compiling the router myself, but I can't access the Subscriber unless I reimplement all the set-up logic in executable.rs. Logger configuration via environment variables directives is also rather limited.

[Geal]

you can add your own subscriber by explicitely passing it to the telemetry plugin:

https://github.com/apollographql/router/blob/d0cab772501db3d8e3a3e0de07a3929968f640fd/apollo-router/tests/integration_tests.rs#L693-L715

[hrkfdn]

Hey @Geal, thanks for the suggestion.

you can add your own subscriber by explicitely passing it to the telemetry plugin:

Hmm, I don't see how, could you elaborate? Plugin implementations are not exported by the crate. Also, this would only affect log lines emitted by the Telemetry plugin and not the rest of the application, right?

[SimonSapin]

I’d much prefer if we can keep plugin instantiation within the Router, with (most) user control happening through YAML configuration.

I tried to make the relevant part of the Telemetry plugin instantiation look at a global OnceCell that would be settable beforehand by some other public API. We can store a Box<dyn Subscriber + Send + Sync> but I ran into difficulties representing the for<'span> LookupSpan<'span> bound that Telemetry also requires into a trait object.

[BrynCooke]

We should think about this when doing #2113

[yanns]

I’d much prefer if we can keep plugin instantiation within the Router, with (most) user control happening through YAML configuration.

I tried to make the relevant part of the Telemetry plugin instantiation look at a global OnceCell that would be settable beforehand by some other public API. We can store a Box<dyn Subscriber + Send + Sync> but I ran into difficulties representing the for<'span> LookupSpan<'span> bound that Telemetry also requires into a trait object.

Do you have any WIP branch about this? I could have a look.

[yanns]

It's not a perfect solution, but I found a way around this that I'd like to share if it helps others.

• first, use jsonlogging:

  telemetry:
  experimental_logging:
  format: json

  (this is done automatically in non-interactive terminals.)

• create file to use for jq to create the log entries you want: Example: config/log_filter.txt:

  {
  timestamp: .timestamp?,
  severity: (.level? | ascii_downcase),
  message: (.fields?.message? // .message?),
  my_field: (if has("spans") then .spans[] | select(.name? == "my_span") | .my_field? else null end),
  type: (.type? // "router")
  } | with_entries( select( .value != null ) )

  my_field is coming from my own span

• then I launch the router like this:

  ./federation-router | jq -R -c --unbuffered 'fromjson?' | jq -c -f config/log_filter.txt

  This first jq invocation makes sure to handle only json entries, and the second json invocation creates the log entries based on the file config/log_filter.txt.

This approach is a bit fragile. The json structure might change. The json format is experimental.

To make it a bit better, I've added some tests like:

    #[test]
    fn structured_log_contains_my_field() {
        let input = indoc! { r#"
        {
            "timestamp": "2023-03-22T15:37:00.745582Z",
            "level": "INFO",
            "message": "Here a beautiful message",
            "log.target": "...",
            "log.module_path": "...",
            "log.file": "...",
            "log.line": 221,
            "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": "/cornichon-0322-163659-159-0/graphql",
                    "otel.kind": "SERVER",
                    "name": "request"
                },
                {
                    "my_field": "abc",
                    "name": "my_span"
                },
                {
                    "apollo_private.field_level_instrumentation_ratio": 0.01,
                    "apollo_private.graphql.variables": "{}",
                    "graphql.document": "...",
                    "graphql.operation.name": "",
                    "otel.kind": "INTERNAL",
                    "name": "supergraph"
                }
            ]
        }
        "# };

        let json_entry = test_jq_expression(input);
        let expected = json!(
            {
                "timestamp": "2023-03-22T15:37:00.745582Z",
                "severity": "info",
                "message": "Here a beautiful message",
                "my_field": "abc",
                "type": "router"
            }
        );
        assert_json_eq!(json_entry, expected);
    }

    fn test_jq_expression(input: &str) -> Value {
        let process = Command::new("jq")
            .arg("-f")
            .arg("config/log_filter.txt")
            .stdin(Stdio::piped())
            .stdout(Stdio::piped())
            .spawn()
            .expect("jq fails to start");

        process
            .stdin
            .unwrap()
            .write_all(input.as_bytes())
            .expect("cannot send data to jq");

        let mut out = String::new();
        process
            .stdout
            .unwrap()
            .read_to_string(&mut out)
            .expect("cannot read data from jq");

        serde_json::from_str(&out).unwrap_or_else(|_| panic!("not a json: '{}'", &out))
    }

It's not perfect, but it allows to create my own json entries in the format I want.