cri-dockerd 로그 로테이션 에러를 발견한 경위

노드 유지보수를 준비하다가 kubelet이 하루에 노드당 3만~8만 줄의 동일한 에러를 남기고 있는 것을 발견했습니다. 원인은 cri-dockerd 로그 로테이션 요청이 구조적으로 성공할 수 없는 구성에 있었습니다. kubelet은 컨테이너 로그가 임계값을 넘으면 로테이션을 요청하는데, cri-dockerd는 그 요청을 처리할 수 없어 10초마다 거부하고 kubelet은 10초마다 다시 요청했습니다.

이 글은 그 무한 재시도를 어떻게 측정하고 끊었는지, 그리고 같은 작업 창에서 함께 처리한 커널 롤링 재부팅 기록입니다. 재부팅 과정에서 문서에 “영구화 완료”로 적혀 있던 부팅 스크립트가 실은 한 번도 동작한 적이 없었다는 사실도 드러났는데, 그 쪽이 더 값진 수확이었습니다.

환경

로그 로테이션 에러를 끊은 과정

1. 에러 규모를 먼저 측정했습니다

로그가 시끄럽다는 인상만으로는 우선순위를 정할 수 없으므로 노드별로 발생량을 세었습니다. 함께 컨테이너 로그 총량과 journald 점유량도 같이 확인했습니다.

journalctl -u kubelet --since "24 hours ago" --no-pager \
  | grep -ci "ReopenContainerLog\|Failed to rotate log"
du -sh /var/lib/docker/containers
journalctl --disk-usage

결과는 예상보다 컸습니다. 4대만 추려도 하루치 에러가 아래와 같았고, journald는 노드당 2.6~4.0 GB를 점유하고 있었습니다. 디스크가 50 GB인 노드에서 무시할 양이 아닙니다.

2. 에러 본문에서 원인이 그대로 드러났습니다

발생 빈도가 10초 간격이라는 점이 단서였습니다. 크기 기반 로테이션이라면 이렇게 잦을 수 없으므로 실제 메시지를 확인했습니다.

E1011 11:39:41 container_log_manager.go:266] "Failed to rotate log for container"
  err="failed to rotate log \"/var/log/pods/.../csi-snapshotter/0.log\":
       failed to reopen container log \"bcce9138ed39\":
       rpc error: code = Unknown desc = docker does not support reopening container log files"
  currentSize=65818371 maxSize=10485760

두 숫자가 전부를 설명합니다. maxSize=10485760은 kubelet의 containerLogMaxSize 기본값 10 Mi이고, currentSize는 62.8 MiB로 이미 그 임계를 한참 넘긴 상태입니다. kubelet은 임계를 넘은 파일을 발견하면 CRI의 ReopenContainerLog를 호출해 로테이션을 수행하는데, cri-dockerd는 이 RPC를 구현하지 않습니다.

즉 cri-dockerd 환경에서 kubelet이 보내는 로그 로테이션 요청은 영원히 성공할 수 없었고, kubelet은 그 요청을 10초마다 재시도하고 있었습니다. 파일이 임계 아래로 내려갈 일이 없으므로 이 루프는 컨테이너가 재생성될 때까지 멈추지 않습니다. 로그 용량 문제가 아니라 끝나지 않는 재시도가 본질이었습니다.

3. 로그 로테이션 주체를 docker로 넘겼습니다

기존 설정은 max-size가 100m이고 max-file이 없었습니다. json-file 드라이버에서 max-file을 생략하면 기본값이 1이므로 이력이 남지 않고, 100 MiB는 kubelet 임계값 10 Mi보다 훨씬 커서 위 루프를 항상 유발합니다.

해결 방향은 두 가지가 있었습니다. kubelet의 containerLogMaxSize를 키워 로테이션 시도 자체를 막는 방법과, docker의 상한을 kubelet 임계값보다 작게 두는 방법입니다. 후자를 택했습니다. 전자는 kubelet 설정을 바꿔야 하는데 그 값은 클러스터 전역 ConfigMap에서 내려오므로 변경 범위가 노드 밖으로 커집니다.

