Uploaded image for project: 'Openshift sandboxed containers'
  1. Openshift sandboxed containers
  2. KATA-4112

Sandbox container logs aren't rotated per kubelet policy

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Done
    • Icon: High High
    • None
    • None
    • sandboxed-containers
    • None
    • Quality / Stability / Reliability
    • False
    • Hide

      None

      Show
      None
    • 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"
      ~~~

              jrope Julien ROPE
              rhn-support-fhirtz Frank Hirtz
              Cameron Meadors Cameron Meadors
              Votes:
              1 Vote for this issue
              Watchers:
              8 Start watching this issue

                Created:
                Updated:
                Resolved: