-
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"
~~~