Ghi log là một phần không thể thiếu trong bất kỳ ứng dụng sản phẩm nào. Nó cho phép chúng ta theo dõi hoạt động của ứng dụng, phát hiện lỗi, và hiểu được hành vi của hệ thống trong môi trường sản xuất. Trong bài viết này, chúng ta sẽ tìm hiểu về structured logging trong Go - một phương pháp ghi log hiệu quả và mạnh mẽ.

Tại sao cần Structured Logging?

Trước khi đi vào chi tiết, hãy hiểu tại sao chúng ta cần structured logging:

  1. Dễ dàng tìm kiếm và lọc: Log có cấu trúc dưới dạng JSON cho phép tìm kiếm nhanh chóng theo nhiều tiêu chí
  2. Phân tích tự động: Có thể xử lý và phân tích bởi các công cụ tự động
  3. Theo dõi request: Có thể theo dõi toàn bộ vòng đời của một request qua các service
  4. Context phong phú: Chứa nhiều thông tin hơn về ngữ cảnh của sự kiện

Thiết kế Logger Interface

Chúng ta sẽ bắt đầu với việc thiết kế một interface đơn giản nhưng linh hoạt:

// Logger định nghĩa interface chung cho các logger
type Logger interface {
    Debug(msg string, fields map[string]interface{})
    Info(msg string, fields map[string]interface{})
    Warn(msg string, fields map[string]interface{})
    Error(msg string, fields map[string]interface{})
    WithField(key string, value interface{}) Logger
    WithFields(fields map[string]interface{}) Logger
    WithTraceID(traceID string) Logger
    GetTraceID() string
}

Interface này cung cấp:

  • Các phương thức ghi log theo cấp độ (Debug, Info, Warn, Error)
  • Khả năng thêm thông tin bổ sung vào logger (WithField, WithFields)
  • Hỗ trợ trace ID để theo dõi request (WithTraceID, GetTraceID)

Cấu trúc của Logger

Bây giờ, chúng ta sẽ triển khai interface của mình sử dụng thư viện logrus - một thư viện logging phổ biến trong Go:

import (
    "github.com/sirupsen/logrus"
    "github.com/google/uuid"
)

// Các cấp độ log
type LogLevel string

const (
    DEBUG LogLevel = "debug"
    INFO  LogLevel = "info"
    WARN  LogLevel = "warn"
    ERROR LogLevel = "error"
)

// TraceIDKey là key để lưu trace ID trong log
const TraceIDKey = "trace_id"

// Config chứa các thiết lập cho logger
type Config struct {
    LogLevel      string
    LogDirectory  string
    EnableConsole bool
}

// loggerImpl là triển khai của Logger interface
type loggerImpl struct {
    logger      *logrus.Logger
    traceID     string
    extraFields map[string]interface{}
    fileMutex   sync.Mutex
}

Cấu trúc này bao gồm:

  • Underlying logger (logrus)
  • Trace ID để theo dõi request
  • Extra fields để lưu trữ thông tin bổ sung
  • Mutex để xử lý đồng thời khi ghi file

Khởi tạo Logger

// NewLogger tạo một instance logger mới
func NewLogger(config *Config) Logger {
    logger := logrus.New()

    // Thiết lập cấp độ log
    level, err := logrus.ParseLevel(config.LogLevel)
    if err != nil {
        level = logrus.InfoLevel // Mặc định Info nếu cấp độ không hợp lệ
    }
    logger.SetLevel(level)

    // Đảm bảo thư mục log tồn tại
    if err := os.MkdirAll(config.LogDirectory, 0755); err != nil {
        fmt.Fprintf(os.Stderr, "Failed to create log directory: %v\n", err)
    }

    // Cấu hình JSON formatter cho structured logging
    logger.SetFormatter(&logrus.JSONFormatter{
        TimestampFormat: time.RFC3339,
    })
    
    // Thiết lập output
    if config.EnableConsole {
        logger.SetOutput(os.Stdout)
    } else {
        logger.SetOutput(io.Discard) // Discard mặc định vì chúng ta sẽ ghi vào file riêng
    }

    return &loggerImpl{
        logger:      logger,
        traceID:     GenerateTraceID(),
        extraFields: make(map[string]interface{}),
    }
}

