Make it easy to emit JSON structured logging to stdout for Python apps and WSGI apps running inside Gunicorn. Is geared toward deployment on Kubernetes, but can be used without Kube or Gunicorn.

revsys revsys Last update: May 21, 2021

jslog4kube (python/JSON logging for kubernetes pod/containers)

Why?

  • provide a JSON-to-stdout setup for python
  • provide the same JSON-to-stdout setup for gunicorn
  • because creating complex log collector configs to handle whateverthat other person thought was a good-idea-at-the-time is for the birds.

We want to make it easier for our clients and ourselves to start new projectsthat emit good logging.

making it go

Two environment variables configure this module:

  • KUBE_META: specifies the mount-point for the Kubernetes downward-APIvolumes bits (default: /etc/meta)
  • KUBE_META_ENV_PREFIX: the textual prefix for anyenvironment variablestargetted for inclusion in this pod’s log records (default: X)


These bits have been verified to be functional under python 2.7.13, 3.5.3 and 3.6.1


from logging.config import dictConfigfrom jslog4kube import LOGGINGdictConfig(LOGGING)

From Django

project settings.py

from jslog4kube import LOGGING

gunicorn

gunicorn.conf

access_log_format = 'remote!%({X-Forwarded-For}i)s|method!%(m)s|url-path!%(U)s|query!%(q)s|username!%(u)s|protocol!%(H)s|status!%(s)s|response-length!%(b)s|referrer!%(f)s|user-agent!%(a)s|request-time!%(L)s'accesslog = '-'logger_class = 'jslog4kube.GunicornLogger'

gunicorn CLI

gunicorn -c /path/to/gunicorn.conf [rest of your options here]

This will produce the following kind of output:

{  "asctime": "2017-07-12 16:07:34,624",  "message": "Booting worker with pid: 6801",  "name": "gunicorn.error",  "created": 1499893654.6243172,  "filename": "glogging.py",  "module": "glogging",  "funcName": "info",  "lineno": 247,  "msecs": 624.3171691894531,  "pathname": "/home/gladiatr/.virtualenvs/json-logs-for-kube/lib/python3.6/site-packages/gunicorn/glogging.py",  "process": 6801,  "processName": "MainProcess",  "relativeCreated": 70.62673568725586,  "thread": 140275859264576,  "threadName": "MainThread",  "levelname": "INFO",  "x_node_name": "ip-10-70-59-190.eu-central-1.compute.internal",  "x_sa_name": "default",  "x_pod_ip": "100.96.1.11",  "build": "5000",  "builder": "Stephen Spencer",  "image": "gladiatr72/kube-demo",  "version": "1.0.2",  "app": "kube-demo",  "env": "dev",  "pod-template-hash": "2802633501",  "something": "else"}{  "asctime": "2017-07-12 21:08:16,354",  "message": "in view: Chameleon",  "name": "efk.views",  "created": 1499893696.3544216,  "filename": "views.py",  "module": "views",  "funcName": "Chameleon",  "lineno": 12,  "msecs": 354.42161560058594,  "pathname": "/home/gladiatr/git/json-logs-for-kube/demo/efk/views.py",  "process": 6800,  "processName": "MainProcess",  "relativeCreated": 41800.73118209839,  "thread": 140275726399232,  "threadName": "<concurrent.futures.thread.ThreadPoolExecutor object at 0x7f947f4b0828>_0",  "levelname": "INFO",  "x_node_name": "ip-10-70-59-190.eu-central-1.compute.internal",  "x_sa_name": "default",  "x_pod_ip": "100.96.1.11",  "build": "5000",  "builder": "Stephen Spencer",  "image": "gladiatr72/kube-demo",  "version": "1.0.2",  "app": "kube-demo",  "env": "dev",  "pod-template-hash": "2802633501",  "something": "else",  "additional data": "whee"}{  "asctime": "2017-07-12 21:08:16,369",  "message": "(access record)",  "name": "gunicorn.access",  "created": 1499893696.3695881,  "filename": "glogging.py",  "module": "glogging",  "funcName": "access",  "lineno": 327,  "msecs": 369.58813667297363,  "pathname": "/home/gladiatr/.virtualenvs/json-logs-for-kube/lib/python3.6/site-packages/gunicorn/glogging.py",  "process": 6800,  "processName": "MainProcess",  "relativeCreated": 41815.89770317078,  "thread": 140275726399232,  "threadName": "<concurrent.futures.thread.ThreadPoolExecutor object at 0x7f947f4b0828>_0",  "levelname": "INFO",  "x_node_name": "ip-10-70-59-190.eu-central-1.compute.internal",  "x_sa_name": "default",  "x_pod_ip": "100.96.1.11",  "build": "5000",  "builder": "Stephen Spencer",  "image": "gladiatr72/kube-demo",  "version": "1.0.2",  "app": "kube-demo",  "env": "dev",  "pod-template-hash": "2802633501",  "something": "else",  "access": {    "remote": "10.0.1.195",    "method": "GET",    "url-path": "/",    "query": "",    "username": "-",    "protocol": "HTTP/1.0",    "status": "200",    "response-length": "140",    "referrer": "-",    "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36",    "request-time": "0.019269"  }}

