In this chapter, we will learn about application logging in Kubernetes and implement it. Additionally, we will introduce a structured logging format to make it ready for parsing by log collection and analysis systems.
The application described in this chapter is not intended for use in production environments as-is. Note that successful completion of this entire guide is required to create a production-ready application.
Preparing the environment
If you haven’t prepared your environment during previous steps, please, do it using the instructions provided in the “Preparing the environment” chapter.
If your environment has stopped working or instructions in this chapter don’t work, please, refer to these hints:
Let’s launch Docker Desktop. It takes some time for this application to start Docker. If there are no errors during the startup process, check that Docker is running and is properly configured:
docker run hello-world
You will see the following output if the command completes successfully:
Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
b8dfde127a29: Pull complete
Digest: sha256:9f6ad537c5132bcce57f7a0a20e317228d382c3cd61edae14650eec68b2b345c
Status: Downloaded newer image for hello-world:latest
Hello from Docker!
This message shows that your installation appears to be working correctly.
Should you have any problems, please refer to the Docker documentation.
Let’s launch the Docker Desktop application. It takes some time for the application to start Docker. If there are no errors during the startup process, then check that Docker is running and is properly configured:
docker run hello-world
You will see the following output if the command completes successfully:
Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
b8dfde127a29: Pull complete
Digest: sha256:9f6ad537c5132bcce57f7a0a20e317228d382c3cd61edae14650eec68b2b345c
Status: Downloaded newer image for hello-world:latest
Hello from Docker!
This message shows that your installation appears to be working correctly.
Should you have any problems, please refer to the Docker documentation.
Start Docker:
sudo systemctl restart docker
Make sure that Docker is running:
sudo systemctl status docker
If the Docker start is successful, you will see the following output:
● docker.service - Docker Application Container Engine
Loaded: loaded (/lib/systemd/system/docker.service; enabled; vendor preset: enabled)
Active: active (running) since Thu 2021-06-24 13:05:17 MSK; 13s ago
TriggeredBy: ● docker.socket
Docs: https://docs.docker.com
Main PID: 2013888 (dockerd)
Tasks: 36
Memory: 100.3M
CGroup: /system.slice/docker.service
└─2013888 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock
dockerd[2013888]: time="2021-06-24T13:05:16.936197880+03:00" level=warning msg="Your kernel does not support CPU realtime scheduler"
dockerd[2013888]: time="2021-06-24T13:05:16.936219851+03:00" level=warning msg="Your kernel does not support cgroup blkio weight"
dockerd[2013888]: time="2021-06-24T13:05:16.936224976+03:00" level=warning msg="Your kernel does not support cgroup blkio weight_device"
dockerd[2013888]: time="2021-06-24T13:05:16.936311001+03:00" level=info msg="Loading containers: start."
dockerd[2013888]: time="2021-06-24T13:05:17.119938367+03:00" level=info msg="Loading containers: done."
dockerd[2013888]: time="2021-06-24T13:05:17.134054120+03:00" level=info msg="Daemon has completed initialization"
systemd[1]: Started Docker Application Container Engine.
dockerd[2013888]: time="2021-06-24T13:05:17.148493957+03:00" level=info msg="API listen on /run/docker.sock"
Now let’s check if Docker is available and its configuration is correct:
docker run hello-world
You will see the following output if the command completes successfully:
Unable to find image 'hello-world:latest' locally
latest: Pulling from library/hello-world
b8dfde127a29: Pull complete
Digest: sha256:9f6ad537c5132bcce57f7a0a20e317228d382c3cd61edae14650eec68b2b345c
Status: Downloaded newer image for hello-world:latest
Hello from Docker!
This message shows that your installation appears to be working correctly.
Should you have any problems, please refer to the Docker documentation.
Let’s start the minikube cluster we have already configured in the “Preparing the environment” chapter:
minikube start
Set the default Namespace so that you don’t have to specify it every time you invoke kubectl:
kubectl config set-context minikube --namespace=werf-guide-app
You will see the following output if the command completes successfully:
😄 minikube v1.20.0 on Ubuntu 20.04
✨ Using the docker driver based on existing profile
👍 Starting control plane node minikube in cluster minikube
🚜 Pulling base image ...
🎉 minikube 1.21.0 is available! Download it: https://github.com/kubernetes/minikube/releases/tag/v1.21.0
💡 To disable this notice, run: 'minikube config set WantUpdateNotification false'
🔄 Restarting existing docker container for "minikube" ...
🐳 Preparing Kubernetes v1.20.2 on Docker 20.10.6 ...
🔎 Verifying Kubernetes components...
▪ Using image gcr.io/google_containers/kube-registry-proxy:0.4
▪ Using image k8s.gcr.io/ingress-nginx/controller:v0.44.0
▪ Using image registry:2.7.1
▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
▪ Using image gcr.io/k8s-minikube/storage-provisioner:v5
🔎 Verifying registry addon...
🔎 Verifying ingress addon...
🌟 Enabled addons: storage-provisioner, registry, default-storageclass, ingress
🏄 Done! kubectl is now configured to use "minikube" cluster and "werf-guide-app" namespace by default
Make sure that the command output contains the following line:
Restarting existing docker container for "minikube"
Its absence means that a new minikube cluster was created instead of using the old one. In this case, repeat all the steps required to install the environment using minikube.
Now run the command in the background PowerShell terminal (do not close its window):
minikube tunnel --cleanup=true
Let’s start the minikube cluster we have already configured in the “Preparing the environment” chapter:
minikube start --namespace werf-guide-app
Set the default Namespace so that you don’t have to specify it every time you invoke kubectl:
kubectl config set-context minikube --namespace=werf-guide-app
You will see the following output if the command completes successfully:
😄 minikube v1.20.0 on Ubuntu 20.04
✨ Using the docker driver based on existing profile
👍 Starting control plane node minikube in cluster minikube
🚜 Pulling base image ...
🎉 minikube 1.21.0 is available! Download it: https://github.com/kubernetes/minikube/releases/tag/v1.21.0
💡 To disable this notice, run: 'minikube config set WantUpdateNotification false'
🔄 Restarting existing docker container for "minikube" ...
🐳 Preparing Kubernetes v1.20.2 on Docker 20.10.6 ...
🔎 Verifying Kubernetes components...
▪ Using image gcr.io/google_containers/kube-registry-proxy:0.4
▪ Using image k8s.gcr.io/ingress-nginx/controller:v0.44.0
▪ Using image registry:2.7.1
▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
▪ Using image docker.io/jettech/kube-webhook-certgen:v1.5.1
▪ Using image gcr.io/k8s-minikube/storage-provisioner:v5
🔎 Verifying registry addon...
🔎 Verifying ingress addon...
🌟 Enabled addons: storage-provisioner, registry, default-storageclass, ingress
🏄 Done! kubectl is now configured to use "minikube" cluster and "werf-guide-app" namespace by default
Make sure that the command output contains the following line:
Restarting existing docker container for "minikube"
Its absence means that a new minikube cluster was created instead of using the old one. In this case, repeat all the steps required to install the environment from scratch using minikube.
If you have inadvertently deleted Namespace of the application, you must run the following commands to proceed with the guide:
kubectl create namespace werf-guide-app
kubectl create secret docker-registry registrysecret \
--docker-server='https://index.docker.io/v1/' \
--docker-username='<Docker Hub username>' \
--docker-password='<Docker Hub password>'
You will see the following output if the command completes successfully:
namespace/werf-guide-app created
secret/registrysecret created
If nothing worked, repeat all the steps described in the “Preparing the environment” chapter and create a new environment from scratch. If creating an environment from scratch did not help either, please, tell us about your problem in our Telegram chat or create an issue on GitHub. We will be happy to help you!
Preparing the repository
Update the existing repository containing the application:
Run the following commands in PowerShell:
cd ~/werf-guide/app
# To see what changes we will make later in this chapter, let's replace all the application files
# in the repository with new, modified files containing the changes described below.
git rm -r .
cp -Recurse -Force ~/werf-guide/guides/examples/django/020_logging/* .
git add .
git commit -m WIP
# Enter the command below to show the files we are going to change.
git show --stat
# Enter the command below to show the changes that will be made.
git show
Run the following commands in Bash:
cd ~/werf-guide/app
# To see what changes we will make later in this chapter, let's replace all the application files
# in the repository with new, modified files containing the changes described below.
git rm -r .
cp -rf ~/werf-guide/guides/examples/django/020_logging/. .
git add .
git commit -m WIP
# Enter the command below to show files we are going to change.
git show --stat
# Enter the command below to show the changes that will be made.
git show
Doesn’t work? Try the instructions on the “I am just starting from this chapter” tab above.
Prepare a new repository with the application:
Run the following commands in PowerShell:
# Clone the example repository to ~/werf-guide/guides (if you have not cloned it yet).
if (-not (Test-Path ~/werf-guide/guides)) {
git clone https://github.com/werf/website $env:HOMEPATH/werf-guide/guides
}
# Copy the (unchanged) application files to ~/werf-guide/app.
rm -Recurse -Force ~/werf-guide/app
cp -Recurse -Force ~/werf-guide/guides/examples/django/010_basic_app ~/werf-guide/app
# Make the ~/werf-guide/app directory a git repository.
cd ~/werf-guide/app
git init
git add .
git commit -m initial
# To see what changes we will make later in this chapter, let's replace all the application files
# in the repository with new, modified files containing the changes described below.
git rm -r .
cp -Recurse -Force ~/werf-guide/guides/examples/django/020_logging/* .
git add .
git commit -m WIP
# Enter the command below to show the files we are going to change.
git show --stat
# Enter the command below to show the changes that will be made.
git show
Run the following commands in Bash:
# Clone the example repository to ~/werf-guide/guides (if you have not cloned it yet).
test -e ~/werf-guide/guides || git clone https://github.com/werf/website ~/werf-guide/guides
# Copy the (unchanged) application files to ~/werf-guide/app.
rm -rf ~/werf-guide/app
cp -rf ~/werf-guide/guides/examples/django/010_basic_app ~/werf-guide/app
# Make the ~/werf-guide/app directory a git repository.
cd ~/werf-guide/app
git init
git add .
git commit -m initial
# To see what changes we will make later in this chapter, let's replace all the application files
# in the repository with new, modified files containing the changes described below.
git rm -r .
cp -rf ~/werf-guide/guides/examples/django/020_logging/. .
git add .
git commit -m WIP
# Enter the command below to show files we are going to change.
git show --stat
# Enter the command below to show the changes that will be made.
git show
Redirecting logs to stdout
All applications deployed to a Kubernetes cluster must write logs to stdout/stderr. Sending logs to standard streams makes them accessible by Kubernetes and log collection systems. Such an approach keeps logs from being deleted when containers are recreated and prevents consuming all available storage on Kubernetes nodes if the output is sent to log files in containers.
Django writes logs to stdout by default, so no extra steps are required to output them.
Formatting logs
By default, Django-based application generate plain text logs:
*** Starting uWSGI 2.0.20 (64bit) on [Thu Aug 4 09:45:00 2022] ***
compiled with version: 11.2.0 on 03 August 2022 22:23:29
os: Linux-5.17.0-1013-oem #14-Ubuntu SMP PREEMPT Mon Jul 4 16:11:10 UTC 2022
nodename: thinkpad
machine: x86_64
clock source: unix
pcre jit disabled
detected number of CPU cores: 8
current working directory: /home/user/github/website/examples/django/020_logging/app
detected binary path: /home/user/.local/bin/uwsgi
*** WARNING: you are running uWSGI without its master process manager ***
your processes number limit is 62424
your memory page size is 4096 bytes
detected max file descriptor number: 1024
lock engine: pthread robust mutexes
thunder lock: disabled (you can enable it with --thunder-lock)
uwsgi socket 0 bound to TCP address :8000 fd 3
Python version: 3.10.4 (main, Jun 29 2022, 12:14:53) [GCC 11.2.0]
*** Python threads support is disabled. You can enable it with --enable-threads ***
Python main interpreter initialized at 0x560060bfcc40
your server socket listen backlog is limited to 100 connections
your mercy for graceful operations on workers is 60 seconds
mapped 72920 bytes (71 KB) for 1 cores
*** Operational MODE: single process ***
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x560060bfcc40 pid: 150328 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI worker 1 (and the only) (pid: 150328, cores: 1)
[pid: 150328|app: 0|req: 1/1] 127.0.0.1 () {24 vars in 258 bytes} [Thu Aug 4 06:45:03 2022] GET /ping => generated 5 bytes in 2 msecs (HTTP/1.1 200) 6 headers in 205 bytes (1 switches on core 0)
As you can see, both the application start message and the query message (we used the curl command just like at the end of the previous section) are in plain text.
Regular log collection and analysis systems will probably struggle with parsing all this gibberish.
You can solve this problem by shipping logs in a structured JSON-like format. Most log collection systems can both, easily parse JSON and correctly process logs/messages in other (unexpected, unstructured) formats when they sneak in between JSON-formatted logs.
To avoid this, we have to configure the application to write logs in JSON format. Let’s create a uwsgi config and define the desired log format in it:
[uwsgi]
module = app.wsgi:application
http-socket = 0.0.0.0:8000
log-encoder = json {"time":"${unix}", "source":"uwsgi", "message":"${msg}"}
log-encoder = nl
log-format = "address":"%(addr)", "host":"%(json_host)", "method":"%(method)", "uri":"%(json_uri)", "protocol":"%(proto)", "resp_size":%(size), "req_body_size":%(cl), "resp_status":%(status), "resp_time":%(secs)"
log-master = true
Log tagging support is beyond the scope of this guide; however, you can implement it if necessary.
Please Note! The steps in the current section are for illustrative purposes only. They show how a basic application was generated. Only the steps in the “Checking whether the application is running” section are intended to be followed.
Managing the logging level
By default, the application logging level for the production environment is set to INFO. However, sometimes you may wish to change that.
For example, switching the logging level from info to debug can provide additional debugging information and help in troubleshooting problems in production. However, if the application has many replicas, switching them all to the debug level may not be the best idea. It may affect security and significantly increase the load on log collection, storage, and analysis components.
You can use an environment variable to set the logging level, thus solving the above problem. Using this approach, you can run a single Deployment replica with the debug logging level next to the existing replicas with the info logging level enabled. Moreover, you can disable centralized log collection for this new Deployment (if any). Together, all these measures prevent overloading log collection systems while keeping debug logs containing potentially sensitive information from being streamed to them.
Here is how you can set the logging level using the LOG_LEVEL environment variable:
...
LOG_LEVEL = 'INFO'
if environ.get('LOG_LEVEL') is not None:
LOG_LEVEL = environ.get('LOG_LEVEL')
LOGGING = {
'version': 1,
'disable_existing_loggers': False,
'handlers': {
'console': {
'class': 'logging.StreamHandler',
},
},
'root': {
'handlers': ['console'],
'level': LOG_LEVEL,
'propagate': True,
},
}
If the environment variable is omitted, the INFO level is used by default.
Displaying logs in werf-based deploys
By default, when deploying, werf prints logs of all application containers until they become Ready.
You can filter these logs using custom werf annotations. In this case, werf will only print lines that match the specified patterns.
Additionally, you can enable log output for specific containers.
For example, here is how you can disable log output for the container_name container during the deployment:
annotations:
werf.io/skip-logs-for-containers: container_name
The example below shows how you can enable printing lines that match a pre-defined regular expression:
annotations:
werf.io/log-regex: ".*ERROR.*"
A list of all available annotations can be found here.
Note that these annotations only influence the way logs are shown during the werf-based deployment process. They do not affect the application being deployed or its configuration in any way. You can still use stdout/stderr streams of the container to view raw logs.
Checking whether the application is running
Let’s deploy our application:
werf converge --repo <DOCKER HUB USERNAME>/werf-guide-app
You should see the following output:
┌ ⛵ image app
│ Use cache image for app/dockerfile
│ name: <DOCKER HUB USERNAME>/werf-guide-app:bffe745a6ab14dac56cdacd3391b880bd2ec6049bae4cae396437d36-1661149059515
│ id: 82580e1e4111
│ created: 2022-08-22 09:17:38 +0000 UTC
│ size: 121.8 MiB
└ ⛵ image app (0.00 seconds)
Release "werf-guide-app" does not exist. Installing it now.
┌ Waiting for resources to become ready
│ ┌ Status progress
│ │ DEPLOYMENT REPLICAS AVAILABLE UP-TO-DATE
│ │ werf-guide-app 1/1 1 1
│ │ │ POD READY RESTARTS STATUS
│ │ └── guide-app-776fd99c79-n88d 0/1 0 ContainerCreatin
│ │ 2 g
│ └ Status progress
└ Waiting for resources to become ready (1.47 seconds)
NAME: werf-guide-app
LAST DEPLOYED: Mon Aug 22 09:23:11 2022
LAST PHASE: rollout
LAST STAGE: 0
NAMESPACE: werf-guide-app
STATUS: deployed
REVISION: 1
TEST SUITE: None
Running time 8.05 seconds
Make several requests in order to generate some logging data:
curl http://werf-guide-app.test/ping # returns "pong" + 200 OK status code
curl http://werf-guide-app.test/not_found # no response; returns 404 Not Found
While our requests are being made, we won’t see any codes returned by the server. However, we can find them in the logs — let’s take a look at them:
kubectl -n werf-guide-app logs deploy/werf-guide-app
You should see the following output:
{"time":"1661149868", "source":"uwsgi", "message":"\"address\":\"127.0.0.1\", \"host\":\"-\", \"method\":\"GET\", \"uri\":\"-\", \"protocol\":\"HTTP/1.1\", \"resp_size\":210, \"req_body_size\":0, \"resp_status\":200, \"resp_time\":0.000525\""}
{"time":"1661149870", "source":"uwsgi", "message":"\"address\":\"127.0.0.1\", \"host\":\"-\", \"method\":\"GET\", \"uri\":\"-\", \"protocol\":\"HTTP/1.1\", \"resp_size\":2314, \"req_body_size\":0, \"resp_status\":404, \"resp_time\":0.007921\""}
Note that application logs are now rendered in JSON format, and most log processing systems can easily parse them. At the same time, Rails and Puma logs are streamed in plain text just like before. The main advantage of this approach is that log processing systems will no longer try to parse application logs and Rails/Puma logs as if they have the same format. JSON logs will be stored separately, letting you perform searching/filtering based on the selected fields.
