Switch to structlog to fix logging under gunicorn #203
Conversation
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
colorama could be a dev-only dependency, but I've ended up missing it when running scripts manually in deployment environments.
Instead of duplicating metrics logic inside and outside the exception handler, use finally to populate metrics once.
Silence the uvicorn per-request logs. In the renamed log_request_middleware, gather the data from the request before sending to FastAPI, and then gather the rest from the response, and send as a metric and a log "ctms.web".
jwhitlock
requested review from
imbstack and
bsieber-mozilla
and removed request for
a team
| @@ -38,6 +38,8 @@ sentry-sdk = "^1.0.0" | |||
| pysilverpop = "^0.2.6" | |||
| lxml = "^4.6.3" | |||
| prometheus-client = "^0.10.1" | |||
| structlog = "^21.1.0" | |||
| colorama = "^0.4.4" | |||
There was a problem hiding this comment.
this enables some colorization for output, I'm interested how this plays with the structlog for console outputting.
jwhitlock
commented
May 11, 2021
| logging_config = { | ||
| "version": 1, | ||
| "disable_existing_loggers": False, | ||
| "formatters": { | ||
| "dev_console": { | ||
| "format": "%(asctime)s %(levelname)s:%(name)s: %(message)s" | ||
| "()": structlog.stdlib.ProcessorFormatter, | ||
| "processor": structlog.dev.ConsoleRenderer(colors=True), |
There was a problem hiding this comment.
@bsieber-mozilla - colorized logs, with colorama, are used when the dev_console logger is used. This is the default for development. There's no color option for the Mozlog JSON logs.
Merged
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.
This suggestion is invalid because no changes were made to the code.
Suggestions cannot be applied while the pull request is closed.
Suggestions cannot be applied while viewing a subset of changes.
Only one suggestion per line can be applied in a batch.
Add this suggestion to a batch that can be applied as a single commit.
Applying suggestions on deleted lines is not supported.
You must change the existing code in this line in order to create a valid suggestion.
Outdated suggestions cannot be applied.
This suggestion has been applied or marked resolved.
Suggestions cannot be applied from pending reviews.
Suggestions cannot be applied on multi-line comments.
Suggestions cannot be applied while the pull request is queued to merge.
Suggestion cannot be applied right now. Please check back later.
Implement web request logging in structlog with logger
ctms.web, so that logs will be consistent between the development environment and running under gunicorn in stage and production. This should fix #169.This drops the
UvicornJsonLogFormatter, which was not being used when run undergunicorn. Instead, the now-duplicate uvicorn access logs are silenced by raising the minimal level toWARNING.The data gathering is adjusted, to remove some duplication in the error handler, and to move request processing from metrics to logging, so that metrics works from the logging context rather than the
Requestitself.In the dev environment, with
make build start, logs for a request to http://localhost:8000/ (root, then redirect to docs) look like this (but with color):web_1 | INFO: Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit) web_1 | INFO: Started reloader process [10] using watchgod web_1 | INFO: Started server process [12] web_1 | INFO: Waiting for application startup. web_1 | INFO: Application startup complete. web_1 | 2021-05-11T16:42:39.451813Z [info ] 172.18.0.1:63292 - 'GET / HTTP/1.1' 307 [ctms.web] client_host=172.18.0.1 duration_s=0.003 headers={'host': 'localhost:8000', 'accept': 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8', 'upgrade-insecure-requests': '1', 'cookie': '[OMITTED]', 'user-agent': 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15', 'accept-language': 'en-us', 'accept-encoding': 'gzip, deflate', 'connection': 'keep-alive'} method=GET path=/ path_template=/ status_code=307 web_1 | 2021-05-11T16:42:39.481684Z [info ] 172.18.0.1:63292 - 'GET /docs HTTP/1.1' 200 [ctms.web] client_host=172.18.0.1 duration_s=0.001 headers={'host': 'localhost:8000', 'accept': 'text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8', 'upgrade-insecure-requests': '1', 'cookie': '[OMITTED]', 'user-agent': 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15', 'accept-language': 'en-us', 'accept-encoding': 'gzip, deflate', 'connection': 'keep-alive'} method=GET path=/docs path_template=/docs status_code=200 web_1 | 2021-05-11T16:42:39.777192Z [info ] 172.18.0.1:63292 - 'GET /openapi.json HTTP/1.1' 200 [ctms.web] client_host=172.18.0.1 duration_s=0.004 headers={'host': 'localhost:8000', 'accept': 'application/json,*/*', 'connection': 'keep-alive', 'cookie': '[OMITTED]', 'user-agent': 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15', 'accept-language': 'en-us', 'referer': 'http://localhost:8000/docs', 'accept-encoding': 'gzip, deflate'} method=GET path=/openapi.json path_template=/openapi.json status_code=200If you set
CTMS_USE_MOZLOG=Truein.env, the development logs look like this:web_1 | INFO: Uvicorn running on http://0.0.0.0:8000 (Press CTRL+C to quit) web_1 | INFO: Started reloader process [10] using watchgod web_1 | INFO: Started server process [12] web_1 | INFO: Waiting for application startup. web_1 | {"Timestamp": 1620751426233834496, "Type": "uvicorn.error", "Logger": "ctms", "Hostname": "b3598ac894b2", "EnvVersion": "2.0", "Severity": 6, "Pid": 12, "Fields": {"msg": "Application startup complete."}} web_1 | {"Timestamp": 1620751431891751680, "Type": "ctms.web", "Logger": "ctms", "Hostname": "b3598ac894b2", "EnvVersion": "2.0", "Severity": 6, "Pid": 12, "Fields": {"client_host": "172.18.0.1", "method": "GET", "path": "/", "path_template": "/", "headers": {"host": "localhost:8000", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8", "upgrade-insecure-requests": "1", "cookie": "[OMITTED]", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15", "accept-language": "en-us", "accept-encoding": "gzip, deflate", "connection": "keep-alive"}, "status_code": 307, "duration_s": 0.004, "msg": "172.18.0.1:63298 - 'GET / HTTP/1.1' 307"}} web_1 | {"Timestamp": 1620751431934572032, "Type": "ctms.web", "Logger": "ctms", "Hostname": "b3598ac894b2", "EnvVersion": "2.0", "Severity": 6, "Pid": 12, "Fields": {"client_host": "172.18.0.1", "method": "GET", "path": "/docs", "path_template": "/docs", "headers": {"host": "localhost:8000", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8", "upgrade-insecure-requests": "1", "cookie": "[OMITTED]", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15", "accept-language": "en-us", "accept-encoding": "gzip, deflate", "connection": "keep-alive"}, "status_code": 200, "duration_s": 0.001, "msg": "172.18.0.1:63298 - 'GET /docs HTTP/1.1' 200"}} web_1 | {"Timestamp": 1620751432153923584, "Type": "ctms.web", "Logger": "ctms", "Hostname": "b3598ac894b2", "EnvVersion": "2.0", "Severity": 6, "Pid": 12, "Fields": {"client_host": "172.18.0.1", "method": "GET", "path": "/openapi.json", "path_template": "/openapi.json", "headers": {"host": "localhost:8000", "accept": "application/json,*/*", "connection": "keep-alive", "cookie": "[OMITTED]", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15", "accept-language": "en-us", "referer": "http://localhost:8000/docs", "accept-encoding": "gzip, deflate"}, "status_code": 200, "duration_s": 0.002, "msg": "172.18.0.1:63298 - 'GET /openapi.json HTTP/1.1' 200"}}Finally, if you set
target: productionindocker-compose.yml, and runmake build start, the logs will look like they will in stage and production:web_1 | {"loglevel": "info", "workers": 6, "bind": "0.0.0.0:8000", "graceful_timeout": 120, "timeout": 120, "keepalive": 5, "errorlog": "-", "accesslog": "-", "workers_per_core": 1.0, "use_max_workers": null, "host": "0.0.0.0", "port": "8000"} web_1 | [2021-05-11 16:48:14 +0000] [12] [INFO] Starting gunicorn 20.1.0 web_1 | [2021-05-11 16:48:14 +0000] [12] [INFO] Listening at: http://0.0.0.0:8000 (12) web_1 | [2021-05-11 16:48:14 +0000] [12] [INFO] Using worker: uvicorn.workers.UvicornWorker web_1 | [2021-05-11 16:48:14 +0000] [14] [INFO] Booting worker with pid: 14 web_1 | [2021-05-11 16:48:14 +0000] [15] [INFO] Booting worker with pid: 15 web_1 | [2021-05-11 16:48:14 +0000] [16] [INFO] Booting worker with pid: 16 web_1 | [2021-05-11 16:48:14 +0000] [17] [INFO] Booting worker with pid: 17 web_1 | [2021-05-11 16:48:14 +0000] [18] [INFO] Booting worker with pid: 18 web_1 | [2021-05-11 16:48:14 +0000] [19] [INFO] Booting worker with pid: 19 web_1 | [2021-05-11 16:48:16 +0000] [14] [INFO] Started server process [14] web_1 | [2021-05-11 16:48:16 +0000] [14] [INFO] Waiting for application startup. web_1 | [2021-05-11 16:48:16 +0000] [15] [INFO] Started server process [15] web_1 | [2021-05-11 16:48:16 +0000] [15] [INFO] Waiting for application startup. web_1 | [2021-05-11 16:48:16 +0000] [16] [INFO] Started server process [16] web_1 | [2021-05-11 16:48:16 +0000] [16] [INFO] Waiting for application startup. web_1 | [2021-05-11 16:48:16 +0000] [18] [INFO] Started server process [18] web_1 | [2021-05-11 16:48:16 +0000] [18] [INFO] Waiting for application startup. web_1 | [2021-05-11 16:48:16 +0000] [17] [INFO] Started server process [17] web_1 | [2021-05-11 16:48:16 +0000] [17] [INFO] Waiting for application startup. web_1 | {"Timestamp": 1620751696543665920, "Type": "uvicorn.error", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 14, "Fields": {"msg": "Application startup complete."}} web_1 | [2021-05-11 16:48:16 +0000] [19] [INFO] Started server process [19] web_1 | [2021-05-11 16:48:16 +0000] [19] [INFO] Waiting for application startup. web_1 | {"Timestamp": 1620751696671503872, "Type": "uvicorn.error", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 15, "Fields": {"msg": "Application startup complete."}} web_1 | {"Timestamp": 1620751696672651776, "Type": "uvicorn.error", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 16, "Fields": {"msg": "Application startup complete."}} web_1 | {"Timestamp": 1620751696997040128, "Type": "uvicorn.error", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 18, "Fields": {"msg": "Application startup complete."}} web_1 | {"Timestamp": 1620751697056656896, "Type": "uvicorn.error", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 19, "Fields": {"msg": "Application startup complete."}} web_1 | {"Timestamp": 1620751697065201408, "Type": "uvicorn.error", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 17, "Fields": {"msg": "Application startup complete."}} web_1 | {"Timestamp": 1620751709990533120, "Type": "ctms.web", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 17, "Fields": {"client_host": "172.18.0.1", "method": "GET", "path": "/", "path_template": "/", "headers": {"host": "localhost:8000", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8", "upgrade-insecure-requests": "1", "cookie": "[OMITTED]", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15", "accept-language": "en-us", "accept-encoding": "gzip, deflate", "connection": "keep-alive"}, "status_code": 307, "duration_s": 0.002, "msg": "172.18.0.1:63774 - 'GET / HTTP/1.1' 307"}} web_1 | {"Timestamp": 1620751709999061760, "Type": "ctms.web", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 17, "Fields": {"client_host": "172.18.0.1", "method": "GET", "path": "/docs", "path_template": "/docs", "headers": {"host": "localhost:8000", "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8", "upgrade-insecure-requests": "1", "cookie": "[OMITTED]", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15", "accept-language": "en-us", "accept-encoding": "gzip, deflate", "connection": "keep-alive"}, "status_code": 200, "duration_s": 0.001, "msg": "172.18.0.1:63774 - 'GET /docs HTTP/1.1' 200"}} web_1 | {"Timestamp": 1620751710080756992, "Type": "ctms.web", "Logger": "ctms", "Hostname": "60ac2aea8b5d", "EnvVersion": "2.0", "Severity": 6, "Pid": 17, "Fields": {"client_host": "172.18.0.1", "method": "GET", "path": "/openapi.json", "path_template": "/openapi.json", "headers": {"host": "localhost:8000", "accept": "application/json,*/*", "connection": "keep-alive", "cookie": "[OMITTED]", "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/605.1.15 (KHTML, like Gecko) Version/14.1 Safari/605.1.15", "accept-language": "en-us", "referer": "http://localhost:8000/docs", "accept-encoding": "gzip, deflate"}, "status_code": 200, "duration_s": 0.003, "msg": "172.18.0.1:63774 - 'GET /openapi.json HTTP/1.1' 200"}}