Example Kubernetes deployment:

apiVersion: extensions/v1beta1kind: Deploymentmetadata:         <<-- This is not the metadata you are looking for  name: kube-demo  labels:    project: kube-demo    environment: devspec:  replicas: 1  selector:    matchLabels:      app: kube-demo      env: dev  template:    metadata:      labels:        app: kube-demo        env: dev        something: else      annotations:        build: "5000"        builder: "Stephen Spencer"        image: "gladiatr72/kube-demo"        version: "1.0.2"

Currently only metadata.(labels|annotations) are supported for exposure via volume.

(Reasons, right?)

    spec:      volumes:          name: podinfo          downwardAPI:            items:              - path: labels                fieldRef:                  fieldPath: metadata.labels              - path: annotations                fieldRef:                  fieldPath: metadata.annotations      containers:        - name: kube-demo          image: gladiatr72/kube-demo:1.0.2          volumeMounts:            -              name: run              mountPath: /run            -              name: podinfo              readOnly: true              mountPath: /etc/meta  <<-- KUBE_META must equal this

environment variable prefixes

(or: how to avoid looking like a complete idiot when you spam your data-storepassword into your logging system)

You can use whatever letter or sequence for the prefix as long as it gets matchedwith the value of KUBE_META_ENV_PREFIX.

          env:            - name: MEMCACHE_HOST              value: unix:/run/memcache.sock            - name: DJANGO_SETTINGS_MODULE              value: "revsys.settings.dev"            - name: DJANGO_FQDN              value: kube-demo.dev.revsys.com            - name: *X_NODE_NAME              valueFrom:                fieldRef:                 fieldPath: spec.nodeName            - name: *X_POD_IP              valueFrom:                fieldRef:                  fieldPath: status.podIP            - name: *X_SA_NAME              valueFrom:                fieldRef:                  fieldPath: spec.serviceAccountName            - name: REDIS_PASSWORD  (oh, nos!)              valueFrom:                secretKeyRef:                  name: redis                  key: pass          ports:            - containerPort: 8000    * unmagical prefix set in KUBE_META_ENV_PREFIX

The logging configuration

It’s just a standard python dictionary. The most obvious thing to changeis the handler definition.

from jslog4kube import LOGGINGLOGGING_HANDLERS = {    'mypackage': {        'handlers': ['json-stdout'],        'formatters': ['json'],        'propagate’: False,        'level’: 'ERROR',    }}LOGGING['handlers'].update(LOGGING_HANDLERS)

Setup your python/django apps to log correctly

The LOGGING dict this provides sets up the "general" things to log, but ifyou want to include your own Python libraries or Django apps you need to specifythem. To specify a Django app named 'foo', you would simply adjust the LOGGING dict like this:

LOGGERS = {    'foo': {        'handlers': ['json-stdout'],        'formatters': ['json'],        'propagate': True,        'level': 'INFO',    }}LOGGING['loggers'].update(LOGGERS)dictConfig(LOGGING)

Or if you want to log EVERYTHING at an DEBUG level you can set a blank (aka default) logger:

LOGGERS = {    '': {        'handlers': ['json-stdout'],        'formatters': ['json'],        'propagate': True,        'level': 'DEBUG',    }}LOGGING['loggers'].update(LOGGERS)dictConfig(LOGGING)

Usage

This is normal Python logging so you can do something simple like our info callbelow or more complex like the debug call and add additional data to the log information:

import logginglogger = logging.getLogger(__name__)logger.info("Simple log message")foo = 12bar = 'something else'logger.debug("More complicated message", extra={  "foo": foo,  "bar": bar,})

Need help?

REVSYS can help with your Python, Django, and infrastructure projects. If you have a question about this project, please open a GitHub issue. If you love us and want to keep track of our goings-on, here's where you can find us online:

PRAGMA foreign_keys = off; BEGIN TRANSACTION; COMMIT TRANSACTION; PRAGMA foreign_keys = on;

Subscribe to our newsletter