-
Bug
-
Resolution: Done
-
High
-
None
-
None
-
None
-
Quality / Stability / Reliability
-
False
-
-
False
-
-
-
Denali #2
-
Important
Description of problem:
Logs aren't rotating for sandboxed containers. This leads to the log continuously getting larger and may eventually result in storage consumption issues
Version-Release number of selected component (if applicable):
OCP 4.18.21 Sandbox Containers 1.10.1
How reproducible:
Always
Steps to Reproduce:
1. Create kata deployment that creates significant console logging. 2. Wait for a few minutes 3. Check on the node to see if the logs are being rotated
Actual results:
Create a deployment that does significant logging: ~~~ fmhirtz@fedora:~/OpenShift/Test/Kata$ cat deployment.yaml --- apiVersion: apps/v1 kind: Deployment metadata: name: logger3 spec: replicas: 1 selector: matchLabels: app: logger3 strategy: type: Recreate template: metadata: annotations: openshift.io/required-scc: restricted-v2 labels: app: logger3 spec: automountServiceAccountToken: false containers: - command: - /bin/sh - -c - "while true; do date; dd if=/dev/urandom of=/dev/stdout count=10 bs=100K | base64; echo; sleep 1; done" image: registry.redhat.io/ubi9/ubi@sha256:8851294389a8641bd6efcd60f615c69e54fb0e2216ec8259448b35e3d9a11b06 name: logger3 resources: limits: cpu: 250m ephemeral-storage: 2Gi memory: 512Mi requests: cpu: 250m ephemeral-storage: 2Gi memory: 512Mi securityContext: readOnlyRootFilesystem: true runtimeClassName: kata --- In seperate terminal, open a debug shell on the node that this is going to run, grab the logs, and filter for the kubelet error that's indicative of a rotation issue (I expect that it's a symptom, not the issue itself): Term 1: ~~~ sh-5.1# journalctl -f | tee /tmp/katatest.out | grep "Failed to stat container log after reopen" ~~~ Term 2: Start the kata deployment: ~~~ fmhirtz@fedora:~/OpenShift/Test/Kata$ oc apply -f deployment.yaml deployment.apps/logger3 created fmhirtz@fedora:~/OpenShift/Test/Kata$ oc get pods -l app=logger3 NAME READY STATUS RESTARTS AGE logger3-94d6b864b-l6clm 1/1 Running 0 13s ~~~ Term 1: Monitor for the error (takes around a minute in my test), then check the logs for the container: ~~~ sh-5.1# journalctl -f | tee /tmp/katatest.out | grep "Failed to stat container log after reopen" Aug 20 13:14:42 sno-mau-1-worker-1 kubenswrapper[3901407]: E0820 13:14:42.301788 3901407 container_log_manager.go:297] "Failed to stat container log after reopen" err="stat /var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log: no such file or directory" worker=1 containerID="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" path="/var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log" ^C sh-5.1# ls -l /var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log ls: cannot access '/var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log': No such file or directory sh-5.1# ls -l /var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/ total 262080 -rw-------. 1 root root 264629847 Aug 20 13:16 0.log.20250820-131432 sh-5.1# while true; do ls -l /var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/; sleep 30; done total 524224 -rw-------. 1 root root 325536589 Aug 20 13:16 0.log.20250820-131432 total 524224 -rw-------. 1 root root 384343057 Aug 20 13:17 0.log.20250820-131432 total 524224 -rw-------. 1 root root 441049220 Aug 20 13:17 0.log.20250820-131432 ~~~ The log continues to grow and doesn't rotate
Expected results:
Log should rotate per the kubelet policy
Additional info:
The kubelet does monitor and try to rotate the log as the error above suggests: ~~~ sh-5.1# grep "container_log_manager.go" /tmp/katatest.out | grep logger3 Aug 20 13:14:02 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:02.199532 3901407 container_log_manager.go:252] "Adding new entry to the queue for processing" id="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" name="logger3" labels={"io.kubernetes.container.name":"logger3","io.kubernetes.pod.name":"logger3-94d6b864b-l6clm","io.kubernetes.pod.namespace":"test","io.kubernetes.pod.uid":"7a63dd0d-d74c-448e-9882-2247df1efa86"} Aug 20 13:14:02 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:02.200305 3901407 container_log_manager.go:302] "log file doesn't need to be rotated" worker=1 containerID="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" path="/var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log" currentSize=2100184 maxSize=52428800 Aug 20 13:14:12 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:12.221306 3901407 container_log_manager.go:252] "Adding new entry to the queue for processing" id="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" name="logger3" labels={"io.kubernetes.container.name":"logger3","io.kubernetes.pod.name":"logger3-94d6b864b-l6clm","io.kubernetes.pod.namespace":"test","io.kubernetes.pod.uid":"7a63dd0d-d74c-448e-9882-2247df1efa86"} Aug 20 13:14:12 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:12.222192 3901407 container_log_manager.go:302] "log file doesn't need to be rotated" worker=1 containerID="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" path="/var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log" currentSize=21002142 maxSize=52428800 Aug 20 13:14:22 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:22.244777 3901407 container_log_manager.go:252] "Adding new entry to the queue for processing" id="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" name="logger3" labels={"io.kubernetes.container.name":"logger3","io.kubernetes.pod.name":"logger3-94d6b864b-l6clm","io.kubernetes.pod.namespace":"test","io.kubernetes.pod.uid":"7a63dd0d-d74c-448e-9882-2247df1efa86"} Aug 20 13:14:22 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:22.245529 3901407 container_log_manager.go:302] "log file doesn't need to be rotated" worker=1 containerID="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" path="/var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log" currentSize=39904240 maxSize=52428800 Aug 20 13:14:32 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:32.266223 3901407 container_log_manager.go:252] "Adding new entry to the queue for processing" id="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" name="logger3" labels={"io.kubernetes.container.name":"logger3","io.kubernetes.pod.name":"logger3-94d6b864b-l6clm","io.kubernetes.pod.namespace":"test","io.kubernetes.pod.uid":"7a63dd0d-d74c-448e-9882-2247df1efa86"} Aug 20 13:14:42 sno-mau-1-worker-1 kubenswrapper[3901407]: I0820 13:14:42.287628 3901407 container_log_manager.go:252] "Adding new entry to the queue for processing" id="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" name="logger3" labels={"io.kubernetes.container.name":"logger3","io.kubernetes.pod.name":"logger3-94d6b864b-l6clm","io.kubernetes.pod.namespace":"test","io.kubernetes.pod.uid":"7a63dd0d-d74c-448e-9882-2247df1efa86"} Aug 20 13:14:42 sno-mau-1-worker-1 kubenswrapper[3901407]: E0820 13:14:42.301788 3901407 container_log_manager.go:297] "Failed to stat container log after reopen" err="stat /var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log: no such file or directory" worker=1 containerID="41f183e116b418a262410d1e543f061d8ccb141642bb7b36ff4391ae607ee685" path="/var/log/pods/test_logger3-94d6b864b-l6clm_7a63dd0d-d74c-448e-9882-2247df1efa86/logger3/0.log" ~~~