// GenerateTraceID tạo trace ID mới
func GenerateTraceID() string {
    return uuid.New().String()
}

Khởi tạo logger bao gồm:

  • Thiết lập cấp độ log
  • Tạo thư mục log nếu chưa tồn tại
  • Cấu hình JSON formatter cho structured logging
  • Thiết lập output (console hoặc file)
  • Tạo trace ID mặc định

Các phương thức bổ trợ

Chúng ta sẽ triển khai các phương thức hỗ trợ để thêm thông tin vào logger:

// WithTraceID tạo một logger mới với trace ID được chỉ định
func (l *loggerImpl) WithTraceID(traceID string) Logger {
    newLogger := &loggerImpl{
        logger:      l.logger,
        traceID:     traceID,
        extraFields: make(map[string]interface{}),
    }
    
    // Copy existing extra fields
    for k, v := range l.extraFields {
        newLogger.extraFields[k] = v
    }
    
    return newLogger
}

// WithField thêm một field vào logger
func (l *loggerImpl) WithField(key string, value interface{}) Logger {
    newLogger := &loggerImpl{
        logger:      l.logger,
        traceID:     l.traceID,
        extraFields: make(map[string]interface{}),
    }
    
    // Copy existing extra fields
    for k, v := range l.extraFields {
        newLogger.extraFields[k] = v
    }
    
    // Add new field
    newLogger.extraFields[key] = value
    
    return newLogger
}

// WithFields thêm nhiều fields vào logger
func (l *loggerImpl) WithFields(fields map[string]interface{}) Logger {
    newLogger := &loggerImpl{
        logger:      l.logger,
        traceID:     l.traceID,
        extraFields: make(map[string]interface{}),
    }
    
    // Copy existing extra fields
    for k, v := range l.extraFields {
        newLogger.extraFields[k] = v
    }
    
    // Add new fields
    for k, v := range fields {
        newLogger.extraFields[k] = v
    }
    
    return newLogger
}

// GetTraceID trả về trace ID hiện tại
func (l *loggerImpl) GetTraceID() string {
    return l.traceID
}

Điểm quan trọng cần lưu ý:

  • Mỗi phương thức trả về một logger mới, không thay đổi logger gốc (immutable)
  • Các fields hiện tại được sao chép sang logger mới
  • Fields mới được thêm vào logger mới

Chuẩn bị Log Entry

Trước khi ghi log, chúng ta cần chuẩn bị log entry với các fields chuẩn:

// makeFields thêm các fields chung vào log entry
func (l *loggerImpl) makeFields(fields map[string]interface{}) logrus.Fields {
    if fields == nil {
        fields = make(map[string]interface{})
    }
    
    // Thêm trace ID và timestamp
    fields[TraceIDKey] = l.traceID
    fields["timestamp"] = time.Now().UTC().Format(time.RFC3339)
    
    // Thêm các extra fields
    for k, v := range l.extraFields {
        fields[k] = v
    }
    
    return logrus.Fields(fields)
}

Hàm này:

  • Đảm bảo có một map fields (tạo mới nếu null)
  • Thêm trace ID và timestamp
  • Thêm các fields từ logger context

Ghi Log vào File

Bây giờ, chúng ta sẽ triển khai ghi log vào file theo cấp độ:

// getLogFile trả về file log thích hợp cho cấp độ
func (l *loggerImpl) getLogFile(level logrus.Level) *os.File {
    // Lock cho các hoạt động file
    l.fileMutex.Lock()
    defer l.fileMutex.Unlock()
    
    var logPath string
    logDir := l.logger.Out.(*os.File).Name()
    if logDir == os.Stdout.Name() || logDir == os.Stderr.Name() {
        logDir = "./logs" // Mặc định nếu output là stdout/stderr
    } else {
        logDir = filepath.Dir(logDir)
    }
    
    // Xác định tên file dựa trên cấp độ
    switch level {
    case logrus.DebugLevel:
        logPath = filepath.Join(logDir, "debug.log")
    case logrus.InfoLevel:
        logPath = filepath.Join(logDir, "info.log")
    case logrus.WarnLevel:
        logPath = filepath.Join(logDir, "warning.log")
    case logrus.ErrorLevel:
        logPath = filepath.Join(logDir, "error.log")
    default:
        logPath = filepath.Join(logDir, "app.log")
    }
    
    // Mở file log
    file, err := os.OpenFile(logPath, os.O_CREATE|os.O_WRONLY|os.O_APPEND, 0666)
    if err != nil {
        fmt.Fprintf(os.Stderr, "Failed to open log file %s: %v\n", logPath, err)
        return os.Stderr // Fallback to stderr nếu không mở được file
    }
    
    return file
}

