kubernetes: kubectl exec can unexpectedly exit 0

Hey,

I think that I am encountering this issue as well, my use case is that I am running a long query on Mongo via kubectl exec and after about 20 minutes I am kicked out of the pod. In the syslog of the Node I have this error:

Exec session in container <id> terminated but process still running!

Would be great to know what the solution is for this.

Thanks, Richard

Fight with the “automation” begins 😃

/remove-lifecycle stale

It does not seem to have anything to do with the runtime, or whether data is sent or not. Still trying to figure out what triggers it. In any case, a PR that ensures that kubectl does proper error reporting will go a long way in figuring out what makes it bail.

Notes

Below are some tests on my Drupal pod. But first, some notes:

• I’m piping it through pv on my machine to see how much data is transferred.
• Each command in this list is prefixed with kubectl -n ns -it exec deploy/drupal-deployment --container=drupal --, but I leave it out for brevity.
• Wherever I say a test “has the issue”, I mean that kubectl exec stops with code 0, but the process keeps running in the container.
• When I do something like kubectl -n ns -it exec deploy/drupal-deployment --container=drupal -- cat /dev/urandom | pv > /dev/null, the pipe to pv is done on my local machine, but cat /dev/urandom runs in the container.

The pipe tests

• drush sql-dump --gzip | pv > tmp/db.sql.gz — has the issue. The .sql.gz file has “unexpected end of file”. Transfers about 50MiB in 23s before it dies.
• drush sql-dump | pv > tmp/db.sql — has the issue. The .sql file also stops in the middle of a table, so we don’t have the entire database. Transfers about 387MiB in 3min before it dies.
• watch date | pv > /dev/null — does NOT have the issue. It keeps running for a very long time without issues, so it rules out the possibility of a timeout somewhere. I’ll edit this if it dies at some point.
• cat /dev/urandom | pv > /dev/null — does NOT have the issue. Same as watch date. Transferred about 1GiB in 0:07:42 at the time of writing, and still going strong, So that rules out a network bandwidth limitation.

Exit code test

This works as expected, so it rules out the possibility of the exec’d command completing with non-zero exit code:

$ kubectl -n ns -it exec deploy/drupal-deployment --container=drupal -- /bin/sh -c "exit 1"
command terminated with exit code 1
$ echo $?
1

Running the same commands interactively

I opened an interactive bash shell, and tried the failing commands from above:

$ kubectl -n ns -it exec deploy/drupal-deployment --container=drupal -- /bin/bash

No problem here. database dump is complete, and kubectl stays connected:

bash-5.1# drush sql:dump | pv > /tmp/db.sql
 394MiB 0:00:11 [35.5MiB/s]
bash-5.1# tail -n 1 /tmp/db.sql
-- Dump completed on 2022-02-04  9:31:24

Also works with gzip. kubectl stays connected:

bash-5.1# drush sql:dump --gzip | pv > /tmp/db.sql.gz
49.9MiB 0:00:18 [2.69MiB/s]
bash-5.1# zcat /tmp/db.sql.gz | tail -n 1
-- Dump completed on 2022-02-04  9:33:50

So that rules out the exec’d command using too much CPU or memory, because these are the same commands as in the above tests.

cat existing file test

This left be wondering if the exec’d command writes something to the stream that makes kubectl choke up, and it just hasn’t come up in /dev/urandom yet, but it’s part of my database dump. So let’s test that…

$ kubectl -n ns -it exec deploy/drupal-deployment --container=drupal -- cat /tmp/db.sql | pv > tmp/db.sql
 392MiB 0:02:59 [2.18MiB/s]
$ less tmp/db.sql

I can see in less that the file is cut off before the end! It should have transferred 394MiB, but we only have 392MiB.

$ kubectl -n ns -it exec deploy/drupal-deployment --container=drupal -- cat /tmp/db.sql.gz | pv > tmp/db.sql.gz
48.1MiB 0:00:21 [2.20MiB/s]

