Troubleshooting a Java application under Kubernetes

image

When developers and operators interact

Let’s say you wrote a Java application and deployed it to Kubernetes in a development environment. Sooner or later, this application will go into production, and you will have to find out what it really is. Then new unexpected problems begin to arise. There can be many reasons for such problems: too many users, memory leaks, race conditions, and it is difficult to identify such problems at the development stage.

Of course, in such cases, the malfunctions need to be corrected, and the first step is to run a root cause analysis of failures, which would lead us to the source of the problems. On a laptop, this is easy: when the application is blocked, you can display thread dumps, heat maps and try to understand where the blocking comes from.

In Kubernetes, things are a little different. You’ve probably been advised to add a separate health check endpoint, so k8s will have time to restart the pod before you intervene. After that, the pod looks fresh, and all the information that you needed was lost in it. This post will show a very simple way to remove information in such a situation.

Lifecycle Hooks in Kubernetes

The main feature of Kubernetes that we will use here is called

Lifecycle hooks in containers

. This feature allows you to execute certain commands at two specific times within the lifecycle of a pod:

  • Interceptor PostStart: immediately after launch
  • Interceptor PreStop: just before stopping

Of course, in this case, the most important interceptor

PreStop

. It fires whenever Kubernetes sends a stop command to the container. This can happen if a pod is removed, or if the health check stops responding, or if you manually or automatically stop the container yourself (for example, new deployed instances).

To configure the interceptor, we just need to add the following configuration to our resource:

apiVersion: v1
kind: Pod
metadata:
name: mypod
spec:
containers:
- image: myapp:latest
lifecycle:
preStop:
exec:
command:
- /bin/sh
- /scripts/pre-stop.sh

...

terminationGracePeriodSeconds: 30

In this example, Kubernetes will execute the script

pre-stop.sh

right before the container stops. Another important setting here is

terminationGracePeriodSeconds

, indicating how long k8s will wait for the pod to stop: this is a normal running process, but also a shutdown hook. That’s why the script

preStop

should be fast enough.

Application for testing

To demonstrate the whole process, I have developed an example Java application based on Quarkus. This application will allow us to test some failure scenarios. In this case, the idea is: to provide a REST API that would allow you to put the application into a faulty mode. Here is just the case when the situation is easier to explain in code than in words – and here is this code:

given()
.when().get("/q/health/live")
.then()
.statusCode(200);

given()
.when().put("/shoot")
.then()
.statusCode(200)
.body(is("Application should now be irresponsive"));

given()
.when().get("/q/health/live")
.then()
.statusCode(503);

The application is uploaded to DockerHub, where it is called

dmetzler/java-k8s-playground

.

Removing information needed for troubleshooting

To remove some useful information, you can try to run the following script. Of course, you can add other commands to get more details. This script will give you:

  • List of open connections
  • java process state
  • The result of the liveness test
  • Memory usage in the JVM
  • Thread Dump

This script could be saved directly to the image, but it won’t help much if you only want to make small changes. Instead, let’s store it in a settings map and mount it

ConfigMap

as a separate volume.

apiVersion: v1
kind: ConfigMap
metadata:
name: pre-stop-scripts
data:
pre-stop.sh: |
#!/bin/bash
set +e

NOW=`date +"%Y-%m-%d_%H-%M-%S"`
LOGFILE=/troubleshoot/${HOSTNAME}_${NOW}.txt

{
echo == Open Connections =======
netstat -an
echo

echo == Process Status info ===================
cat /proc/1/status
echo

echo == Health endpoint =========================
curl -m 3 localhost:8080/q/health/live
if [ $? -gt 0 ]; then
echo "Health endpoint resulted in ERROR"
fi
echo

echo == JVM Memory usage ======================
jcmd 1 VM.native_memory
echo

echo == Thread dump ===========================
jcmd 1 Thread.print

} >> $LOGFILE 2>&1

This script expects it to have write access to the directory

/troubleshoot

to save the result. To do this, you will need to provide an additional volume.

Deploying an Application with a PreStop Interceptor

Here is the complete deployment resource we will create:

apiVersion: apps/v1
kind: Deployment
metadata:
labels:
app: java-k8s-playground
name: java-k8s-playground
spec:
replicas: 1
selector:
matchLabels:
app: java-k8s-playground
template:
metadata:
labels:
app: java-k8s-playground
spec:
containers:
- name: java-k8s-playground
image: dmetzler/java-k8s-playground

# Пробы работоспособности (1)
livenessProbe:
failureThreshold: 3
httpGet:
path: /q/health/live
port: 8080
scheme: HTTP
initialDelaySeconds: 5
periodSeconds: 5
successThreshold: 1
timeoutSeconds: 10
readinessProbe:
failureThreshold: 15
httpGet:
path: /q/health/ready
port: 8080
scheme: HTTP
initialDelaySeconds: 5
periodSeconds: 5
successThreshold: 1
timeoutSeconds: 3

# При останове запрашиваем здесь запуск скрипта для устранения неполадок (2)
lifecycle:
preStop:
exec:
command:
- /bin/sh
- /scripts/pre-stop.sh

# Тома для получения скрипта и сохранения результата (3)
volumeMounts:
# Карта настроек, содержащая скрипт
- mountPath: /scripts
name: scripts
# Где сохранять информацию
- mountPath: /troubleshoot
name: troubleshoot
volumes:
- emptyDir: {}
name: troubleshoot
- configMap:
defaultMode: 493
name: pre-stop-scripts
name: scripts

terminationGracePeriodSeconds: 30

  1. First, we configure the health checks so that when the application becomes unhealthy, Kubernetes automatically restarts the pod.
  2. This is where we tell Kubernetes to run our script when the pod stops.
  3. We provide two pods. One is to mount the script to help troubleshoot, and the other is to save the result. Here we use the directory emptyDir. This may not be so easy if the scheduler has moved the pod to another node (for example, after deletion). We may prefer to use a volume that is more persistent. In our experience, the container will simply be restarted, so there is no such problem.

Shooting to kill

Now let’s do our experiment. First, let’s deploy our two resources:

$ kubectl create -f configmap.yaml
configmap "pre-stop-scripts" created
$ kubectl create -f deployment.yaml
deployment "java-k8s-playground" created
$ kubectl get deployment java-k8s-playground
NAME DESIRED CURRENT UP-TO-DATE AVAILABLE AGE
java-k8s-playground 1 1 1 1 5s

Our application has started working, and now we just need to use

cURL

knock on the endpoint

/shoot

to switch to the failed state.

$ oc get pod -l app=java-k8s-playground
NAME READY STATUS RESTARTS AGE
java-k8s-playground-65d6b9b4f4-xrjgn 1/1 Running 1 23m
$ kubectl exec -it java-k8s-playground-65d6b9b4f4-xrjgn -- bash
bash-4.4$ curl -XPUT localhost:8080/shoot
Application should now be irresponsive
bash-4.4$ command terminated with exit code 137
$ # Здесь мы наконец=то теряем соединение, так как под перезапущен k8s
The container has been restarted by Kubernetes. Let’s see what we have in the newly created container.
$ kubectl exec -it java-k8s-playground-65d6b9b4f4-xrjgn -- bash
bash-4.4$ cd /troubleshoot/
bash-4.4$ ls
java-k8s-playground-65d6b9b4f4-xrjgn_2021-03-27_18-06-48.txt
bash-4.4$
bash-4.4$ head -n 5 java-k8s-playground-65d6b9b4f4-xrjgn_2021-03-27_18-06-48.txt
== Open Connections =======
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address Foreign Address State
tcp6 0 0 :::8080 :::* LISTEN
tcp6 0 0 172.16.247.87:8080 172.16.246.1:42238 TIME_WAIT

That’s all, now the file contains all the information we need. The full output of our script is

here

.

Use a message to terminate Kubernetes

The operation of adding a volume that will store the result of our research can seem somewhat complicated when carried out in scenarios with deployment to production. Kubernetes also has a lighter, but functionally limited solution that allows you to save some information about the completion. This is a termination message.

In a pod definition, you can specify spec.terminationMessagePath (default /dev/termination-log) where you can record some information about why the pod was stopped. AT documentation it is stated that:

Log output is limited to 2048 bytes or 80 lines, whichever is smaller.

In our case, the output of the script is usually larger (about 30 KB), so we cannot redirect all the content to this file. No, it would actually make sense to keep only the output of the health probe. Therefore, we could modify our script like this:

...
echo == Health endpoint =========================
curl -m 3 localhost:8080/q/health/live > /dev/termination-log
if [ $? -gt 0 ]; then
echo "Health endpoint resulted in ERROR"
fi
cat /dev/termination-log
echo
...

Having repeated the same destructive experiment, let’s see what we now have in the description of the pod:

$ oc describe pod java-k8s-playground-65d6b9b4f4-xrjgn
Name: java-k8s-playground-65d6b9b4f4-xrjgn
Namespace: XXXXX
Node: ip-XXXXXX.ec2.internal/XXXXXX
Start Time: Sat, 27 Mar 2021 18:41:27 +0100

....

Containers:
java-k8s-playground:

...

State: Running
Started: Sat, 27 Mar 2021 19:06:49 +0100
Last State: Terminated
Reason: Error
Message:
{
"status": "DOWN",
"checks": [
{
"name": "App is down",
"status": "DOWN"
}
]
}
Exit Code: 143
Started: Sat, 27 Mar 2021 18:42:29 +0100
Finished: Sat, 27 Mar 2021 19:06:49 +0100
Ready: True
Restart Count: 2
$

Kubernetes was able to get the probe result and store it in the partition

last state

(also available in

status.containerStatuses[0].lastState.terminated.message

in YAML representation). Of course, we can only add a limited amount of data here, since it will probably end up in

etcd

.

But this way you can quickly get some useful status messages, and this does not require you to anticipate and plan a script for troubleshooting. For example, in Nuxeo you can save the result of a sample runningstatus. Another option is to install terminationMessagePolicy in FallbackToLogsOnError. In this case, if the message is empty, then Kubernetes will take the last line of console logs as a message. So, to get a quick pre-troubleshooting status when using Nuxeo in Kubernetes, you need to add the following code to your pod definition:

apiVersion: v1
kind: Pod
metadata:
name: mypod
spec:
containers:
- image: nuxeo:LTS
lifecycle:
preStop:
exec:
command:
- /bin/bash
- -c
- "/usr/bin/curl -m 3 localhost:8080/nuxeo/runningstatus > /dev/termination-log"
terminationMessagePolicy: FallbackToLogsOnError

In this case, the result of a valid status probe will be stored in the last state of our container. For example, a very common mistake made when configuring credentials in S3 is easy to spot; all you have to do is view the latest status message.

Conclusion

When we are dealing with applications in production and the application crashes, the first reaction is to look at the logs. This is of course useful, but sometimes it can be difficult to go through thousands of lines of logs, especially in Java, where stack traces are sometimes extremely verbose. Flow dumps or heatmaps are usually very helpful if the solution isn’t quite obvious and can’t be seen from the logs alone.

Using lifecycle hooks in Kubernetes, it is convenient to capture the state of your application at the time it was restarted. It’s actually a good idea to anticipate this event, as by default k8s gives you 30 seconds to collect everything you need.

Links

Similar Posts

Leave a Reply

Your email address will not be published. Required fields are marked *