로그 파일이 8 MiB에서 회전하므로 10 Mi에 도달하는 일 자체가 없어지고, kubelet은 로테이션을 시도할 이유를 잃습니다. 실제 회전은 docker가 수행하며 직전 2세대가 남습니다. 결과적으로 cri-dockerd 로그 로테이션 경로는 더 이상 호출되지 않습니다.

# /etc/docker/daemon.json
{
  "exec-opts": ["native.cgroupdriver=systemd"],
  "log-driver": "json-file",
  "log-opts": {
    "max-size": "8m",
    "max-file": "3"
  },
  "storage-driver": "overlay2"
}

적용 전 반드시 검증해야 합니다. daemon.json이 깨지면 재부팅 후 docker가 기동하지 못해 노드가 그대로 죽습니다. JSON 구문 검사만으로는 부족하므로 dockerd 자체의 검증기를 통과시킨 뒤 설치했습니다.

sudo cp -a /etc/docker/daemon.json /etc/docker/daemon.json.bak-$(date +%Y%m%d)
python3 -m json.tool /tmp/dj.new > /dev/null          # 구문
sudo dockerd --validate --config-file /tmp/dj.new     # dockerd 레벨 → "configuration OK"
sudo install -m 644 -o root -g root /tmp/dj.new /etc/docker/daemon.json

docker는 재시작하지 않았습니다. 재시작하면 해당 노드의 모든 컨테이너가 재생성되므로, 어차피 진행할 롤링 재부팅에서 자연히 반영되도록 두었습니다.

4. journald 상한을 고정했습니다

SystemMaxUse는 기본적으로 주석 처리되어 있고, 그 경우 파일시스템의 10 %를 쓸 수 있습니다. 50 GB 디스크에서 약 5 GB이며 실제로 4 GB에 근접해 있었습니다. 에러 폭주를 끊어도 상한 자체는 남겨두는 편이 안전합니다.

sudo sed -i -E 's|^[[:space:]]*#?[[:space:]]*SystemMaxUse=.*|SystemMaxUse=1G|' \
  /etc/systemd/journald.conf
sudo systemctl restart systemd-journald
sudo journalctl --vacuum-size=1G

6대 합계로 약 15 GB를 회수했습니다. 노드당 여유 공간이 마스터는 34 → 36 GB, 워커는 23 → 26 GB로 늘었습니다.

5. 롤링 재부팅으로 설정과 커널을 함께 반영했습니다

때마침 커널 드리프트가 쌓여 있었습니다. 6대 전부 6.8.0-146이 설치만 된 상태였고 1대만 그 커널로 가동 중이었습니다. 나머지 5대는 6.8.0-124로 돌고 있어, 다음 재부팅에서 커널이 바뀐다는 뜻입니다. 계획된 창에서 바꾸는 편이 장애 상황에서 마주치는 것보다 낫습니다.

마스터 3대 → 워커 3대 순으로 한 대씩 진행했습니다. 워커 구간은 OSD 하나가 내려가는 동안 Ceph가 리밸런싱을 시작하지 않도록 감쌌습니다.

kubectl -n rook-ceph exec deploy/rook-ceph-tools -- ceph osd set noout   # 워커 구간 시작

kubectl drain <node> --ignore-daemonsets --delete-emptydir-data --timeout=600s
ssh <admin-user>@<node-ip> 'sudo systemctl reboot'

until kubectl get node <node> \
      -o jsonpath='{.status.conditions[?(@.type=="Ready")].status}' | grep -q True;
do sleep 10; done
kubectl uncordon <node>

kubectl -n rook-ceph exec deploy/rook-ceph-tools -- ceph osd unset noout # 워커 구간 종료

노드마다 다음 게이트를 모두 통과한 뒤에만 다음 노드로 넘어갔습니다. 커널 버전, ceph 커널 모듈 적재, docker 로그 설정, kubelet·docker 활성 상태, 그리고 마스터는 etcd 쿼럼, 워커는 Ceph의 전체 PG가 active+clean으로 복귀했는지입니다.

전체 약 40분이 걸렸고 서비스 중단은 없었습니다. Ingress 뒤의 웹 워크로드는 작업 내내 HTTP 200을 유지했습니다.

재부팅하면서 드러난 문제

부팅 스크립트가 매번 조용히 실패하고 있었습니다

