Merge pull request #740 from dod-ccpo/uwsgi-logging

uWSGI JSON logging

atst/utils/logging.py

@@ -35,7 +35,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)
 

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

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"

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

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"

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:

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

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"

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

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
+```

sample-server/nginx.conf

@@ -0,0 +1,61 @@
+worker_processes  1;
+
+daemon off;
+
+error_log  /dev/stdout;
+
+events {
+    worker_connections  1024;
+}
+
+http {
+    default_type  application/octet-stream;
+    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;
+
+    server {
+        listen       8000;
+        server_name  localhost;
+
+        access_log /dev/stdout json;
+
+        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;
+        }
+    }
+}

sample-server/uwsgi.ini

@@ -0,0 +1,26 @@
+[uwsgi]
+; general uWSGI config for sample
+callable = app
+module = app
+plugin = python3
+plugin = stdio
+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