better logging documentation

[xenoterracide]

Describe the solution you'd like

Logging says there are 2 kinds of logging, basic and json. I can't find anything on how to configure this. I've also been looking for a way to log the full error even if the server doesn't emit it, and I can't find that either.

[Geal]

JSON logging activates automatically if the router is not running under a tty (so not started from an interactive terminal). To see the full errors, I thin you need this: https://www.apollographql.com/docs/router/configuration/subgraph-error-inclusion

[xenoterracide]

hmm... maybe it should be another issue, but I'd like to be able to change to basic logging directly. Running router in docker in a local development environment doesn't mean I want to read json.

[xenoterracide]

Also, I'm not sure if I want to propagate or not, but this error is kind of not useful in the logs, and hard to read because I"m not a machine ;)

iw-pm-backend-graphql-router-1  | {"timestamp":"2022-08-30T13:04:42.997104Z","level":"ERROR","fields":{"message":"Fetch error: HTTP fetch failed from 'users': HTTP fetch failed from 'redacted': redacted"},"target":"apollo_router::query_planner","span":{"graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"execution"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"","client_version":"","graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"supergraph"},{"graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"execution"}]}

[xenoterracide]

actually a little easier to read on here because my terminal isn't wrapping it... still doesn't appear to contain useful information though. I'm not sure if that's because the other server isn't returning any or what.

[Geal]

did you activate the option from : https://www.apollographql.com/docs/router/configuration/subgraph-error-inclusion ? it should replace the redacted with the actual information. Here it looks like the router cannot send a request to the subgraph, so you should check the URL indicated in the schema

[xenoterracide]

yes, I did (I think), and yes it's giving a 404... something is wrong in my DGS server, but that's a different problem. fetch failed isn't very useful. Trying to read these logs in docker compose is hard.

iw-pm-backend-graphql-router-1  | {"timestamp":"2022-08-30T13:19:46.467205Z","level":"INFO","fields":{"message":"list of plugins","plugin_details":"[(\"experimental.include_subgraph_errors\", \"apollo_router::plugins::include_subgraph_errors::IncludeSubgraphErrors\"), (\"apollo.csrf\", \"apollo_router::plugins::csrf::Csrf\"), (\"apollo.telemetry\", \"apollo_router::plugins::telemetry::Telemetry\")]"},"target":"apollo_router::router_factory"}
...
iw-pm-backend-graphql-router-1  | {"timestamp":"2022-08-30T16:43:09.813190Z","level":"INFO","fields":{"message":"redacted subgraph(users) error"},"target":"apollo_router::plugins::include_subgraph_errors","span":{"otel.kind":"internal","name":"fetch"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"","client_version":"","graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"supergraph"},{"graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"execution"},{"otel.kind":"internal","name":"fetch"}]}
iw-pm-backend-graphql-router-1  | {"timestamp":"2022-08-30T16:43:09.813708Z","level":"ERROR","fields":{"message":"Fetch error: HTTP fetch failed from 'users': HTTP fetch failed from 'redacted': redacted"},"target":"apollo_router::query_planner","span":{"graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"execution"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"","client_version":"","graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"supergraph"},{"graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"execution"}]}
iw-pm-backend-graphql-router-1  | {"timestamp":"2022-08-30T16:43:09.819912Z","level":"DEBUG","fields":{"message":"invalid type for data in response."},"target":"apollo_router::spec::query","span":{"name":"format_response"},"spans":[{"method":"POST","otel.kind":"server","otel.status_code":"","uri":"/","version":"HTTP/1.1","name":"request"},{"client_name":"","client_version":"","graphql.document":"query {\n\tusers(keys: \"0\") {\n\t\tname\n\t\trole\n\t}\n}","graphql.operation.name":"","otel.kind":"internal","name":"supergraph"},{"name":"format_response"}]}

the debug log is a little more useful

[rgoodwin]

One of the selling points of using this rust router is supposed to be a great out of the box experience. (Paraphrasing your teams presentation at your GraphQL conference). But it's not. Here are a few points.

1. There are not sensible defaults - nor full examples of sensible defaults. As an example most web and ingress type servers log http requests, and if they are proxies log bad requests to the back end. Or all responses.
2. There is no reference config file - Most products/tools that have a config file provide a fully commented config file with comments so it's easy to look through. And to know what values and defaults are available. While the doc is pretty its does not provide the clarity of a fully documented file. As well some full blown examples (say a debug, qa and production example) would help.
3. The log levels on startup and the logging setting in the config file are not unified. I turn on debug level logging and get a whole bunch of messages about DNS lookups. But, why not full request/response logging right there. For that I have to use the config file. It's just not all clear.
4. The logging levels do not provide useful output and are not calibrated. EX: see DNS lookups, i don't see failures.
5. The debug level should be split into developer debug and operational debug. Again with DNS seeing lookups is not operationally super useful - it would be great to see failures and calls to backends as an ops person.