// logToFile ghi log vào file theo cấp độ
func (l *loggerImpl) logToFile(level logrus.Level, entry *logrus.Entry) {
    if !l.logger.IsLevelEnabled(level) {
        return
    }
    
    // Lấy file phù hợp
    file := l.getLogFile(level)
    defer file.Close()
    
    // Tạo logger mới cho file cụ thể
    fileLogger := logrus.New()
    fileLogger.SetOutput(file)
    fileLogger.SetFormatter(&logrus.JSONFormatter{
        TimestampFormat: time.RFC3339,
    })
    fileLogger.SetLevel(level)
    
    // Ghi log theo cấp độ
    switch level {
    case logrus.DebugLevel:
        fileLogger.WithFields(entry.Data).Debug(entry.Message)
    case logrus.InfoLevel:
        fileLogger.WithFields(entry.Data).Info(entry.Message)
    case logrus.WarnLevel:
        fileLogger.WithFields(entry.Data).Warn(entry.Message)
    case logrus.ErrorLevel:
        fileLogger.WithFields(entry.Data).Error(entry.Message)
    }
}

Những điểm quan trọng:

  • Mỗi cấp độ log có file riêng
  • Sử dụng mutex để tránh xung đột khi ghi file
  • Fallback sang stderr nếu không thể mở file
  • Tạo logger mới cho mỗi lần ghi để tránh vấn đề với output

Triển khai các phương thức log

Cuối cùng, chúng ta triển khai các phương thức ghi log:

// Debug ghi log ở cấp độ DEBUG
func (l *loggerImpl) Debug(msg string, fields map[string]interface{}) {
    if l.logger.IsLevelEnabled(logrus.DebugLevel) {
        entry := &logrus.Entry{
            Logger:  l.logger,
            Data:    l.makeFields(fields),
            Time:    time.Now(),
            Level:   logrus.DebugLevel,
            Message: msg,
        }
        
        // Ghi ra console nếu được bật
        l.logger.WithFields(entry.Data).Debug(msg)
        
        // Ghi vào file
        l.logToFile(logrus.DebugLevel, entry)
    }
}

// Info ghi log ở cấp độ INFO
func (l *loggerImpl) Info(msg string, fields map[string]interface{}) {
    if l.logger.IsLevelEnabled(logrus.InfoLevel) {
        entry := &logrus.Entry{
            Logger:  l.logger,
            Data:    l.makeFields(fields),
            Time:    time.Now(),
            Level:   logrus.InfoLevel,
            Message: msg,
        }
        
        // Ghi ra console nếu được bật
        l.logger.WithFields(entry.Data).Info(msg)
        
        // Ghi vào file
        l.logToFile(logrus.InfoLevel, entry)
    }
}

// Warn ghi log ở cấp độ WARN
func (l *loggerImpl) Warn(msg string, fields map[string]interface{}) {
    if l.logger.IsLevelEnabled(logrus.WarnLevel) {
        entry := &logrus.Entry{
            Logger:  l.logger,
            Data:    l.makeFields(fields),
            Time:    time.Now(),
            Level:   logrus.WarnLevel,
            Message: msg,
        }
        
        // Ghi ra console nếu được bật
        l.logger.WithFields(entry.Data).Warn(msg)
        
        // Ghi vào file
        l.logToFile(logrus.WarnLevel, entry)
    }
}