현상 – 첫 마스터를 재부팅한 직후, ClusterIP를 HAProxy로 넘기는 DNAT 규칙이 0건이었습니다. 운영 문서에는 /etc/rc.local로 영구화했다고 적혀 있었고 파일도 실행 권한을 갖고 있었습니다.

systemctl status rc-local.service

  rc-local.service: Failed to execute /etc/rc.local: Exec format error
  Process: 822 ExecStart=/etc/rc.local start (code=exited, status=203/EXEC)

원인 – 파일에 shebang이 없었습니다. 실행 권한만으로는 systemd가 인터프리터를 결정할 수 없어 203/EXEC로 떨어집니다. 그 결과 “재부팅 영구화”라고 기록된 장치가 실은 한 번도 동작한 적이 없었습니다. 마스터를 재부팅한 적이 없어서 드러나지 않았을 뿐입니다.

해결 – shebang을 추가하고, 규칙을 넣기 전에 -C로 존재를 확인하도록 다시 썼습니다. 재실행해도 중복이 쌓이지 않습니다.

#!/bin/sh -e
for CHAIN in OUTPUT PREROUTING; do
  iptables -t nat -C "$CHAIN" -d 10.96.0.1 -p tcp --dport 443 \
    -j DNAT --to-destination 192.168.x.x:6443 2>/dev/null ||
  iptables -t nat -I "$CHAIN" -d 10.96.0.1 -p tcp --dport 443 \
    -j DNAT --to-destination 192.168.x.x:6443
done
exit 0

다음 마스터를 재부팅했을 때 규칙이 정확히 2건으로 복원되어 실동작을 확인했습니다.

한 가지 덧붙이면 이 결함의 기능적 영향은 없었습니다. 규칙이 0건인 상태에서도 https://10.96.0.1:443/healthz가 HTTP 200을 반환했습니다. 정상 가동 중에는 kube-proxy가 ClusterIP를 처리하므로, 이 DNAT는 kube-proxy가 아직 준비되지 않은 control plane 조인 시점에만 필요합니다. 그래서 결함이 오래 숨어 있을 수 있었습니다.

같은 파일에 규칙이 중복 기재되어 있었습니다

현상 – 수정 후 서비스를 재시작했더니 한 노드는 규칙이 2건인데 다른 두 노드는 6건이 됐습니다.

원인 – 두 노드의 rc.local 안에 iptables 두 줄이 각각 두 번 적혀 있었습니다. 실행마다 4건이 삽입되던 셈입니다. 동일한 DNAT 규칙이 중복되면 첫 매칭만 평가되므로 기능상 무해하지만, 규칙 수로 상태를 판단할 수 없게 됩니다.

해결 – 중복 줄을 제거해 3대의 파일을 통일하고, 라이브 테이블에서도 체인별 1건만 남도록 정리했습니다. 위의 -C 검사가 재발을 막습니다.

CephFS 커널 모듈이 부팅 시 적재되지 않았습니다

현상 – 앞서 한 워커가 커널 교체와 함께 재부팅된 뒤, RWX 볼륨을 쓰는 워크로드가 마운트에 실패했습니다.

MountVolume.MountDevice failed ... an error (exit status 1) occurred
while running modprobe args: [ceph]

원인 – 모듈 파일은 새 커널 트리에 정상적으로 존재했고 수동 modprobe ceph도 성공했습니다. 모듈 부재가 아니라 부팅 시 자동 적재가 되지 않은 것이었습니다.

해결 – /etc/modules-load.d/ceph.conf로 영구화하고 6대 전부에 배포했습니다. 설정 파일이 존재한다는 사실만으로는 검증이 안 되므로, 모듈을 내린 뒤 적재 서비스를 재시작해 부팅을 재현했습니다.

sudo modprobe -r ceph                       # 사용 중이면 실패하는데 그건 정상
sudo systemctl restart systemd-modules-load
lsmod | grep '^ceph '                       # 적재돼 있어야 한다

이후 6대 재부팅 전부에서 자동 적재를 확인했습니다. 블록 스토리지(RBD)는 이 문제와 무관하며 CephFS를 쓰는 워크로드만 영향을 받습니다.

로그 로테이션 설정 적용 후에도 큰 파일이 남아 있었습니다

현상 – 재부팅을 마치고 확인했더니 8 MiB를 넘는 로그 파일이 노드당 1~3건 남아 있었습니다. 설정이 먹지 않은 것처럼 보였습니다.

