MPP-3777 - Tune logs for Google Cloud Profiler

[jwhitlock]

The Google Cloud Profiler (GCP) creates a root logger with the standard configuration, if no existing root logger exists. This logger will output a standard log line to stderr, like:

INFO:request.summary:

In production, anything sent to stderr is treated as an error.

This adds a root logger that uses the Mozlog format, so that GCP and other 3rd-party package loggers will use JSON logging to stderr by default.

This also sets "propagate": False on our loggers, to avoid two logs for each log call.

How to test

Set these environment variables, for example in .env:

GOOGLE_APPLICATION_CREDENTIALS="gcp_key.json"
GOOGLE_CLOUD_PROFILER_CREDENTIALS_B64="e30K"
RELAY_CHANNEL=dev

On main, when you run ./manage.py runserver, you should see messages like:

WARNING:google.auth.compute_engine._metadata:Compute Engine Metadata server unavailable on attempt 1 of 3. Reason: [Errno 64] Host is down
WARNING:google.auth.compute_engine._metadata:Compute Engine Metadata server unavailable on attempt 2 of 3. Reason: [Errno 64] Host is down
WARNING:google.auth.compute_engine._metadata:Compute Engine Metadata server unavailable on attempt 3 of 3. Reason: [Errno 64] Host is down
WARNING:google.auth._default:Authentication failed using Compute Engine authentication due to unavailable metadata server.
exception DefaultCredentialsError('Your default credentials were not found. To set up Application Default Credentials, see https://cloud.google.com/docs/authentication/external/set-up-adc for more information.') while starting google cloud profiler with key file: gcp_key.json
Performing system checks...

When you visit http://127.0.0.1:8000/, you'll see paired log messages:

{"Timestamp": 1711486062979428096, "Type": "request.summary", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45668, "Fields": {"errno": 0, "agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0", "lang": "en-US,en;q=0.5", "method": "GET", "path": "/api/v1/profiles/", "uid": "", "rid": "d61d97a4-a5ac-4a14-ad6e-a6af89f5b417", "t": 0}}
INFO:request.summary:
{"Timestamp": 1711486062979954944, "Type": "request.summary", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45668, "Fields": {"errno": 0, "agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0", "lang": "en-US,en;q=0.5", "method": "GET", "path": "/api/v1/users/", "uid": "", "rid": "429146f4-9afb-4e23-856c-de82f11b1972", "t": 0}}
INFO:request.summary:
{"Timestamp": 1711486063088260096, "Type": "eventsinfo", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45668, "Fields": {"accept_lang": "en-US,en;q=0.5", "accept_lang_region": "US", "region_method": "accept_lang", "region": "US", "msg": "region_details"}}
INFO:eventsinfo:region_details
{"Timestamp": 1711486063088568064, "Type": "request.summary", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45668, "Fields": {"errno": 0, "agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0", "lang": "en-US,en;q=0.5", "method": "GET", "path": "/api/v1/runtime_data", "uid": "", "rid": "78dec5f9-1411-46c6-a9de-43875302a401", "t": 108}}
INFO:request.summary:

The INFO:request.summary: lines are added by the Google Cloud Provider setup, which changes the logging configuration.

On this branch (tune-logs-for-google-cloud-profiler-mpp-3777), when you run ./manage.py runserver, you should see messages like:

{"Timestamp": 1711486214341404928, "Type": "google.auth.compute_engine._metadata", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 4, "Pid": 45759, "Fields": {"msg": "Compute Engine Metadata server unavailable on attempt 1 of 3. Reason: [Errno 64] Host is down"}}
{"Timestamp": 1711486214342242048, "Type": "google.auth.compute_engine._metadata", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 4, "Pid": 45759, "Fields": {"msg": "Compute Engine Metadata server unavailable on attempt 2 of 3. Reason: [Errno 64] Host is down"}}
{"Timestamp": 1711486214342541056, "Type": "google.auth.compute_engine._metadata", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 4, "Pid": 45759, "Fields": {"msg": "Compute Engine Metadata server unavailable on attempt 3 of 3. Reason: [Errno 64] Host is down"}}
{"Timestamp": 1711486214342597120, "Type": "google.auth._default", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 4, "Pid": 45759, "Fields": {"msg": "Authentication failed using Compute Engine authentication due to unavailable metadata server."}}
exception DefaultCredentialsError('Your default credentials were not found. To set up Application Default Credentials, see https://cloud.google.com/docs/authentication/external/set-up-adc for more information.') while starting google cloud profiler with key file: gcp_key.json
Performing system checks...

When you visit http://127.0.0.1:8000/, the second log lines are missing:

{"Timestamp": 1711486242816915968, "Type": "request.summary", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45759, "Fields": {"errno": 0, "agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0", "lang": "en-US,en;q=0.5", "method": "GET", "path": "/api/v1/profiles/", "uid": "", "rid": "1c179626-fa80-47c4-838e-80352a789010", "t": 1}}
{"Timestamp": 1711486242819543040, "Type": "request.summary", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45759, "Fields": {"errno": 0, "agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0", "lang": "en-US,en;q=0.5", "method": "GET", "path": "/api/v1/users/", "uid": "", "rid": "fe607f4b-d195-4628-8599-3899693f48f9", "t": 0}}
{"Timestamp": 1711486242927428096, "Type": "eventsinfo", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45759, "Fields": {"accept_lang": "en-US,en;q=0.5", "accept_lang_region": "US", "region_method": "accept_lang", "region": "US", "msg": "region_details"}}
{"Timestamp": 1711486242927819008, "Type": "request.summary", "Logger": "fx-private-relay", "Hostname": "jwhitlock-MB-M2.local", "EnvVersion": "2.0", "Severity": 6, "Pid": 45759, "Fields": {"errno": 0, "agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.15; rv:126.0) Gecko/20100101 Firefox/126.0", "lang": "en-US,en;q=0.5", "method": "GET", "path": "/api/v1/runtime_data", "uid": "", "rid": "37bd0b7d-72d8-4461-b4ec-1f84d3c0b365", "t": 110}}

[jwhitlock]

This breaks tests because pytest's caplog attaches to the root logger. There are some work-arounds in pytest-dev/pytest#3697. I'm putting in draft until I figure out how to proceed.

[jwhitlock]

I used IN_PYTEST to turn log propagation back on. It isn't my favorite solution, but it works.

[say-yawn]

Changes LGTM. John also paired with me to show how he debugged and it was very cool.