Command Box bài học 9: Xây dựng cơ chế Logging nội bộ cho Command Box: Debug dễ dàng hơn

Ở Bài học 5, chúng ta đã làm đẹp cho Command Box bằng các vòng xoay Spinner, bảng biểu bắt mắt và thông báo lỗi ngắn gọn. Nhưng điều đó lại vô tình tạo ra một bài toán hóc búa khi vận hành thực tế: Khi công cụ chạy sai trên máy của một đồng nghiệp, làm sao bạn biết chuyện gì đã thực sự xảy ra bên dưới?

Hãy tưởng tượng một kỹ sư trong team nhắn cho bạn: "Ơi, anh chạy lệnh cbox order sync -i 999 mà nó chỉ báo ✖ Lỗi: Đồng bộ thất bại (500 Internal Server Error) rồi tắt luôn, không biết lỗi ở bước gọi MySQL hay lúc bắn sang Elasticsearch nữa!". Nếu lúc đó bạn bảo họ cài Go về, mở code ra thêm lệnh fmt.Println vào để kiểm tra thì toàn bộ giá trị của một công cụ đóng gói độc lập sẽ sụp đổ.

Bài học thứ 9 này sẽ hướng dẫn bạn thiết kế Hệ thống Logging nội bộ đa tầng (Internal Diagnostic Logging) — giúp Command Box bình thường thì im lặng, gọn gàng tuyệt đối, nhưng khi cần chẩn đoán bệnh (qua cờ -v hoặc file log ngầm) thì có thể "chụp X-quang" từng câu lệnh SQL, từng gói tin HTTP và từng mili-giây thực thi.

(Hình minh họa: Sử dụng package chuẩn log/slog từ Go 1.21+ giúp phân tách rõ các cấp độ log kèm thời gian thực thi chính xác tới từng mili-giây).

1. Phân biệt rạch ròi: "UI Output" và "Internal Log"

Sai lầm phổ biến nhất của lập trình viên Backend khi chuyển sang viết CLI là đánh đồng việc in thông báo cho người dùng đọc với việc ghi log kỹ thuật. Trong kiến trúc Command Box chuẩn (như đã chia ở Bài học 4), đây là hai thế giới hoàn toàn tách biệt:

2. Thiết kế 4 Cấp độ Verbosity (-v, -vv, -vvv) chuẩn công nghiệp

Bạn có để ý khi dùng curl -v, ssh -vvv hay ansible-playbook -vv, càng thêm nhiều chữ v thì thông tin nội bộ bung ra càng sâu không? Thay vì chỉ có một chiếc công tắc bật/tắt đơn điệu, hãy thiết kế cho Command Box của bạn thang đo độ chi tiết (Verbosity Ladder) thông qua CountVarP của Cobra:

• Mặc định (Không truyền cờ): Logger ở mức WARN/ERROR. Màn hình chỉ hiển thị giao diện UI sạch sẽ.

• Mức 1 (-v — Info Mode): Hiển thị luồng đi chính của tiến trình (Đang đọc file config nào, đang kết nối tới host nào, bước nào đã xong).

• Mức 2 (-vv — Debug Mode): Hiển thị chi tiết tham số nội bộ (Câu lệnh SQL vừa chạy, thời gian phản hồi của từng hàm, trạng thái biến môi trường).

• Mức 3 (-vvv — Trace / Network Dump Mode): Mức độ "giải phẫu" sâu nhất. In toàn bộ HTTP Request/Response Headers, Payload JSON gửi đi, hoặc câu lệnh exec thô gọi xuống hệ điều hành.

3. Hộp đen máy bay (Flight Recorder): Ghi log ngầm ra File xoay vòng

Có những lỗi chỉ xảy ra đúng 1 lần rồi biến mất (ví dụ: timeout mạng chập chờn hoặc deadlock tức thời). Khi lỗi vừa xảy ra xong, người dùng mới gõ lại lệnh kèm cờ -vv thì lỗi lại không tái hiện nữa!

Để giải quyết triệt để tình huống này, các CLI chuyên nghiệp đều áp dụng kỹ thuật "Hộp đen máy bay" (Always-on Background File Logging):

1. Bất kể người dùng có truyền cờ -v hay không, Command Box luôn âm thầm ghi log mức DEBUG vào một file cố định trong máy người dùng (ví dụ: ~/.local/state/cbox/cbox.log hoặc ~/.cbox/logs/debug.log).

2. Khi một lệnh bất ngờ bị crash, ở dòng thông báo lỗi cuối cùng trên màn hình, bạn chỉ cần in ra: 💡 Chi tiết kỹ thuật của lỗi vừa rồi đã được lưu tại: ~/.cbox/logs/debug.log (Gõ 'cbox log view' để xem ngay).

3. Cơ chế tự dọn rác (Log Rotation): Để tránh file log ngầm phình to hàng chục GB chiếm ổ cứng của anh em trong team, bắt buộc phải kết hợp với thư viện xoay vòng log (như natefinch/lumberjack) để giới hạn dung lượng (ví dụ: tối đa 10MB, chỉ giữ lại 3 file gần nhất).

4. Chốt chặn Bảo mật: Tự động che giấu thông tin nhạy cảm (Secret Masking)

Khi bật chế độ -vv hoặc ghi log ra file để gửi cho đồng nghiệp nhờ kiểm tra hộ, nguy cơ lớn nhất là lộ mật khẩu Database, JWT Token, hoặc API Key ngay trong dòng log.

Với gói thư viện chuẩn log/slog (có sẵn từ Go 1.21+), bạn có thể cài đặt một bộ lọc ReplaceAttr hoặc triển khai interface slog.LogValuer để tự động biến mọi trường nhạy cảm thành ***REDACTED*** ngay tại tầng lõi trước khi dòng log kịp chạm tới màn hình hay ổ cứng.

5. Thực hành viết code: Xây dựng bộ Logger Đa luồng (Console + File) kèm Masking với log/slog

Dưới đây là mã nguồn hoàn chỉnh cho package internal/logger/ của Command Box, kết hợp đồng thời cả 3 kỹ thuật: Ghi song song (Multi-Sink), Phân cấp -v, và Tự động che mật khẩu:

Go

package logger

import (
	"context"
	"io"
	"log/slog"
	"os"
	"path/filepath"
	"strings"
)

// Các từ khóa nhạy cảm cần tự động che giấu khi in log
var sensitiveKeys = []string{"password", "token", "secret", "api_key", "authorization"}

// InitLogger khởi tạo hệ thống log kép:
// 1. Luồng stderr: Chỉ in theo mức verbosity (-v, -vv) do người dùng chọn.
// 2. Luồng file ngầm: Luôn ghi mức DEBUG vào ~/.cbox/debug.log (Hộp đen).
func InitLogger(verbosity int) (*os.File, error) {
	// 1. Xác định mức log hiển thị ra màn hình (stderr) dựa trên số lượng chữ 'v'
	var consoleLevel slog.Level
	switch {
	case verbosity >= 2:
		consoleLevel = slog.LevelDebug // -vv: Hiện tất cả Debug
	case verbosity == 1:
		consoleLevel = slog.LevelInfo  // -v: Hiện Info
	default:
		consoleLevel = slog.LevelError // Mặc định: Im lặng, chỉ hiện khi có Error nghiêm trọng
	}

	// 2. Mở file "Hộp đen" tại thư mục Home của người dùng
	homeDir, _ := os.UserHomeDir()
	logDir := filepath.Join(homeDir, ".cbox", "logs")
	_ = os.MkdirAll(logDir, 0755)
	logFile, err := os.OpenFile(filepath.Join(logDir, "debug.log"), os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0600)
	if err != nil {
		return nil, err
	}

	// 3. Bộ lọc tự động che mật khẩu/token (Secret Redaction)
	maskingReplace := func(groups []string, a slog.Attr) slog.Attr {
		keyLower := strings.ToLower(a.Key)
		for _, secret := range sensitiveKeys {
			if strings.Contains(keyLower, secret) {
				return slog.String(a.Key, "***[REDACTED]***")
			}
		}
		return a
	}

	// 4. Tạo 2 Handler độc lập: Text cho màn hình và JSON cho file hộp đen
	consoleHandler := slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{
		Level:       consoleLevel,
		ReplaceAttr: maskingReplace,
	})

	fileHandler := slog.NewJSONHandler(logFile, &slog.HandlerOptions{
		Level:       slog.LevelDebug, // File hộp đen luôn lưu mức chi tiết nhất
		AddSource:   true,            // Ghi kèm tên file .go và số dòng gây lỗi
		ReplaceAttr: maskingReplace,
	})

	// 5. Gộp 2 Handler lại và đặt làm Logger mặc định toàn cục
	multiHandler := &fanoutHandler{handlers: []slog.Handler{consoleHandler, fileHandler}}
	slog.SetDefault(slog.New(multiHandler))

	return logFile, nil
}