// Error ghi log ở cấp độ ERROR
func (l *loggerImpl) Error(msg string, fields map[string]interface{}) {
    if l.logger.IsLevelEnabled(logrus.ErrorLevel) {
        entry := &logrus.Entry{
            Logger:  l.logger,
            Data:    l.makeFields(fields),
            Time:    time.Now(),
            Level:   logrus.ErrorLevel,
            Message: msg,
        }
        
        // Ghi ra console nếu được bật
        l.logger.WithFields(entry.Data).Error(msg)
        
        // Ghi vào file
        l.logToFile(logrus.ErrorLevel, entry)
    }
}

Mỗi phương thức:

  • Kiểm tra xem cấp độ log có được bật không
  • Tạo entry với fields và timestamp
  • Ghi ra console nếu được bật
  • Ghi vào file tương ứng với cấp độ

Tích hợp với HTTP Middleware

Một trong những ứng dụng chính của structured logging là trong HTTP middleware để tự động ghi log cho mỗi request:

// RequestLoggerMiddleware tạo middleware cho Gin để ghi log HTTP requests
func RequestLoggerMiddleware(logger Logger) gin.HandlerFunc {
    return func(c *gin.Context) {
        // Bắt đầu timer
        start := time.Now()

        // Lấy hoặc tạo trace ID
        traceID := c.GetHeader("X-Trace-ID")
        if traceID == "" {
            traceID = GenerateTraceID()
        }

        // Tạo logger với trace ID
        requestLogger := logger.WithTraceID(traceID)

        // Lưu logger vào context
        c.Set("logger", requestLogger)

        // Thêm trace ID vào response header
        c.Header("X-Trace-ID", traceID)

        // Ghi log request
        requestLogger.Info("Request started", map[string]interface{}{
            "method":     c.Request.Method,
            "path":       c.Request.URL.Path,
            "query":      c.Request.URL.RawQuery,
            "client_ip":  c.ClientIP(),
            "user_agent": c.Request.UserAgent(),
        })

        // Xử lý request
        c.Next()

        // Ghi log response
        statusCode := c.Writer.Status()
        elapsed := time.Since(start)

        logFields := map[string]interface{}{
            "status_code": statusCode,
            "duration_ms": elapsed.Milliseconds(),
        }

        if len(c.Errors) > 0 {
            logFields["errors"] = c.Errors.Errors()
        }

        if statusCode >= 500 {
            requestLogger.Error("Request failed", logFields)
        } else if statusCode >= 400 {
            requestLogger.Warn("Request error", logFields)
        } else {
            requestLogger.Info("Request completed", logFields)
        }
    }
}

Middleware này:

  • Bắt đầu timer cho request
  • Lấy hoặc tạo trace ID
  • Tạo logger riêng cho mỗi request
  • Ghi log khi request bắt đầu
  • Ghi log khi request kết thúc, với thông tin về status code và thời gian xử lý

Cách sử dụng Logger

Sau khi đã thiết lập logger, đây là cách sử dụng nó trong ứng dụng:

func main() {
    // Khởi tạo logger
    logger := NewLogger(&Config{
        LogLevel:      "info",
        LogDirectory:  "./logs",
        EnableConsole: true,
    })

    // Sử dụng logger trực tiếp
    logger.Info("Application starting", map[string]interface{}{
        "version": "1.0.0",
        "env":     "production",
    })

    // Tạo logger với context
    userLogger := logger.WithField("user_id", "12345")
    userLogger.Info("User logged in", map[string]interface{}{
        "username": "john.doe",
        "role":     "admin",
    })

    // Ghi log lỗi
    if err := someFunction(); err != nil {
        logger.Error("Operation failed", map[string]interface{}{
            "operation": "someFunction",
            "error":     err.Error(),
        })
    }

    // Trong handler HTTP
    http.HandleFunc("/api/users", func(w http.ResponseWriter, r *http.Request) {
        // Retrieve logger from context (if using middleware)
        ctx := r.Context()
        reqLogger, ok := ctx.Value("logger").(Logger)
        if !ok {
            reqLogger = logger
        }

        reqLogger.Info("Processing users request", nil)
        // ... xử lý request
    })
}

Ví dụ về Log JSON

Đây là một số ví dụ về log JSON được tạo ra bởi logger của chúng ta:

Log INFO

