Pod in ra 400.000 dòng nhật ký, nằm sờ sờ 53 MB trên đĩa — kubectl logs trả về đúng 0 dòng, không một lời cảnh báo

Tưởng tượng một cuốn sổ trực ca chỉ giữ đúng trang đang viết: viết đầy trang là xé trang cũ vứt đi, mở một trang trắng. Ngày bình thường thì chẳng sao. Nhưng đúng cái đêm xảy ra sự cố — khi mọi thứ hỏng và người trực ghi lia lịa từng phút — cuốn sổ đầy nhanh nhất, xé trang nhanh nhất, và cái nó xé đi trước tiên lại chính là những dòng đầu tiên ghi lúc sự cố mới chớm: nguyên nhân gốc. Sáng ra mở sổ, bạn chỉ còn thấy triệu chứng cuối cùng. kubectl logs mặc định là cuốn sổ ấy, và bài này đo để chỉ ra đúng khoảnh khắc nó phản bội bạn.

kubectl logs là lệnh ai cũng gõ trước tiên khi có sự cố. Bài này đo xem nó thực sự đọc cái gì — và cái gì nó không đọc.

Đường đi

ứng dụng ghi stdout
   -> containerd ghi ra tệp
      /var/log/pods/<ns>_<pod>_<uid>/<container>/0.log
         -> kubelet đọc lại khi có ai gọi kubectl logs

Không có cơ sở dữ liệu, không có bộ đệm. Chỉ là một tệp văn bản trên đĩa của node, mỗi dòng kèm dấu thời gian và nhãn stdout/stderr. Điều đó giải thích một chuyện hay bị hỏi: log không đi qua control plane. kubectl logs mở một luồng tới kubelet của đúng node đó. Node chết là không đọc được nữa, dù pod vẫn còn trong etcd.

Đo: 400.000 dòng, trả về 0 dòng

Tôi cho một pod in 400.000 dòng liên tục rồi ngủ, và đợi. Trên node:

        0 byte   0.log
55.392.273 byte  0.log.20260831-160306

kubectl logs:

0 dòng

Không lỗi. Không cảnh báo. Không có gì cho biết 53 MB nhật ký đang nằm ngay đó. Tôi tưởng mình gõ nhầm tên pod. Một pod khác in ba dòng thì kubectl logs trả về đúng ba dòng, nên lệnh không hỏng.

Lần đo thứ hai, rõ hơn

Lần này pod in 300.000 dòng nhanh, rồi in tiếp mỗi hai giây một dòng.

40.940.121 byte  0.log.20260831-160526   (300.000 dòng "cu")
     1.678 byte  0.log                   (36 dòng "moi")

kubectl logs -> 36 dòng, dòng đầu là "moi 1"

Đủ rõ: kubectl logs chỉ đọc tệp hiện tại. Mọi thứ đã xoay vòng coi như mất, kể cả khi tệp còn nguyên trên đĩa.

Hệ quả thực tế đáng sợ hơn nó nghe: một pod ồn ào tự xoá nhật ký của chính nó. Đúng lúc sự cố xảy ra, ứng dụng thường in nhiều nhất — stack trace, retry, warning — và chính lượng đó đẩy phần đầu của sự cố ra khỏi tầm với của kubectl logs. Bạn mở log lên và chỉ thấy triệu chứng cuối cùng. Cách chữa duy nhất là gom log ra ngoài. kubectl logs là công cụ xem nhanh, không phải nơi lưu trữ.

Trong lúc chưa có bộ gom, còn một đường: đọc thẳng tệp đã xoay vòng trên node.

kubectl debug node/<node> -it --image=busybox -- \
  ls -la /host/var/log/pods/<ns>_<pod>_<uid>/<container>/

Xấu, nhưng đó là chỗ duy nhất còn dữ liệu.

containerLogMaxSize không phải trần cứng

Mặc định của kubelet là containerLogMaxSize: 10Mi và containerLogMaxFiles: 5. Tôi trông đợi tệp đã xoay vòng nặng khoảng 10 MB. Đo được 55 MB và 40 MB.

Lý do: kubelet kiểm tra định kỳ rồi mới xoay vòng, chứ không chặn lúc ghi. Giữa hai lần kiểm tra, container ghi được bao nhiêu thì ghi. Container ghi nhanh thì vượt trần vài lần là chuyện thường. Nghĩa là phép tính dung lượng đĩa quen thuộc — 10Mi × 5 tệp × số container — thiếu vài lần trong tình huống xấu nhất. Node hết ephemeral-storage vì log là sự cố có thật, và nó xảy ra đúng lúc mọi thứ đang hỏng nên mọi ứng dụng đều đang in nhiều.

--previous và giới hạn của nó

kubectl logs <pod> --previous

Đọc log của lần chạy trước của container — cứu tinh khi pod CrashLoopBackOff, vì log của lần chạy hiện tại thường trống rỗng. Giới hạn: chỉ giữ một lần trước. Container khởi động lại hai lần là lần đầu tiên mất hẳn, mà lần đầu tiên mới là lần chứa nguyên nhân gốc.

Vài lệnh hữu dụng ít người dùng:

kubectl logs <pod> --since=15m           # theo thời gian
kubectl logs <pod> --timestamps          # thêm dấu thời gian
kubectl logs -l app=web --max-log-requests=20   # gom nhiều pod
kubectl logs <pod> -c <container> -f     # theo dõi một container cụ thể

-l rất tiện lúc điều tra, nhưng nhớ là nó chỉ theo dõi pod đang tồn tại lúc gõ lệnh — pod mới sinh ra sau đó không tự vào luồng.

Sự kiện: nửa còn lại, và nó hết hạn

kubectl logs cho biết ứng dụng nói gì. kubectl get events cho biết Kubernetes nói gì — vì sao pod không xếp được lịch, vì sao image kéo hỏng, vì sao probe trượt.

kubectl get events -n <ns> --sort-by=.lastTimestamp
kubectl describe pod <pod> | sed -n '/Events:/,$p'

Bẫy lớn nhất: sự kiện chỉ giữ một giờ (--event-ttl mặc định của API server). Sự cố lúc 2 giờ sáng, 9 giờ sáng mở lên xem thì không còn gì. Và khác với log, sự kiện đã hết hạn thì không còn ở đâu trên đĩa cả. Nên khi bắt được sự cố, việc đầu tiên là chụp lại:

kubectl get events -A -o yaml > su-kien-$(date +%s).yaml

Gõ trước, đọc sau. Một phút chần chừ có thể là một giờ mò mẫm.

Mẫu số chung: cửa sổ quan sát tự thua đúng lúc bạn cần nó nhất

Bài này gói một nghịch lý đáng nhớ về quan sát hệ thống: công cụ đầu tiên bạn với tới thường chỉ cho thấy một cửa sổ gần đây, và cửa sổ đó loại bỏ dữ liệu cũ nhất — nên khi khối lượng tăng vọt lúc sự cố, chính nguyên nhân gốc (những dòng sớm nhất) là thứ bị đẩy ra trước. Sự cố tự tay xoá bằng chứng về nguồn gốc của nó, và nó làm việc đó nhanh hơn đúng vào lúc nó nghiêm trọng hơn. Đây không phải chuyện riêng Kubernetes — nó là bản chất của mọi bộ đệm cuộn: một RollingFileAppender của logback với maxHistory cố định, journald giới hạn dung lượng, scrollback của terminal, dmesg. Một OOM ghi ngập log sẽ đẩy đúng cái dòng cấp phát khởi đầu ra khỏi tầm nhìn. Bài học mang đi: cái tail đang chạy chỉ để phân loại nhanh; muốn còn nguyên nhân gốc thì phải đẩy log ra một nơi lưu bền, ngay từ trước sự cố — vì lúc sự cố nổ ra thì đã muộn để bắt đầu giữ.

Bài học thứ hai, âm thầm hơn: một giới hạn được thi hành bằng cách quét định kỳ là cap mềm, không phải trần cứng. 10Mi hoá ra 55 MB vì kubelet chỉ ngó lại theo chu kỳ, còn container thì ghi không nghỉ giữa hai lần ngó. Cùng hình dạng với ngưỡng kích hoạt GC (heap vọt lên giữa hai lần thu gom), với logrotate chạy theo cron (tệp phình to giữa hai lần chạy), với hạn mức đĩa kiểm theo lượt, với cửa sổ của một rate limiter. Hệ quả chung: phép tính dung lượng/tài nguyên dựa trên con số danh nghĩa luôn lạc quan hơn thực tế xấu nhất — phải cộng thêm phần vượt-giữa-hai-lần-quét, đúng lúc tải cao là lúc phần vượt đó lớn nhất.

Mẫu số chung: đừng coi cái nhìn trực tiếp (live tail) là nơi lưu trữ, và đừng coi một giới hạn quét-định-kỳ là trần không thể vượt — cả hai đều phản bội đúng vào lúc tải cao: một bên xoá mất khởi đầu của sự cố, một bên phình quá con số bạn đã lập kế hoạch.

Muốn tự soi, xem pod nào đang xoay vòng log nhanh nhất — tức là pod đang mất log của chính nó:

kubectl get --raw "/api/v1/nodes/<node>/proxy/stats/summary" \
  | python3 -c '
import sys, json
d = json.load(sys.stdin)
r = []
for p in d.get("pods", []):
    for c in p.get("containers", []):
        b = (c.get("logs") or {}).get("usedBytes")
        if b: r.append((b, p["podRef"]["namespace"], p["podRef"]["name"], c["name"]))
for b, ns, n, c in sorted(r, reverse=True)[:10]:
    print(f"{b/1e6:8.1f} MB  {ns}/{n}  {c}")
'

Đây là tổng cả tệp đã xoay vòng, không phải riêng tệp hiện tại — tôi đã đoán nhầm và phải chạy lại mới thấy: pod noi ở trên có 0.log rỗng mà vẫn báo 55,4 MB. Điều đó lại làm con số này hữu dụng hơn. Pod nào vượt xa 10Mi là pod đã xoay vòng ít nhất một lần, tức là đã có một khối log biến mất khỏi tầm với của kubectl logs. Sắp xếp giảm dần rồi gom log của mấy pod đầu bảng trước.

Phần sau: chỉ số — metrics-server đo gì, Prometheus đo gì, và vì sao hai con số không bao giờ khớp nhau.