This is cut short again: 48.1MiB instead of 49.9MiB. But this is where it gets really weird. Compare the first few lines of the file on the source, vs. the file we got by downloading it through kubectl exec ... cat > ...:

$ kubectl -n ns -it exec deploy/drupal-deployment --container=drupal -- /bin/sh -c "zcat /tmp/db.sql.gz | head"
-- MariaDB dump 10.19  Distrib 10.5.13-MariaDB, for Linux (x86_64)
--
-- Host: db-primary    Database: drupal
-- ------------------------------------------------------
-- Server version       10.5.13-MariaDB-log

/*!40101 SET @OLD_CHARACTER_SET_CLIENT=@@CHARACTER_SET_CLIENT */;
/*!40101 SET @OLD_CHARACTER_SET_RESULTS=@@CHARACTER_SET_RESULTS */;
/*!40101 SET @OLD_COLLATION_CONNECTION=@@COLLATION_CONNECTION */;
/*!40101 SET NAMES utf8mb4 */;

$ zcat tmp/db.sql.gz | head
-- MariaDB dump 10.19  Distrib 10.5.13-MariaDB, for Linux (x86_64)
--
-- Host: db-primary    Database: drupal
-- ------------------------------------------------------
-- Server version       10.5.13-MariaDB-log

/*!40101 SET @OLD_CHARACTER_SET_CLIENT=@@CHARACTER_SET_CLIENT */;
/*!40101 SET @OLD_CHARACTER_SET_RESULTS=@@CHARACTER_SET_RESULTS */;
/*!40101 SET @OLD_COLLATION_CONNECTION=@@COLLATION_CONNECTIONb-primary    Databrupal
--UeES utf8mb4ry    Databr3LD_COLLATITIME_ZONEATITIME_ZONEry    Databr3LD_COTIME_ZONEA'+00:00'ry    Data014LD_COLLATIUNIQUETERECKRACTUNIQUETERECKR, UNIQUETERECKRA0ry    Data014LD_COLLATIFOREIGN_KEYTERECKRACTFOREIGN_KEYTERECKR, FOREIGN_KEYTERECKRA0!40101 SET @OLD_COLLATISQL_MODEATISQL_MODE, SQL_MODEA'NO_AUTO_VALUETECTZERO'ry    Data11OLD_COLLATISQL_NOTESATISQL_NOTES, SQL_NOTESA0!4010Host: dTable 0.5ucturenux (table `batch`Host

Not surprisingly, the downloaded file can’t be extracted completely:

$ zcat tmp/db.sql.gz > /dev/null

gzip: tmp/db.sql.gz: invalid compressed data--format violated

Trying to verify that the problem is not with different versions of gzip or something like that, I tried kubectl cp, and that works fine. The .sql.gz file has the proper size, and can be extracted on my local machine just like in the container.

$ kubectl cp ns/drupal-deployment-66795dfd9d-ft56s:/tmp/db.sql.gz -c drupal tmp/cp_db.sql.gz
tar: Removing leading `/' from member names
$ zcat tmp/cp_db.sql.gz | tail -n 1
-- Dump completed on 2022-02-04  9:33:50

Verdict

kubectl exec has issues transferring stdout data to the local machine.

I’m surprised, this has gone on for so long. Apparently, this is by design:

"--streaming-connection-idle-timeout=30m" (see https://kubernetes.io/docs/reference/command-line-tools-reference/kubelet/)

in my deployment gives me the observed exact 30 minutes before disconnecting. What’s worse is that it exits with an exit code of 0. This may be fine in some cases, but problematic in others. It seems, for example, that gitlab’s kubernetes executor sends the entire job script into its pod as a single kubectl exec and should it time out, it aborts mid-job, but returning a “Job succeeded”.

I have v1.16.3 on macOS and I still see this issue nearly on a daily basis. It generally appears when I leave my laptop to sleep overnight. Seems like something under the hood is timing out but kubectl exec exits zero and the command it started keeps running in the container.