Logging middleware

Oldingi darsda so‘rov metodi, yo‘li va davomiyligini log qiladigan oddiy middleware yozdik. Lekin real loyihada bu yetarli emas. Kechasi foydalanuvchilar "sayt ishlamayapti" deb yozishdi. Loglarga qaraysiz: qaysi so‘rovlar xato bilan tugagan? Qaysi biri sekin ishlagan? Bitta foydalanuvchining so‘rovi tizim bo‘ylab qanday yo‘l bosib o‘tgan?

Bu savollarga javob berish uchun har bir so‘rov haqida quyidagilar yozilishi kerak:

metod va yo‘l;
javob status kodi;
javob hajmi;
davomiylik;
klient manzili;
har bir so‘rovni ajratib turadigan request ID.

Bu darsda shunday middleware’ni bosqichma-bosqich yozamiz.

Muammo: status kodni qanday bilamiz?

Handler status kodni w.WriteHeader(404) bilan yozadi. Lekin http.ResponseWriter interfeysida yozilgan kodni qaytarib o‘qiydigan metod yo‘q. Middleware next.ServeHTTP(w, r) chaqirgandan keyin handler qanday javob berganini bilolmaydi.

Yechim — ResponseWriterni o‘z turimiz bilan o‘rash. Bu tur haqiqiy ResponseWriterga yozishni davom ettiradi, lekin yo‘l-yo‘lakay status kod va yozilgan baytlar sonini eslab qoladi.

`responseRecorder` turi

type responseRecorder struct {
    http.ResponseWriter
    status int
    bytes  int
}

func (rec *responseRecorder) WriteHeader(code int) {
    rec.status = code
    rec.ResponseWriter.WriteHeader(code)
}

func (rec *responseRecorder) Write(b []byte) (int, error) {
    if rec.status == 0 {
        rec.status = http.StatusOK
    }
    n, err := rec.ResponseWriter.Write(b)
    rec.bytes += n
    return n, err
}

Kod qanday ishlaydi:

http.ResponseWriter struct ichiga nomsiz (embedded) joylashtirilgan. Shu sababli responseRecorder interfeysning barcha metodlariga, jumladan Header()ga ham avtomatik ega bo‘ladi.
WriteHeader qayta yozilgan: kodni saqlaydi va asl WriteHeaderni chaqiradi.
Write ham qayta yozilgan. Handler WriteHeaderni chaqirmasdan to‘g‘ridan-to‘g‘ri Write qilsa, Go avtomatik 200 yuboradi. Recorder ham shu holatni hisobga oladi.

`Unwrap` metodi

O‘ralgan ResponseWriter bitta muammo tug‘diradi. Asl writer’da Flush kabi qo‘shimcha imkoniyatlar bo‘lishi mumkin. Ular Server-Sent Events yoki streaming uchun kerak. O‘ralgandan keyin bu imkoniyatlar ko‘rinmay qoladi.

Go 1.20 dan beri bu muammoni http.ResponseController hal qiladi. U o‘ralgan writer ichidan asl writer’ni Unwrap metodi orqali topadi. Shuning uchun recorder’ga bitta kichik metod qo‘shamiz:

func (rec *responseRecorder) Unwrap() http.ResponseWriter {
    return rec.ResponseWriter
}

Endi handler ichida http.NewResponseController(w).Flush() middleware orqali ham ishlaydi.

Request ID

Bir vaqtda yuzlab so‘rov kelsa, ularning loglari aralashib ketadi. Har bir so‘rovga noyob ID berilsa, bitta so‘rovga tegishli barcha yozuvlarni shu ID bo‘yicha topish mumkin.

func newRequestID() string {
    b := make([]byte, 8)
    rand.Read(b)
    return hex.EncodeToString(b)
}

crypto/rand 8 ta tasodifiy bayt yaratadi. hex.EncodeToString ularni 3f9a1c0b7e2d4a61 kabi 16 belgili satrga aylantiradi.

Request ID bilan bog‘liq odatiy qoidalar:

klient yoki oldingi proxy X-Request-ID sarlavhasini yuborgan bo‘lsa, o‘sha qiymat ishlatiladi. Shunda bir so‘rovni bir nechta servis orqali kuzatish mumkin;
ID javob sarlavhasida ham qaytariladi. Foydalanuvchi xato haqida xabar berganda shu ID’ni aytsa, uning so‘rovini loglardan darhol topasiz;
ID so‘rov contextiga joylanadi, shunda handler ichidagi loglar ham shu ID bilan yoziladi.

Warning

Tashqaridan kelgan X-Request-ID qiymatiga to‘liq ishonmang. Uzunligini cheklang va faqat xavfsiz belgilardan iboratligini tekshiring. Aks holda kimdir juda uzun satr yoki maxsus belgilar yuborib, loglarni buzishi mumkin.

Contextga ID joylash

type ctxKey struct{}

func withRequestID(ctx context.Context, id string) context.Context {
    return context.WithValue(ctx, ctxKey{}, id)
}

func RequestID(ctx context.Context) string {
    id, _ := ctx.Value(ctxKey{}).(string)
    return id
}

Context kaliti sifatida eksport qilinmagan maxsus tur (ctxKey) ishlatildi. Oddiy "request_id" satri kalit bo‘lsa, boshqa paket ham xuddi shu satrni ishlatib, qiymatni ustidan yozib yuborishi mumkin. Alohida tur bunday to‘qnashuvning oldini oladi.

To‘liq middleware

main.go
package main

import (
    "context"
    "crypto/rand"
    "encoding/hex"
    "fmt"
    "log/slog"
    "net/http"
    "os"
    "regexp"
    "time"
)

// ---------- responseRecorder ----------

type responseRecorder struct {
    http.ResponseWriter
    status int
    bytes  int
}

func (rec *responseRecorder) WriteHeader(code int) {
    rec.status = code
    rec.ResponseWriter.WriteHeader(code)
}

func (rec *responseRecorder) Write(b []byte) (int, error) {
    if rec.status == 0 {
        rec.status = http.StatusOK
    }
    n, err := rec.ResponseWriter.Write(b)
    rec.bytes += n
    return n, err
}

func (rec *responseRecorder) Unwrap() http.ResponseWriter {
    return rec.ResponseWriter
}

// ---------- Request ID ----------

type ctxKey struct{}

var validRequestID = regexp.MustCompile(`^[a-zA-Z0-9-]{1,64}$`)

func newRequestID() string {
    b := make([]byte, 8)
    rand.Read(b)
    return hex.EncodeToString(b)
}

func RequestID(ctx context.Context) string {
    id, _ := ctx.Value(ctxKey{}).(string)
    return id
}

// ---------- Middleware ----------

func Logging(logger *slog.Logger) func(http.Handler) http.Handler {
    return func(next http.Handler) http.Handler {
        return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
            start := time.Now()

            id := r.Header.Get("X-Request-ID")
            if !validRequestID.MatchString(id) {
                id = newRequestID()
            }
            w.Header().Set("X-Request-ID", id)
            ctx := context.WithValue(r.Context(), ctxKey{}, id)

            rec := &responseRecorder{ResponseWriter: w}
            next.ServeHTTP(rec, r.WithContext(ctx))

            if rec.status == 0 {
                rec.status = http.StatusOK // handler hech narsa yozmagan
            }

            level := slog.LevelInfo
            switch {
            case rec.status >= 500:
                level = slog.LevelError
            case rec.status >= 400:
                level = slog.LevelWarn
            }

            logger.LogAttrs(ctx, level, "http so‘rov",
                slog.String("request_id", id),
                slog.String("method", r.Method),
                slog.String("path", r.URL.Path),
                slog.Int("status", rec.status),
                slog.Int("bytes", rec.bytes),
                slog.Duration("duration", time.Since(start)),
                slog.String("remote_addr", r.RemoteAddr),
                slog.String("user_agent", r.UserAgent()),
            )
        })
    }
}

// ---------- Handlerlar ----------

func main() {
    logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))

    mux := http.NewServeMux()
    mux.HandleFunc("GET /books", func(w http.ResponseWriter, r *http.Request) {
        fmt.Fprintln(w, `[{"id":1,"title":"O‘tkan kunlar"}]`)
    })
    mux.HandleFunc("GET /books/{id}", func(w http.ResponseWriter, r *http.Request) {
        logger.Info("kitob qidirilmoqda",
            "request_id", RequestID(r.Context()),
            "id", r.PathValue("id"))
        http.Error(w, "kitob topilmadi", http.StatusNotFound)
    })
    mux.HandleFunc("GET /crash", func(w http.ResponseWriter, r *http.Request) {
        http.Error(w, "ichki xato", http.StatusInternalServerError)
    })

    handler := Logging(logger)(mux)

    logger.Info("server ishga tushdi", "addr", ":8080")
    if err := http.ListenAndServe(":8080", handler); err != nil {
        logger.Error("server to‘xtadi", "err", err)
        os.Exit(1)
    }
}

