From a86751e010fa6c1b8f27332bda40eb6e46069734 Mon Sep 17 00:00:00 2001 From: dandds Date: Tue, 2 Apr 2019 14:16:24 -0400 Subject: [PATCH 1/4] sample uWSGI logging - added source identifier to application logs - added toy NGINX/uWSGI setup in sample directory --- atst/utils/logging.py | 2 +- sample-config/Procfile | 2 ++ sample-config/nginx.conf | 50 ++++++++++++++++++++++++++++++++++++++++ sample-config/uwsgi.ini | 25 ++++++++++++++++++++ 4 files changed, 78 insertions(+), 1 deletion(-) create mode 100644 sample-config/Procfile create mode 100644 sample-config/nginx.conf create mode 100644 sample-config/uwsgi.ini diff --git a/atst/utils/logging.py b/atst/utils/logging.py index 1ef84d0a..a356c6d2 100644 --- a/atst/utils/logging.py +++ b/atst/utils/logging.py @@ -34,7 +34,7 @@ class JsonFormatter(logging.Formatter): ] def format(self, record): - message_dict = {} + message_dict = {"source": "atst"} for field, func in self._DEFAULT_RECORD_FIELDS: message_dict[field] = func(record) diff --git a/sample-config/Procfile b/sample-config/Procfile new file mode 100644 index 00000000..c25f1cb2 --- /dev/null +++ b/sample-config/Procfile @@ -0,0 +1,2 @@ +uwsgi: LOG_JSON=true DEBUG=false uwsgi --ini sample-config/uwsgi.ini +nginx: nginx -c $(pwd)/sample-config/nginx.conf diff --git a/sample-config/nginx.conf b/sample-config/nginx.conf new file mode 100644 index 00000000..7832c28a --- /dev/null +++ b/sample-config/nginx.conf @@ -0,0 +1,50 @@ +worker_processes 1; + +daemon off; + +error_log /dev/stdout; + +events { + worker_connections 1024; +} + +http { + default_type application/octet-stream; + log_format main '$remote_addr - $remote_user [$time_local] "$request" ' + '$status $body_bytes_sent "$http_referer" ' + '"$http_user_agent" "$http_x_forwarded_for"'; + + keepalive_timeout 65; + + server { + listen 8000; + server_name localhost; + + access_log /dev/stdout; + + location / { + try_files $uri @app; + } + + location @app { + uwsgi_pass uwsgi://localhost:8080; + uwsgi_param QUERY_STRING $query_string; + uwsgi_param REQUEST_METHOD $request_method; + uwsgi_param CONTENT_TYPE $content_type; + uwsgi_param CONTENT_LENGTH $content_length; + + uwsgi_param REQUEST_URI $request_uri; + uwsgi_param PATH_INFO $document_uri; + uwsgi_param DOCUMENT_ROOT $document_root; + uwsgi_param SERVER_PROTOCOL $server_protocol; + uwsgi_param REQUEST_SCHEME $scheme; + uwsgi_param HTTPS $https if_not_empty; + + uwsgi_param REMOTE_ADDR $remote_addr; + uwsgi_param REMOTE_PORT $remote_port; + uwsgi_param SERVER_PORT $server_port; + uwsgi_param SERVER_NAME $server_name; + uwsgi_param HTTP_X_REQUEST_ID $request_id; + } + } +} diff --git a/sample-config/uwsgi.ini b/sample-config/uwsgi.ini new file mode 100644 index 00000000..94ee919a --- /dev/null +++ b/sample-config/uwsgi.ini @@ -0,0 +1,25 @@ +[uwsgi] +; general uWSGI config for sample +callable = app +module = app +plugin = python3 +socket = localhost:8080 + +; logger config + +; application logs: log without modifying +logger = secondlogger stdio +log-route = secondlogger atst +log-encoder = format:secondlogger ${msg} + +; default uWSGI messages (start, stop, etc.) +logger = default stdio +log-route = default ^((?!atst).)*$ +log-encoder = json:default {"timestamp":"${strftime:%%FT%%T}","source":"uwsgi","severity":"DEBUG","message":"${msg}"} +log-encoder = nl + +; uWSGI request logs +logger-req = stdio +log-format = request_id=%(var.HTTP_X_REQUEST_ID), pid=%(pid), remote_add=%(addr), request=%(method) %(uri), status=%(status), body_bytes_sent=%(rsize), referer=%(referer), user_agent=%(uagent), http_x_forwarded_for=%(var.HTTP_X_FORWARDED_FOR) +log-req-encoder = json {"timestamp":"${strftime:%%FT%%T}","source":"req","severity":"INFO","message":"${msg}"} +log-req-encoder = nl From f72ec839a975bb5dd360b3dfff3516ac4ee10229 Mon Sep 17 00:00:00 2001 From: dandds Date: Tue, 2 Apr 2019 17:04:27 -0400 Subject: [PATCH 2/4] configure json logging for uwsgi in k8s environments --- deploy/kubernetes/atst-configmap.yml | 22 +++++++++++++++++++++- deploy/kubernetes/test/atst-configmap.yml | 22 +++++++++++++++++++++- deploy/kubernetes/test/test.yml | 4 ++-- deploy/kubernetes/uat/atst-configmap.yml | 22 +++++++++++++++++++++- sample-config/nginx.conf | 19 +++++++++++++++---- sample-config/uwsgi.ini | 1 + 6 files changed, 81 insertions(+), 9 deletions(-) diff --git a/deploy/kubernetes/atst-configmap.yml b/deploy/kubernetes/atst-configmap.yml index a9584fc5..79f9a61b 100644 --- a/deploy/kubernetes/atst-configmap.yml +++ b/deploy/kubernetes/atst-configmap.yml @@ -10,6 +10,26 @@ data: callable = app module = app socket = /var/run/uwsgi/uwsgi.socket - plugins = python3 + plugin = python3 + plugin = logfile virtualenv = /opt/atat/atst/.venv chmod-socket = 666 + + ; logger config + + ; application logs: log without modifying + logger = secondlogger stdio + log-route = secondlogger atst + log-encoder = format:secondlogger ${msg} + + ; default uWSGI messages (start, stop, etc.) + logger = default stdio + log-route = default ^((?!atst).)*$ + log-encoder = json:default {"timestamp":"${strftime:%%FT%%T}","source":"uwsgi","severity":"DEBUG","message":"${msg}"} + log-encoder = nl + + ; uWSGI request logs + logger-req = stdio + log-format = request_id=%(var.HTTP_X_REQUEST_ID), pid=%(pid), remote_add=%(addr), request=%(method) %(uri), status=%(status), body_bytes_sent=%(rsize), referer=%(referer), user_agent=%(uagent), http_x_forwarded_for=%(var.HTTP_X_FORWARDED_FOR) + log-req-encoder = json {"timestamp":"${strftime:%%FT%%T}","source":"req","severity":"INFO","message":"${msg}"} + log-req-encoder = nl diff --git a/deploy/kubernetes/test/atst-configmap.yml b/deploy/kubernetes/test/atst-configmap.yml index 54409d7d..30c64f29 100644 --- a/deploy/kubernetes/test/atst-configmap.yml +++ b/deploy/kubernetes/test/atst-configmap.yml @@ -10,6 +10,26 @@ data: callable = app module = app socket = /var/run/uwsgi/uwsgi.socket - plugins = python3 + plugin = python3 + plugin = logfile virtualenv = /opt/atat/atst/.venv chmod-socket = 666 + + ; logger config + + ; application logs: log without modifying + logger = secondlogger stdio + log-route = secondlogger atst + log-encoder = format:secondlogger ${msg} + + ; default uWSGI messages (start, stop, etc.) + logger = default stdio + log-route = default ^((?!atst).)*$ + log-encoder = json:default {"timestamp":"${strftime:%%FT%%T}","source":"uwsgi","severity":"DEBUG","message":"${msg}"} + log-encoder = nl + + ; uWSGI request logs + logger-req = stdio + log-format = request_id=%(var.HTTP_X_REQUEST_ID), pid=%(pid), remote_add=%(addr), request=%(method) %(uri), status=%(status), body_bytes_sent=%(rsize), referer=%(referer), user_agent=%(uagent), http_x_forwarded_for=%(var.HTTP_X_FORWARDED_FOR) + log-req-encoder = json {"timestamp":"${strftime:%%FT%%T}","source":"req","severity":"INFO","message":"${msg}"} + log-req-encoder = nl diff --git a/deploy/kubernetes/test/test.yml b/deploy/kubernetes/test/test.yml index 3c1c3bc0..82c64dd0 100644 --- a/deploy/kubernetes/test/test.yml +++ b/deploy/kubernetes/test/test.yml @@ -28,7 +28,7 @@ spec: fsGroup: 101 containers: - name: atst - image: registry.atat.codes:443/atst-prod:47ce80b4 + image: registry.atat.codes:443/atst-prod:575cfce5 resources: requests: memory: "2500Mi" @@ -155,7 +155,7 @@ spec: fsGroup: 101 containers: - name: atst-worker - image: registry.atat.codes:443/atst-prod:47ce80b4 + image: registry.atat.codes:443/atst-prod:575cfce5 args: ["/bin/bash", "-c", "/opt/atat/atst/script/rq_worker"] resources: requests: diff --git a/deploy/kubernetes/uat/atst-configmap.yml b/deploy/kubernetes/uat/atst-configmap.yml index f7a8a9ca..0482ea10 100644 --- a/deploy/kubernetes/uat/atst-configmap.yml +++ b/deploy/kubernetes/uat/atst-configmap.yml @@ -10,6 +10,26 @@ data: callable = app module = app socket = /var/run/uwsgi/uwsgi.socket - plugins = python3 + plugin = python3 + plugin = logfile virtualenv = /opt/atat/atst/.venv chmod-socket = 666 + + ; logger config + + ; application logs: log without modifying + logger = secondlogger stdio + log-route = secondlogger atst + log-encoder = format:secondlogger ${msg} + + ; default uWSGI messages (start, stop, etc.) + logger = default stdio + log-route = default ^((?!atst).)*$ + log-encoder = json:default {"timestamp":"${strftime:%%FT%%T}","source":"uwsgi","severity":"DEBUG","message":"${msg}"} + log-encoder = nl + + ; uWSGI request logs + logger-req = stdio + log-format = request_id=%(var.HTTP_X_REQUEST_ID), pid=%(pid), remote_add=%(addr), request=%(method) %(uri), status=%(status), body_bytes_sent=%(rsize), referer=%(referer), user_agent=%(uagent), http_x_forwarded_for=%(var.HTTP_X_FORWARDED_FOR) + log-req-encoder = json {"timestamp":"${strftime:%%FT%%T}","source":"req","severity":"INFO","message":"${msg}"} + log-req-encoder = nl diff --git a/sample-config/nginx.conf b/sample-config/nginx.conf index 7832c28a..07a63084 100644 --- a/sample-config/nginx.conf +++ b/sample-config/nginx.conf @@ -10,9 +10,20 @@ events { http { default_type application/octet-stream; - log_format main '$remote_addr - $remote_user [$time_local] "$request" ' - '$status $body_bytes_sent "$http_referer" ' - '"$http_user_agent" "$http_x_forwarded_for"'; + log_format json escape=json + '{' + '"timestamp":"$time_iso8601",' + '"msec":"$msec",' + '"request_id":"$request_id",' + '"remote_addr":"$remote_addr",' + '"remote_user":"$remote_user",' + '"request":"$request",' + '"status":$status,' + '"body_bytes_sent":$body_bytes_sent,' + '"referer":"$http_referer",' + '"user_agent":"$http_user_agent",' + '"http_x_forwarded_for":"$http_x_forwarded_for"' + '}'; keepalive_timeout 65; @@ -20,7 +31,7 @@ http { listen 8000; server_name localhost; - access_log /dev/stdout; + access_log /dev/stdout json; location / { try_files $uri @app; diff --git a/sample-config/uwsgi.ini b/sample-config/uwsgi.ini index 94ee919a..daf040bb 100644 --- a/sample-config/uwsgi.ini +++ b/sample-config/uwsgi.ini @@ -3,6 +3,7 @@ callable = app module = app plugin = python3 +plugin = stdio socket = localhost:8080 ; logger config From 09f58dc6cb349d82fc0649430c40e58105f297d8 Mon Sep 17 00:00:00 2001 From: dandds Date: Wed, 3 Apr 2019 06:24:08 -0400 Subject: [PATCH 3/4] set flask app instances to log json in k8s clusters --- deploy/kubernetes/atst-envvars-configmap.yml | 1 + deploy/kubernetes/test/atst-envvars-configmap.yml | 1 + deploy/kubernetes/uat/atst-envvars-configmap.yml | 1 + sample-config/Procfile | 2 -- sample-server/Procfile | 2 ++ {sample-config => sample-server}/nginx.conf | 0 {sample-config => sample-server}/uwsgi.ini | 0 7 files changed, 5 insertions(+), 2 deletions(-) delete mode 100644 sample-config/Procfile create mode 100644 sample-server/Procfile rename {sample-config => sample-server}/nginx.conf (100%) rename {sample-config => sample-server}/uwsgi.ini (100%) diff --git a/deploy/kubernetes/atst-envvars-configmap.yml b/deploy/kubernetes/atst-envvars-configmap.yml index 5e5a1fb1..39b09ad3 100644 --- a/deploy/kubernetes/atst-envvars-configmap.yml +++ b/deploy/kubernetes/atst-envvars-configmap.yml @@ -10,3 +10,4 @@ data: OVERRIDE_CONFIG_FULLPATH: /opt/atat/atst/atst-overrides.ini UWSGI_CONFIG_FULLPATH: /opt/atat/atst/uwsgi-config.ini CRL_STORAGE_PROVIDER: CLOUDFILES + LOG_JSON: "true" diff --git a/deploy/kubernetes/test/atst-envvars-configmap.yml b/deploy/kubernetes/test/atst-envvars-configmap.yml index 67f1d226..bc82c333 100644 --- a/deploy/kubernetes/test/atst-envvars-configmap.yml +++ b/deploy/kubernetes/test/atst-envvars-configmap.yml @@ -11,3 +11,4 @@ data: UWSGI_CONFIG_FULLPATH: /opt/atat/atst/uwsgi-config.ini RQ_QUEUES: atat-test CRL_STORAGE_PROVIDER: CLOUDFILES + LOG_JSON: "true" diff --git a/deploy/kubernetes/uat/atst-envvars-configmap.yml b/deploy/kubernetes/uat/atst-envvars-configmap.yml index e7afea02..7821b5c0 100644 --- a/deploy/kubernetes/uat/atst-envvars-configmap.yml +++ b/deploy/kubernetes/uat/atst-envvars-configmap.yml @@ -11,3 +11,4 @@ data: UWSGI_CONFIG_FULLPATH: /opt/atat/atst/uwsgi-config.ini RQ_QUEUES: atat-uat CRL_STORAGE_PROVIDER: CLOUDFILES + LOG_JSON: "true" diff --git a/sample-config/Procfile b/sample-config/Procfile deleted file mode 100644 index c25f1cb2..00000000 --- a/sample-config/Procfile +++ /dev/null @@ -1,2 +0,0 @@ -uwsgi: LOG_JSON=true DEBUG=false uwsgi --ini sample-config/uwsgi.ini -nginx: nginx -c $(pwd)/sample-config/nginx.conf diff --git a/sample-server/Procfile b/sample-server/Procfile new file mode 100644 index 00000000..a03656c7 --- /dev/null +++ b/sample-server/Procfile @@ -0,0 +1,2 @@ +uwsgi: LOG_JSON=true DEBUG=false uwsgi --ini sample-server/uwsgi.ini +nginx: nginx -c $(pwd)/sample-server/nginx.conf diff --git a/sample-config/nginx.conf b/sample-server/nginx.conf similarity index 100% rename from sample-config/nginx.conf rename to sample-server/nginx.conf diff --git a/sample-config/uwsgi.ini b/sample-server/uwsgi.ini similarity index 100% rename from sample-config/uwsgi.ini rename to sample-server/uwsgi.ini From 8ecd1bca3415c8c1be9aa654421a3798c087faa5 Mon Sep 17 00:00:00 2001 From: dandds Date: Wed, 3 Apr 2019 06:31:56 -0400 Subject: [PATCH 4/4] readme for sample server --- sample-server/README | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) create mode 100644 sample-server/README diff --git a/sample-server/README b/sample-server/README new file mode 100644 index 00000000..7e0407f4 --- /dev/null +++ b/sample-server/README @@ -0,0 +1,17 @@ +# Sample Server + +## Requirements + +- [nginx](https://www.nginx.com/resources/wiki/start/topics/tutorials/install/): On macos with homebrew, `brew install nginx` +- [uwsgi](https://uwsgi-docs.readthedocs.io/en/latest/Install.html): With python, `pip install uwsgi`. +- pipenv and honcho: If you have the regular atst dependencies installed, you already have pipenv and honcho + +## Run + +The sample server runs at localhost:8000, so you cannot have another copy of the app running on that port. + +Start both NGINX and uWSGI with honcho: + +``` +pipenv run honcho start -f sample-server/Procfile +```