// fanoutHandler giúp bắn 1 dòng log vào cả màn hình lẫn file cùng lúc
type fanoutHandler struct {
	handlers []slog.Handler
}

func (f *fanoutHandler) Enabled(ctx context.Context, l slog.Level) bool {
	for _, h := range f.handlers {
		if h.Enabled(ctx, l) {
			return true
		}
	}
	return false
}

func (f *fanoutHandler) Handle(ctx context.Context, r slog.Record) error {
	for _, h := range f.handlers {
		if h.Enabled(ctx, r.Level) {
			_ = h.Handle(ctx, r.Clone())
		}
	}
	return nil
}

func (f *fanoutHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	var next []slog.Handler
	for _, h := range f.handlers {
		next = append(next, h.WithAttrs(attrs))
	}
	return &fanoutHandler{handlers: next}
}

func (f *fanoutHandler) WithGroup(name string) slog.Handler {
	var next []slog.Handler
	for _, h := range f.handlers {
		next = append(next, h.WithGroup(name))
	}
	return &fanoutHandler{handlers: next}
}

Cách gắn cờ -v vào Root Command và sử dụng trong nghiệp vụ:

Go

// Trong internal/cli/root.go:
var verbosity int
// Dùng CountVarP để đếm số chữ 'v': -v (1), -vv (2), -vvv (3)
rootCmd.PersistentFlags().CountVarP(&verbosity, "verbose", "v", "Tăng mức độ chi tiết log (-v: Info, -vv: Debug)")

// Trong bất kỳ hàm nào ở tầng internal/core/database/db.go:
slog.Debug("Khởi tạo kết nối MySQL",
    slog.String("host", "10.0.1.55:3306"),
    slog.String("db_password", "SuperSecret123!"), // Sẽ tự động biến thành ***[REDACTED]***!
    slog.Int("max_conns", 10),
)

6. Mẹo thực chiến: Tạo lệnh cbox doctor và cbox log tail

Khi đã có file hộp đen ~/.cbox/logs/debug.log, đừng bắt đồng nghiệp phải tự nhớ đường dẫn đó để mở bằng vim hay cat. Hãy đóng gói luôn 2 lệnh tiện ích đi kèm vào trong Command Box của bạn:

1. cbox log last-error: Tự động đọc ngược từ cuối file debug.log lên, lọc đúng những dòng có "level":"ERROR" của phiên chạy gần nhất và in đẹp đẽ ra màn hình để họ chỉ việc copy gửi vào nhóm chat kỹ thuật.

2. cbox doctor: Một lệnh tự chẩn đoán sức khỏe môi trường máy local (kiểm tra xem Docker đã bật chưa, VPN công ty đã thông tới IP Database chưa, file cấu hình có thiếu biến nào không) và xuất ra bảng checklist xanh/đỏ rõ ràng.

💡 Bài tập thực hành cuối bài (Dành cho độc giả):

Hãy tích hợp đoạn code CountVarP cho cờ -v vào Root Command của bạn và thử chạy 3 câu lệnh liên tiếp:

• cbox order sync -i 100 (Màn hình hoàn toàn sạch sẽ)

• cbox order sync -i 100 -v (Hiện các bước lớn)

• cbox order sync -i 100 -vv (Hiện chi tiết từng câu query và thấy mật khẩu đã tự động bị che thành ***[REDACTED]***) Sau đó mở file ~/.cbox/logs/debug.log lên xem — bạn sẽ thấy ngay cả ở lần chạy đầu tiên không có cờ -v, toàn bộ thông tin chi tiết vẫn đã được ghi nhận đầy đủ trong hộp đen!