Sinab ko‘ramiz:

curl -i http://localhost:8080/books
curl http://localhost:8080/books/7
curl -H "X-Request-ID: mobile-app-42" http://localhost:8080/crash

Birinchi so‘rov javobida request ID sarlavhasi ko‘rinadi:

HTTP/1.1 200 OK
X-Request-Id: 5c1e0a9b3d7f2e84
...

Server loglari (qulaylik uchun time maydoni qisqartirilgan):

{"level":"INFO","msg":"http so‘rov","request_id":"5c1e0a9b3d7f2e84","method":"GET","path":"/books","status":200,"bytes":37,"duration":41250,"remote_addr":"127.0.0.1:50412","user_agent":"curl/8.5.0"}
{"level":"INFO","msg":"kitob qidirilmoqda","request_id":"a41d77c09e3b5f12","id":"7"}
{"level":"WARN","msg":"http so‘rov","request_id":"a41d77c09e3b5f12","method":"GET","path":"/books/7","status":404,"bytes":16,"duration":88917,"remote_addr":"127.0.0.1:50418","user_agent":"curl/8.5.0"}
{"level":"ERROR","msg":"http so‘rov","request_id":"mobile-app-42","method":"GET","path":"/crash","status":500,"bytes":11,"duration":30125,"remote_addr":"127.0.0.1:50422","user_agent":"curl/8.5.0"}

Natijani tahlil qilamiz:

404 javobi WARN, 500 esa ERROR darajasida yozildi. Loglar tizimida faqat xatolarni filtrlash oson.
Handler ichidagi kitob qidirilmoqda yozuvi va middleware yozuvi bir xil request_idga ega. Ular bitta so‘rovga tegishli ekani aniq ko‘rinadi.
Uchinchi so‘rovda klient yuborgan mobile-app-42 ID’si ishlatildi.
duration nanosekundlarda yozildi. slog.Duration JSON handlerda son, text handlerda esa 1.2ms ko‘rinishida chiqadi.

`LogAttrs` nima uchun?

logger.Info("msg", "key", value) qulay, lekin har chaqiruvda qiymatlar any turiga o‘raladi. LogAttrs bilan slog.String, slog.Int kabi tipli atributlar beriladi. Bu biroz tezroq ishlaydi va kalit-qiymat juftligini noto‘g‘ri yozib qo‘yish ehtimolini yo‘qotadi. Har bir so‘rovda ishlaydigan middleware uchun bu farq sezilarli bo‘lishi mumkin.

Nimani log qilmaslik kerak?

Logging middleware barcha so‘rovlarni ko‘radi. Shuning uchun u maxfiy ma’lumot sizib chiqishi mumkin bo‘lgan asosiy joylardan biri.

Authorization va Cookie sarlavhalarini yozmang.
So‘rov tanasini log qilmang: unda parol yoki shaxsiy ma’lumot bo‘lishi mumkin.
Query parametrlarda token yuboriladigan bo‘lsa (?token=...), r.URL.Path yozing, r.URL.String() emas.

Health check so‘rovlarini tashlab ketish

Kubernetes yoki load balancer serverni har bir necha soniyada /healthz orqali tekshiradi. Bunday so‘rovlar loglarni to‘ldirib yuboradi. Ularni middleware boshida o‘tkazib yuborish mumkin:

if r.URL.Path == "/healthz" {
    next.ServeHTTP(w, r)
    return
}

Xulosa

Status kod va javob hajmini bilish uchun ResponseWriter o‘z turimiz bilan o‘raladi.
O‘ralgan writer’ga Unwrap metodi qo‘shilsa, http.ResponseController asl writer imkoniyatlarini topa oladi.
Request ID har bir so‘rovni ajratib turadi. U javob sarlavhasida qaytariladi va contextga joylanadi.
Status kodga qarab log darajasi tanlanadi: 2xx — INFO, 4xx — WARN, 5xx — ERROR.
Loglarga token, cookie va so‘rov tanasini yozmang.

Keyingi darsda javob vaqtini o‘lchaydigan va panic hamda xatolarni bir joyda ushlaydigan middleware’lar yozamiz.