Docker log stdout, stderr can not show the graphic progess bar

General
1

I am deploying a Kubernetes cluster that uses containerd as a container runtime.
Kubernetes store stdout and stderr log to this directory /var/log/pods/<namespace>_<pod>_7c88431c-d138-4d92-9c30-ae5366bf61a6.
The log is normal until we have some special content like a progress bar in the log content, such as here:

download: s3://test/hymenoptera_data/val/bees/65038344_52a45d090d.jpg to ../../test/input/val/bees/65038344_52a45d090d.jpg
download: s3://test/hymenoptera_data/val/bees/603711658_4c8cd2201e.jpg to ../../test/input/val/bees/603711658_4c8cd2201e.jpg
download: s3://test/hymenoptera_data/val/bees/6a00d8341c630a53ef00e553d0beb18834-800wi.jpg to ../../test/input/val/bees/6a00d8341c630a53ef00e553d0beb18834-800wi.jpg
download: s3://test/hymenoptera_data/val/bees/abeja.jpg to ../../test/input/val/bees/abeja.jpg
download: s3://test/hymenoptera_data/val/bees/936182217_c4caa5222d.jpg to ../../test/input/val/bees/936182217_c4caa5222d.jpg
download: s3://test/hymenoptera_data/val/bees/759745145_e8bc776ec8.jpg to ../../test/input/val/bees/759745145_e8bc776ec8.jpg
download: s3://test/hymenoptera_data/val/bees/59798110_2b6a3c8031.jpg to ../../test/input/val/bees/59798110_2b6a3c8031.jpg
download: s3://test/hymenoptera_data/val/ants/ants-devouring-remains-of-large-dead-insect-on-red-tile-in-Stellenbosch-South-Africa-closeup-1-DHD.jpg to ../../test/input/val/ants/ants-devouring-remains-of-large-dead-insect-on-red-tile-in-Stellenbosch-South-Africa-closeup-1-DHD.jpg
2023-11-24T04:53:30.222016269Z stderr F 2023/11/24 04:53:30.221735 s3.INFO Switching from region 'us-east-1' to 'ap-southeast-1'
2023-11-24T04:53:30.596892481Z stderr F 2023/11/24 04:53:30.596795 main.INFO File system has been successfully mounted.
2023-11-24T04:53:30.60038546Z stdout F run python sample.py
2023-11-24T04:53:37.028559324Z stderr F Downloading: "https://download.pytorch.org/models/resnet18-f37072fd.pth" to /root/.cache/torch/hub/checkpoints/resnet18-f37072fd.pth
100%|██████████| 44.7M/44.7M [00:02<00:00, 22.9MB/s]
2023-11-24T04:53:49.316040711Z stdout F Epoch 0/1
2023-11-24T04:53:49.316066991Z stdout F ----------
2023-11-24T08:28:08.269246372Z stdout F train Loss: 0.4961 Acc: 0.7582
2023-11-24T09:10:53.332419433Z stdout F val Loss: 0.2540 Acc: 0.8889
2023-11-24T09:10:53.33245518Z stdout F 
2023-11-24T09:10:53.332461372Z stdout F Epoch 1/1
2023-11-24T09:10:53.33246572Z stdout F ----------
2023-11-24T14:51:19.932292384Z stdout F train Loss: 0.4983 Acc: 0.7664
2023-11-24T16:08:25.421694138Z stdout F val Loss: 0.4678 Acc: 0.8170
2023-11-24T16:08:25.421714276Z stdout F 
2023-11-24T16:08:25.421717783Z stdout F Training complete in 672m 16s
2023-11-24T16:08:25.421720728Z stdout F Best val Acc: 0.888889
2023-11-24T16:08:26.182466811Z stdout F total 43656
2023-11-24T16:08:26.182502178Z stdout F -rw-r--r-- 1 root root 44700647 Nov 24 16:08 model.onnx
2023-11-24T16:08:26.182609691Z stdout F Training done
2023-11-24T16:08:26.182614941Z stdout F Pushing model
upload: ./model.onnx to s3://test/model/1/model.onnx         B (358.1 KiB/s) with 1 file(s) remaining
2023-11-24T16:08:41.451756744Z stdout F Model have been pushed

In the example, we only saw one line 100% progress, but when I am using the Kubernetes Dashboard or the Lens Software, it show all the progress:

image
image1284×757 108 KB

I also wrote the simple golang application that get log from kube-apiserver and saving the output to the new file, that process also show the complete progress bar. Here is the code block:

package main

import (
	"context"
	"flag"
	"fmt"
	"os"
	"strings"

	corev1 "k8s.io/api/core/v1"
	"k8s.io/client-go/kubernetes"
	"k8s.io/client-go/kubernetes/scheme"
	"k8s.io/client-go/tools/clientcmd"
)
type LogTimestamp string

type LogLine struct {
	Timestamp LogTimestamp `json:"timestamp"`
	Content   string       `json:"content"`
}

type LogLines []LogLine



func ToLogLines(rawLogs string) LogLines {
	logLines := LogLines{}
	for _, line := range strings.Split(rawLogs, "\n") {
		if line != "" {
			startsWithDate := ('0' <= line[0] && line[0] <= '9') //2017-...
			idx := strings.Index(line, " ")
			if idx > 0 && startsWithDate {
				timestamp := LogTimestamp(line[0:idx])
				content := line[idx+1:]
				logLines = append(logLines, LogLine{Timestamp: timestamp, Content: content})
			} else {
				logLines = append(logLines, LogLine{Timestamp: LogTimestamp("0"), Content: line})
			}
		}
	}
	return logLines
}
func main() {
	var (
		podName    string
		namespace  string
		filePath  string
	)
	flag.StringVar(&podName, "pod", "", "Name of the pod")
	flag.StringVar(&namespace, "namespace", "default", "Namespace of the pod")
	flag.StringVar(&filePath, "file", "pod_logs.txt", "File to save pod logs")
	flag.Parse()

	// Load kubeconfig file if it exists, otherwise use in-cluster config
	kubeconfig := os.Getenv("HOME") + "/.kube/config/config" // Change the path if your kubeconfig is elsewhere
	config, err := clientcmd.BuildConfigFromFlags("", kubeconfig)
	if err != nil {
		panic(err.Error())
	}

	// Create a Kubernetes clientset
	clientset, err := kubernetes.NewForConfig(config)
	if err != nil {
		panic(err.Error())
	}
	readCloser, err := clientset.CoreV1().
	RESTClient().Get().
	Namespace(namespace).Name(podName).Resource("pods").SubResource("log").
	VersionedParams(&corev1.PodLogOptions{}, scheme.ParameterCodec).Stream(context.TODO())
	if err != nil {
		panic(err.Error())
	}

	defer readCloser.Close()
	// Get pod logs
	// podLogs, err := clientset.CoreV1().Pods(namespace).GetLogs(podName, &corev1.PodLogOptions{}).Stream(context.TODO())
	// if err != nil {
	// 	panic(err.Error())
	// }
	// defer podLogs.Close()
	// Create or open the file for writing logs
	file, err := os.Create(filePath)
	if err != nil {
		panic(err.Error())
	}
	buf := make([]byte, 1000)
	for {
		numBytes, err := readCloser.Read(buf)
		if err != nil {
			break
		}
		if _, err := file.Write(buf[:numBytes]); err != nil {
			panic(err.Error())
		}
	}
	fmt.Printf("Logs saved to %s\n", filePath)
	// result, err := io.ReadAll(readCloser)
	// if err != nil {
	// 	panic(err.Error())
	// }
	// fmt.Print(string(result))
	// parsedLines := logs.ToLogLines(rawLogs)
}

Here is the new log file that processed by the golang application:

2023/11/24 04:53:18.475116 main.INFO File system has been successfully mounted.
run python sample.py
Downloading: "https://download.pytorch.org/models/resnet18-f37072fd.pth" to /root/.cache/torch/hub/checkpoints/resnet18-f37072fd.pth

  0%|          | 0.00/44.7M [00:00<?, ?B/s]
  0%|          | 208k/44.7M [00:00<00:22, 2.11MB/s]
  3%|▎         | 1.25M/44.7M [00:00<00:07, 6.11MB/s]
  6%|▌         | 2.62M/44.7M [00:00<00:05, 8.26MB/s]
 15%|█▌        | 6.88M/44.7M [00:00<00:01, 20.6MB/s]
 20%|██        | 9.01M/44.7M [00:00<00:02, 17.9MB/s]
 26%|██▌       | 11.5M/44.7M [00:00<00:01, 19.8MB/s]
 31%|███       | 13.6M/44.7M [00:00<00:01, 20.4MB/s]
 35%|███▌      | 15.7M/44.7M [00:00<00:01, 20.6MB/s]
 40%|███▉      | 17.7M/44.7M [00:01<00:01, 20.8MB/s]
 44%|████▍     | 19.8M/44.7M [00:01<00:01, 20.8MB/s]
 49%|████▉     | 21.8M/44.7M [00:01<00:01, 20.9MB/s]
 54%|█████▍    | 24.1M/44.7M [00:01<00:01, 21.0MB/s]
 58%|█████▊    | 26.1M/44.7M [00:01<00:00, 20.3MB/s]
 64%|██████▎   | 28.4M/44.7M [00:01<00:00, 21.2MB/s]
 68%|██████▊   | 30.5M/44.7M [00:01<00:00, 21.2MB/s]
 74%|███████▍  | 33.0M/44.7M [00:01<00:00, 22.5MB/s]
 79%|███████▊  | 35.2M/44.7M [00:01<00:00, 21.2MB/s]
 83%|████████▎ | 37.2M/44.7M [00:02<00:00, 21.0MB/s]
 88%|████████▊ | 39.3M/44.7M [00:02<00:00, 21.3MB/s]
 93%|█████████▎| 41.5M/44.7M [00:02<00:00, 21.2MB/s]
 98%|█████████▊| 43.8M/44.7M [00:02<00:00, 21.3MB/s]
100%|██████████| 44.7M/44.7M [00:02<00:00, 19.9MB/s]
Epoch 0/1
----------
train Loss: 0.5612 Acc: 0.7172
val Loss: 0.3160 Acc: 0.8758

Epoch 1/1
----------

I try to understand how docker processes stdout and stderr log.
Could we have the way that lets the Docker show the full progress bar?

2

So how is it related to Docker? If Kubernetes uses containerd which is the default in recent Kubernetes, there is no Docker involved.

Let’s say you use Docker and not containerd. I don’t think that what you see in the log file has anything to do with Docker. In an interactive terminal you when you see a single line as progressbar, that is an application rewriting the same line in the terminal which requires repositioning the cursor. Usually when you have a progressbar without an interactive terminal, the application writes the progressbar lines, but without the interactive terminal, you will see each line.

I’m actually surprised that in your case the log file contains only the final line. It could be that the aploication detects that you don’t have a terminal so it writes only the final line. Docker Containerd or Kubernetes will not change the error stream and will not even know when you have a progressbar. It is just output. Everíthing that goes to the standard error stream or standard output will be written to a json file and when you get the logs using the client (docker logs or kubectl logs) you will read that json.

Did you check the log file too in that case? I’m already surprised but I would be even more surprised if the log file would not contain the progress when you saw it on the screen. If that is the case, then I can only think that Kubernetes with containerd doesn’T work as I thought and it somehow sends the output to the standard streams and sends something different to the json files. Or a more likely way could be that Kubernetes supports rewriting the last line in the json logs detecting that the application wanted to write the same line, but it can’t rewrite what you already see on a dashboard which is not managed by Kubernetes directly.

3

Hi @rimelek,

Thanks for your response!

Did you check the log file too in that case? I’m already surprised but I would be even more surprised if the log file would not contain the progress when you saw it on the screen.

I am sorry, What log file did you mean here?
If you mean the raw log in the directory: /var/log/pods/_, I already shared the log content in the question.
I re-attach some information here:

  • The log file content that I am using cat command to get the output, you can see in the output we only have one line of the progress bar:
download: s3://kimnh-test/hymenoptera_data/val/ants/ants-devouring-remains-of-large-dead-insect-on-red-tile-in-Stellenbosch-South-Africa-closeup-1-DHD.jpg to ../../aiplatform/input/val/ants/ants-devouring-remains-of-large-dead-insect-on-red-tile-in-Stellenbosch-South-Africa-closeup-1-DHD.jpg
2023-11-24T04:53:30.222016269Z stderr F 2023/11/24 04:53:30.221735 s3.INFO Switching from region 'us-east-1' to 'ap-southeast-1'
2023-11-24T04:53:30.596892481Z stderr F 2023/11/24 04:53:30.596795 main.INFO File system has been successfully mounted.
2023-11-24T04:53:30.60038546Z stdout F run python sample.py
2023-11-24T04:53:37.028559324Z stderr F Downloading: "https://download.pytorch.org/models/resnet18-f37072fd.pth" to /root/.cache/torch/hub/checkpoints/resnet18-f37072fd.pth
100%|██████████| 44.7M/44.7M [00:02<00:00, 22.9MB/s]
2023-11-24T04:53:49.316040711Z stdout F Epoch 0/1
2023-11-24T04:53:49.316066991Z stdout F ----------
2023-11-24T08:28:08.269246372Z stdout F train Loss: 0.4961 Acc: 0.7582
2023-11-24T09:10:53.332419433Z stdout F val Loss: 0.2540 Acc: 0.8889
2023-11-24T09:10:53.33245518Z stdout F 
2023-11-24T09:10:53.332461372Z stdout F Epoch 1/1
2023-11-24T09:10:53.33246572Z stdout F ----------
2023-11-24T14:51:19.932292384Z stdout F train Loss: 0.4983 Acc: 0.7664
2023-11-24T16:08:25.421694138Z stdout F val Loss: 0.4678 Acc: 0.8170
2023-11-24T16:08:25.421714276Z stdout F 
2023-11-24T16:08:25.421717783Z stdout F Training complete in 672m 16s
2023-11-24T16:08:25.421720728Z stdout F Best val Acc: 0.888889
2023-11-24T16:08:26.182466811Z stdout F total 43656
2023-11-24T16:08:26.182502178Z stdout F -rw-r--r-- 1 root root 44700647 Nov 24 16:08 model.onnx
2023-11-24T16:08:26.182609691Z stdout F Training done
2023-11-24T16:08:26.182614941Z stdout F Pushing model
upload: ./model.onnx to s3://kimnh-test/model/1/model.onnx         B (358.1 KiB/s) with 1 file(s) remaining
2023-11-24T16:08:41.451756744Z stdout F Model have been pushed
filebeat@filebeat-djvgd:/var/log/pods/logging_tj-tantm3-test-worker-0_7c88431c-d138-4d92-9c30-ae5366bf61a6/pytorch$
  • Here is the log content from Lens’s log console feature, you can see all the graphic progress bars:

image
image1669×677 102 KB

4

I know you shared the log file but it wasn’t clear to me when you checked that file. If you just read it before you tried it in Lens, it could be that lens made the app generate the progressbar and you would see it in the log file too. If you checked the log file after seeing the logs in Lens, and you didn’t see the progressbar but you saw it in Lens, then I have no idea except Kubernetes rewriting the last log line.

If you can’T reproduce this behavior in Docker, that it is a Kubernetes issue. Since containerd is behind Docker too, it is probably not a containerd issue.

5

If you can’T reproduce this behavior in Docker, that it is a Kubernetes issue.

I will try to reproduce the case with Docker.

If you checked the log file after seeing the logs in Lens, and you didn’t see the progressbar but you saw it in Lens, then I have no idea except Kubernetes rewriting the last log line.

About the logging flow, I think Kubernetes is not involved in writing and storing the log file, it’s the responsibility of the container runtime which is containerd.
So, I think maybe that is the behavior from containerd and the Kubernetes-Dashboard project have the logic that converts the rewriting log line.