{
  "level": "info",
  "msg": "Application starting",
  "version": "1.0.0",
  "env": "production",
  "trace_id": "7b8f3da4-6149-4d4a-b3a2-65f0c568a563",
  "timestamp": "2023-06-14T10:32:45Z"
}

Log Request

{
  "level": "info",
  "msg": "Request started",
  "path": "/api/users",
  "method": "GET",
  "client_ip": "127.0.0.1",
  "trace_id": "3a9f1d83-5b41-4918-a432-f61b3a4bd69c",
  "timestamp": "2023-06-14T10:32:45Z",
  "user_agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36..."
}

Log ERROR

{
  "level": "error",
  "msg": "Operation failed",
  "operation": "someFunction",
  "error": "connection refused",
  "trace_id": "3a9f1d83-5b41-4918-a432-f61b3a4bd69c",
  "timestamp": "2023-06-14T10:32:47Z"
}

Tìm kiếm và phân tích Log

Với log có cấu trúc, chúng ta có thể dễ dàng tìm kiếm và phân tích bằng các công cụ như jq. Đây là một số ví dụ:

Tìm tất cả log lỗi

cat logs/error.log | jq '.'

Tìm log theo trace_id

cat logs/*.log | jq 'select(.trace_id == "3a9f1d83-5b41-4918-a432-f61b3a4bd69c")'

Thống kê lỗi theo loại

cat logs/error.log | jq -r '.operation' | sort | uniq -c | sort -nr

Phân tích thời gian phản hồi trung bình

cat logs/info.log | jq 'select(.duration_ms != null) | .duration_ms' | awk '{ sum += $1; n++ } END { if (n > 0) print sum / n; }'

Thực tiễn tốt nhất

1. Sử dụng cấp độ log phù hợp

  • DEBUG: Thông tin chi tiết cho phát triển
  • INFO: Thông tin về hoạt động bình thường
  • WARN: Cảnh báo về vấn đề tiềm ẩn
  • ERROR: Lỗi ảnh hưởng đến chức năng

2. Cung cấp context đầy đủ

// Không tốt
logger.Error("Database connection failed")

// Tốt hơn
logger.Error("Database connection failed", map[string]interface{}{
    "database": "users",
    "host": dbHost,
    "port": dbPort,
    "retry_count": retryCount,
    "error": err.Error(),
})

3. Dùng trace ID để theo dõi request

// Ở service đầu tiên
traceID := GenerateTraceID()
requestLogger := logger.WithTraceID(traceID)

// Truyền trace ID đến service tiếp theo
nextServiceRequest.Header.Set("X-Trace-ID", traceID)

4. Không log thông tin nhạy cảm

// KHÔNG NÊN
logger.Info("User authenticated", map[string]interface{}{
    "email": user.Email,
    "password": password, // ĐỪNG làm điều này!
})

// NÊN LÀM
logger.Info("User authenticated", map[string]interface{}{
    "user_id": user.ID,
    "email": user.Email,
})

5. Sử dụng log sampling cho traffic cao

Đối với endpoints có traffic cao, bạn có thể cân nhắc chỉ log một phần nhỏ các requests:

func shouldSampleLog() bool {
    return rand.Float64() < 0.01 // Log 1% requests
}

if shouldSampleLog() {
    logger.Info("High traffic endpoint accessed", map[string]interface{}{
        "path": "/api/status",
    })
}

Kết luận

Structured logging là một công cụ mạnh mẽ trong bộ công cụ của nhà phát triển Go. Bằng cách sử dụng các kỹ thuật được mô tả trong bài viết này, bạn có thể xây dựng một hệ thống logging mạnh mẽ, giúp dễ dàng theo dõi, gỡ lỗi và phân tích ứng dụng của mình trong môi trường sản xuất.

Nhớ rằng, một hệ thống logging tốt không chỉ giúp bạn phát hiện và giải quyết vấn đề nhanh hơn, mà còn cung cấp insights quý giá về hành vi và hiệu suất của ứng dụng. Hãy đầu tư thời gian vào việc thiết kế hệ thống logging của bạn, và nó sẽ đền đáp bạn nhiều lần khi ứng dụng phát triển.