logrotate báo 'thành công' rồi nuốt mất 4.317 dòng log — và không một dòng lỗi nào cảnh báo tôi

Xoay vòng log nghe như chuyện dọn dẹp vặt — cắt file cũ, mở file mới, ai chẳng làm được. Nhưng nó giống hơn với việc thay băng cassette trong lúc đang thu âm: có một khoảnh khắc mà đầu ghi không biết nó đang ghi vào đâu, và đúng những gì phát ra trong khoảnh khắc đó biến mất không dấu vết. Ba phần trước tôi đo cái giá của việc sinh log và lưu log. Phần này đo cái hầu như không ai đo: chuyện gì xảy ra trong lúc xoay vòng.

Tôi cho một tiến trình ghi liên tục 300.000 dòng đánh số, chạy logrotate thật ở giữa, rồi đếm xem còn lại bao nhiêu. Con số không bằng nhau — và điều làm tôi lạnh gáy là không có một dòng lỗi nào nói cho tôi biết điều đó. (Chạy trong container debian:12-slim, không cần phần cứng đặc biệt gì; đây là hành vi của hệ điều hành, không phải phép đo perf counter.)

Bảng số liệu

Container debian:12-slim, logrotate thật, một tiến trình Python giữ file mở ở chế độ nối thêm và ghi liên tục. Mỗi dòng dài 130 byte và mang số thứ tự riêng, nên sau khi xong tôi gom mọi tệp app.log* lại và đếm số thứ tự duy nhất. Cái mẹo đánh số này mới là thứ cứu cả thí nghiệm — không có nó thì tôi đã chẳng thấy gì.

Cách 1 — copytruncate (chép nội dung sang tệp mới rồi cắt cụt tệp gốc):

Trung bình khoảng 2 159 dòng mỗi lần xoay.

Cách 2 — đổi tên tệp, tiến trình không được báo mở lại:

Nén:

Hai cách xoay vòng, hai kiểu hỏng — và cả hai đều câm

Tôi muốn nói lại từng cái một, vì điều đáng học không phải "cái nào tốt hơn" mà là chúng hỏng khác kiểu nhau ra sao.

copytruncate mất dữ liệu thật. 4.317 dòng biến mất vĩnh viễn, chỉ với hai lần xoay. Chúng không nằm trong tệp cũ, không nằm trong tệp mới, không nằm ở đâu cả. Và tuyệt nhiên không có lỗi nào: logrotate báo thành công, tiến trình ghi vẫn chạy phây phây, log nhìn vẫn liền mạch. Nếu bạn không đánh số trước từng dòng, bạn sẽ không bao giờ biết mình vừa mất gì.

Đổi tên tệp thì không mất dòng nào, nhưng mọi dòng đi sai chỗ. Tệp app.log mới — đúng cái mà công cụ thu gom log đang chằm chằm theo dõi — có tròn trĩnh 0 dòng, trong khi cả 200.000 dòng vẫn thản nhiên chảy vào tệp đã bị đổi tên. Từ góc nhìn của hệ thống giám sát, dịch vụ của bạn vừa im bặt hoàn toàn. Không mất byte nào, mà vẫn là một thảm hoạ quan sát.

Cái đáng sợ nhất, và là lý do tôi viết hẳn một bài về chuyện tưởng như vặt vãnh này: cả hai kiểu hỏng đều im lặng tuyệt đối. Tôi chỉ tóm được chúng vì đã đánh số từng dòng từ trước rồi ngồi đếm lại. Bỏ cái mốc đối chiếu đó đi, cả hai thí nghiệm đều trông y hệt một thành công mỹ mãn.

Và một chuyện bên lề nhưng cũng đắt giá: tỷ lệ nén của người khác vô dụng với bạn. Cùng lệnh gzip -6, cùng máy, cùng lần chạy: 46,02 lần trên dữ liệu nhân tạo, 7,57 lần trên log JSON thật. Lệch tới 6,1 lần, chỉ vì nội dung khác nhau. Ai bê con số nén của người khác về làm ngân sách đĩa thì sẽ hụt cả nửa.

Vì sao lại thế

copytruncate làm hai việc mà nó giả vờ là một: đọc toàn bộ tệp sang chỗ khác, rồi cắt tệp gốc về 0. Giữa hai việc đó có một khoảng thời gian, và mọi dòng được ghi trong khoảng đó bị cắt mất — nó chưa kịp vào bản sao, mà lại bị xoá khỏi bản gốc. Cửa sổ ấy càng rộng khi tệp càng lớn (chép lâu hơn) và tiến trình ghi càng nhanh. Ở đây tệp vài chục megabyte, tiến trình ghi hết tốc lực, nên cửa sổ ngoạm mất chừng 2.159 dòng mỗi lần.

Vậy tại sao người ta vẫn dùng copytruncate? Vì nó né được vấn đề thứ hai. Trong Linux, một tiến trình đang mở tệp thì bám vào inode, chứ không bám vào tên. Đổi tên app.log thành app.log.1 chẳng đụng gì tới tiến trình đó: nó vẫn ghi vào đúng inode cũ, giờ mang tên mới. Tệp app.log mới tạo là một inode khác hẳn, và sẽ rỗng cho tới khi tiến trình được bảo mở lại tệp — thường bằng SIGHUP, hoặc bằng chỉ thị postrotate trong cấu hình logrotate.

Nên đây không phải chuyện một lựa chọn tốt và một lựa chọn xấu, mà là hai lựa chọn hỏng theo hai cách:

Cách đúng là cách thứ hai kèm bước báo mở lại. copytruncate chỉ nên rút ra dùng khi bạn hết đường bảo tiến trình mở lại tệp.

Còn chuyện nén: gzip đi tìm chuỗi lặp trong một cửa sổ trượt. Dữ liệu nhân tạo của tôi là 120 ký tự x giống hệt nhau ở mọi dòng — gần như cả tệp là một chuỗi lặp, nên tỷ lệ vọt lên 46 lần. Log JSON thật vẫn rất lặp ở phần khung ({"level":"INFO","service":), nhưng có trace_id ngẫu nhiên 16 chữ số hex và user_id rải rác — những phần đó gần như không nén được, và chúng kéo tỷ lệ chung xuống 7,57.

Nghĩa là gì trong công việc hằng ngày

• Kiểm tra ngay hôm nay xem cấu hình của bạn có copytruncate không. Một dòng grep -r copytruncate /etc/logrotate.d/ là đủ. Nếu có, bạn đang mất log mỗi lần xoay vòng, và tỷ lệ mất tăng theo tốc độ ghi.
• Nếu buộc phải dùng copytruncate, hãy xoay theo kích thước lớn và ít lần hơn. Mất mát tính theo số lần xoay, không theo lượng dữ liệu. Xoay mỗi giờ tốn gấp 24 lần xoay mỗi ngày.
• Nếu đổi tên, đừng quên postrotate. Thiếu nó thì bạn không mất log — bạn mất toàn bộ luồng log kể từ lần xoay đầu tiên, và điều đó tệ hơn nhiều.
• Ước lượng dung lượng bằng tỷ lệ nén đo trên chính log của bạn. Với 10.000 dòng mỗi giây ở 161 byte, một ngày là 139 GB thô. Nén 7,57 lần còn 18,4 GB; nếu bạn lỡ tin con số 46 lần thì ngân sách sẽ là 3,0 GB — sai gấp sáu.
• Nén tốn 0,30 giây cho 30,75 MB (103 MB/s). Ở quy mô một ngày, đó là khoảng 22 phút CPU — không đáng kể, nhưng đủ để đừng chạy nó vào giờ cao điểm.

Cùng một cái bẫy inode, đổi ngăn xếp

Chuyện "file handle bám inode chứ không bám tên" không phải đặc sản của logrotate — nó rình mọi nơi có tiến trình sống lâu ghi ra tệp, và các nền tảng khác đều có phiên bản riêng của cái đau này.

Trong Java, Logback và Log4j2 tự làm xoay vòng bên trong tiến trình, nên chúng né được cửa sổ mất mát: cùng một luồng vừa đóng tệp cũ vừa mở tệp mới, không có ai ghi xen vào giữa. Nhưng cái giá đổi lại là bạn không được để logrotate bên ngoài đụng vào file đó nữa — nếu bạn vừa bật RollingFileAppender của Logback vừa để logrotate với copytruncate chạy song song, hai bên giẫm chân nhau và bạn nhận đúng kiểu mất dòng câm lặng như trên.

Trong Go, thư viện lumberjack phổ biến cũng chọn xoay-vòng-trong-tiến-trình vì đúng lý do đó: tự đổi tên rồi tự mở lại file ngay lập tức, không cần ai gửi SIGHUP từ ngoài. Đây là cùng một bài học "ai cầm file handle thì người đó phải lo mở lại" được đóng gói thành thư viện.

Còn ở cơ sở dữ liệu, họ hàng gần nhất là chuyện xoay WAL/redo log và "log rotation" của chính engine. PostgreSQL, MySQL đều tự quản vòng đời tệp WAL bên trong, và tài liệu của chúng cảnh báo rất rõ: đừng bao giờ để một công cụ ngoài xoá hay cắt cụt tệp log mà engine đang mở — làm thế là hỏng dữ liệu, đúng cái copytruncate gây ra ở tầng ứng dụng.

Mẫu số chung: trên Unix, cái mở tệp là inode chứ không phải cái tên bạn nhìn thấy; ai giữ file handle thì người đó là nguồn chân lý về việc ghi tiếp vào đâu. Mọi cách xoay vòng an toàn đều quy về một nguyên tắc: hoặc chính tiến trình đang ghi tự xoay, hoặc phải có một tín hiệu tường minh bảo nó mở lại. Bỏ qua điều đó thì dữ liệu không kêu lên khi mất — nó chỉ lặng lẽ đi mất.

Nếu muốn tự thấy tận mắt trong nửa phút, chạy đúng thí nghiệm này:

docker run --rm debian:12-slim bash -c '
apt-get -qq update >/dev/null && apt-get -qq install -y logrotate python3 >/dev/null
cat > /etc/logrotate.d/app <<CFG
/var/log/app.log { size 1k rotate 50 copytruncate missingok notifempty }
CFG
: > /var/log/app.log
python3 -c "
f=open(\"/var/log/app.log\",\"a\",buffering=1)
for i in range(1,200001): f.write(\"%08d\n\"%i)
" &
W=$!
while kill -0 $W 2>/dev/null; do logrotate -f /etc/logrotate.conf >/dev/null 2>&1; sleep 0.15; done
wait $W
CO=$(cat /var/log/app.log* | sort -u | wc -l)
echo "da ghi 200000 dong, con lai $CO  ->  mat $((200000-CO))"
'

logrotate sẽ báo thành công ở mọi lần chạy. Con số ở dòng cuối là thứ duy nhất nói cho bạn biết chuyện gì thật sự đã xảy ra — và đó chính là điều đáng sợ nhất.