원인 – 해당 파일들의 소유 컨테이너를 역추적하니 모두 exited 상태였고, 마지막 수정 시각이 재부팅 시점이었습니다. 구 100m 설정으로 돌던 컨테이너들의 잔존 로그였습니다. 더 커지지 않으며 docker가 해당 컨테이너를 정리할 때 함께 사라집니다.

확인 – 신규 컨테이너에 설정이 실제로 적용됐는지는 파일 크기가 아니라 컨테이너의 로그 설정을 직접 조회해 판단해야 합니다.

docker inspect $(docker ps -q | head -1) \
  --format '{{json .HostConfig.LogConfig}}'

{"Type":"json-file","Config":{"max-file":"3","max-size":"8m"}}

파드가 원래 노드로 돌아오지 않습니다

현상 – 6대를 모두 순회한 뒤 메모리 사용률이 한쪽으로 쏠렸습니다. 한 워커는 68 %인데 다른 워커는 25 %였습니다.

원인 – drain으로 옮겨진 파드는 노드가 복귀해도 자동으로 되돌아오지 않습니다. 순차 재부팅에서는 뒤에 처리한 노드의 파드가 앞서 복귀한 노드로 모이기 쉽습니다.

대응 – 기능 문제는 아니지만 노드 메모리 여유가 빠듯한 환경에서는 지켜볼 값입니다. 작업 직후 kubectl top nodes로 분포를 확인하고, 필요하면 해당 디플로이먼트를 재시작해 재배치를 유도하는 편이 안전합니다. 스케줄러가 선언된 requests를 기준으로 판단하므로, 실사용이 requests보다 큰 워크로드에서는 스케줄러의 여유 표시를 그대로 믿기 어렵습니다.

로그 로테이션 조치 결과

cri-dockerd 로그 로테이션 요청의 무한 재시도는 완전히 멈췄습니다. 재부팅 이후 수집 구간에서 6대 모두 해당 에러가 0건입니다.

journalctl -b -u kubelet --no-pager | grep -c "ReopenContainerLog"
# 6대 전부 0

클러스터 상태도 함께 확인했습니다. 6대 전부 Ready이고 스케줄 가능 상태이며, etcd 3개 엔드포인트가 모두 정상, Ceph는 HEALTH_OK에 mon 3/3, OSD 3/3, 전체 PG active+clean입니다.

kubectl get nodes -o custom-columns=\
'NODE:.metadata.name,STATUS:.status.conditions[-1].status,KERNEL:.status.nodeInfo.kernelVersion'

kubectl get pods -A | grep -v Running | grep -v Completed
kubectl -n rook-ceph exec deploy/rook-ceph-tools -- ceph -s

정리하면 이번 작업의 핵심은 두 가지입니다. 하나는 런타임이 지원하지 않는 기능을 요청하는 구성은 조용히 자원을 태운다는 점입니다. cri-dockerd 로그 로테이션 문제는 로테이션 주체를 docker로 옮겨 해결했습니다. 다른 하나는 부팅 시 동작하는 설정은 실제로 재부팅해 보기 전까지 검증된 것이 아니라는 점입니다. 이번에 드러난 rc.local 결함과 커널 모듈 자동 적재 문제 모두 재부팅 없이는 알 수 없었습니다.

확인하지 않은 범위도 남겨둡니다. kubelet의 containerLogMaxSize를 직접 조정하는 방식은 시도하지 않았고, max-size를 10 Mi 이상으로 되돌리면 같은 에러가 재발하는지도 실측하지 않았습니다. 동작 원리상 재발이 예상되지만 측정한 결과는 아닙니다.

참고

관련 포스트:

• Diagnosing a 9-Second Node Blackout – 노드 순단이 스토리지 컨트롤 파드 축출로 번진 장애 추적과 축출 유예 시간 조정
• Upgrading Kubernetes Add-ons: Calico, MetalLB, and Traefik – 무중단을 전제로 한 애드온 순차 업그레이드 절차
• Preserving the Real Client IP Behind Traefik – Ingress 경로의 설정이 기대와 다르게 동작할 때의 검증 방법

참고 문서: Kubernetes Logging Architecture · Docker json-file logging driver · cri-dockerd · journald.conf