لاگ‌گیری ساختاریافته

در حال حاضر، ما ورودی‌های لاگ را از کد خود با استفاده از توابع log.Printf() و log.Fatal() خروجی می‌دهیم. یک مثال خوب از این، ورودی لاگ “starting server…” است که دقیقاً قبل از شروع سرور ما چاپ می‌کنیم:

log.Printf("starting server on %s", *addr)

هر دو تابع log.Printf() و log.Fatal() ورودی‌های لاگ را با استفاده از لاگر استاندارد Go از پکیج log خروجی می‌دهند، که — به طور پیش‌فرض — یک پیام را با تاریخ و زمان محلی پیشوند می‌کند و به جریان خطای استاندارد می‌نویسد (که باید در پنجره ترمینال شما نمایش داده شود).

$ go run ./cmd/web/
2024/03/18 11:29:23 starting server on :4000

برای بسیاری از برنامه‌ها، استفاده از لاگر استاندارد کافی خواهد بود و نیازی به انجام کار پیچیده‌تری نیست.

اما برای برنامه‌هایی که لاگ‌گیری زیادی انجام می‌دهند، ممکن است بخواهید ورودی‌های لاگ را برای فیلتر و کار آسان‌تر کنید. به عنوان مثال، ممکن است بخواهید بین شدت‌های مختلف ورودی‌های لاگ تمایز قائل شوید (مانند ورودی‌های اطلاعاتی و خطا)، یا ساختار یکنواختی برای ورودی‌های لاگ اعمال کنید تا برای برنامه‌ها یا سرویس‌های خارجی تجزیه آسان باشند.

برای پشتیبانی از این، کتابخانه استاندارد Go شامل پکیج log/slog است که به شما امکان ایجاد لاگرهای ساختاریافته سفارشی که ورودی‌های لاگ را در یک فرمت مشخص خروجی می‌دهند را می‌دهد. هر ورودی لاگ شامل موارد زیر است:

• یک برچسب زمانی با دقت میلی‌ثانیه.
• سطح شدت ورودی لاگ (Debug، Info، Warn یا Error).
• پیام لاگ (یک مقدار string دلخواه).
• به صورت اختیاری، هر تعداد جفت کلید-مقدار (معروف به ویژگی‌ها) حاوی اطلاعات اضافی.

ایجاد یک لاگر ساختاریافته

کد ایجاد یک لاگر ساختاریافته با پکیج log/slog ممکن است اولین بار که آن را می‌بینید کمی گیج‌کننده باشد.

نکته کلیدی که باید درک کنید این است که همه لاگرهای ساختاریافته یک handler لاگ ساختاریافته مرتبط با خود دارند (نباید با یک HTTP handler اشتباه گرفته شود)، و در واقع این handler لاگ است که نحوه فرمت‌بندی ورودی‌های لاگ و محل نوشتن آن‌ها را کنترل می‌کند.

کد ایجاد یک لاگر (logger) به این شکل است:

loggerHandler := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{...})
logger := slog.New(loggerHandler)

در خط اول کد، ابتدا از تابع slog.NewTextHandler() برای ایجاد handler لاگ ساختاریافته استفاده می‌کنیم. این تابع دو آرگومان می‌پذیرد:

• آرگومان اول مقصد نوشتن برای ورودی‌های لاگ است. در مثال بالا آن را روی os.Stdout تنظیم کرده‌ایم، که به معنای نوشتن ورودی‌های لاگ به جریان خروجی استاندارد است.
• آرگومان دوم یک اشاره‌گر به یک ساختار slog.HandlerOptions است که می‌توانید از آن برای سفارشی‌سازی رفتار handler استفاده کنید. در پایان این فصل به برخی از سفارشی‌سازی‌های موجود نگاهی می‌اندازیم. اگر با پیش‌فرض‌ها راضی هستید و نمی‌خواهید چیزی را تغییر دهید، می‌توانید به جای آن nil را به عنوان آرگومان دوم ارسال کنید.

سپس در خط دوم کد، در واقع لاگر ساختاریافته را با ارسال handler به تابع slog.New() ایجاد می‌کنیم.

در عمل، انجام همه این کارها در یک خط کد رایج‌تر است:

logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{...}))

استفاده از یک لاگر ساختاریافته

پس از ایجاد یک لاگر ساختاریافته، می‌توانید یک ورودی لاگ در سطح شدت خاص با فراخوانی متدهای Debug()، Info()، Warn() یا Error() روی لاگر بنویسید. به عنوان مثال، خط کد زیر:

logger.Info("request received")

منجر به یک ورودی لاگ می‌شود که به این شکل است:

time=2024-03-18T11:29:23.000+00:00 level=INFO msg="request received"

متدهای Debug()، Info()، Warn() یا Error() متدهای متغیر هستند که تعداد دلخواهی از ویژگی‌های اضافی (جفت‌های کلید-مقدار) را می‌پذیرند. مانند این:

logger.Info("request received", "method", "GET", "path", "/")

در این مثال، ما دو ویژگی اضافی به ورودی لاگ اضافه کرده‌ایم: کلید "method" و مقدار "GET"، و کلید "path" و مقدار "/". کلیدهای ویژگی باید همیشه رشته باشند، اما مقادیر می‌توانند از هر نوعی باشند. در این مثال، ورودی لاگ به این شکل خواهد بود:

time=2024-03-18T11:29:23.000+00:00 level=INFO msg="request received" method=GET path=/

افزودن لاگ‌گیری ساختاریافته به برنامه ما

خوب، بیایید ادامه دهیم و فایل main.go خود را برای استفاده از یک لاگر ساختاریافته به جای لاگر استاندارد Go به‌روزرسانی کنیم. مانند این:

package main

import (
    "flag"
    "log/slog" // New import
    "net/http"
    "os" // New import
)

func main() {
    addr := flag.String("addr", ":4000", "HTTP network address")
    flag.Parse()

    // Use the slog.New() function to initialize a new structured logger, which
    // writes to the standard out stream and uses the default settings.
    logger := slog.New(slog.NewTextHandler(os.Stdout, nil))

    mux := http.NewServeMux()

    fileServer := http.FileServer(http.Dir("./ui/static/"))
    mux.Handle("GET /static/", http.StripPrefix("/static", fileServer))

    mux.HandleFunc("GET /{$}", home)
    mux.HandleFunc("GET /snippet/view/{id}", snippetView)
    mux.HandleFunc("GET /snippet/create", snippetCreate)
    mux.HandleFunc("POST /snippet/create", snippetCreatePost)

    // Use the Info() method to log the starting server message at Info severity
    // (along with the listen address as an attribute).
    logger.Info("starting server", "addr", *addr)

    err := http.ListenAndServe(*addr, mux)
    // And we also use the Error() method to log any error message returned by
    // http.ListenAndServe() at Error severity (with no additional attributes),
    // and then call os.Exit(1) to terminate the application with exit code 1.
    logger.Error(err.Error())
    os.Exit(1)
}

خوب… بیایید این را امتحان کنیم!

ادامه دهید و برنامه را اجرا کنید، سپس یک پنجره ترمینال دیگر باز کنید و سعی کنید آن را بار دوم اجرا کنید. این باید یک خطا ایجاد کند زیرا آدرس شبکه که سرور ما می‌خواهد روی آن گوش دهد (":4000") در حال استفاده است.

خروجی لاگ در ترمینال دوم شما باید کمی شبیه این باشد:

$ go run ./cmd/web
time=2024-03-18T11:29:23.000+00:00 level=INFO msg="starting server" addr=:4000
time=2024-03-18T11:29:23.000+00:00 level=ERROR msg="listen tcp :4000: bind: address already in use"
exit status 1

این به نظر خوب می‌رسد. می‌بینیم که دو ورودی لاگ حاوی اطلاعات متفاوتی هستند، اما به همان روش کلی فرمت شده‌اند.

ورودی لاگ اول شدت level=INFO و پیام msg="starting server" دارد، همراه با ویژگی اضافی addr=:4000. در مقابل، می‌بینیم که ورودی لاگ دوم شدت level=ERROR دارد، مقدار msg حاوی محتوای پیام خطا است و هیچ ویژگی اضافی وجود ندارد.

اطلاعات اضافی

ویژگی‌های امن‌تر

بیایید بگوییم که به طور تصادفی کدی می‌نویسید که فراموش می‌کنید کلید یا مقدار یک ویژگی را شامل کنید. به عنوان مثال:

logger.Info("starting server", "addr") // Oops, the value for "addr" is missing

وقتی این اتفاق می‌افتد، ورودی لاگ همچنان نوشته می‌شود اما ویژگی کلید !BADKEY خواهد داشت، مانند این:

time=2024-03-18T11:29:23.000+00:00 level=INFO msg="starting server" !BADKEY=addr

برای جلوگیری از این اتفاق و شناسایی هر مشکلی در زمان کامپایل، می‌توانید به جای آن از تابع slog.Any() برای ایجاد یک جفت ویژگی استفاده کنید:

logger.Info("starting server", slog.Any("addr", ":4000"))

یا می‌توانید حتی بیشتر پیش بروید و با استفاده از توابع slog.String()، slog.Int()، slog.Bool()، slog.Time() و slog.Duration() برای ایجاد ویژگی‌ها با نوع خاصی از مقدار، ایمنی نوع (type safety) اضافی معرفی کنید.

logger.Info("starting server", slog.String("addr", ":4000"))

استفاده از این توابع یا نه به خود شما بستگی دارد. پکیج log/slog نسبتاً جدید در Go است (در Go 1.21 معرفی شد)، و هنوز روش‌های زیادی از بهترین روش‌ها یا قراردادهای تثبیت شده در مورد استفاده از آن وجود ندارد. اما معامله ساده است… استفاده از توابعی مانند slog.String() برای ایجاد ویژگی‌ها طولانی‌تر است، اما از این نظر امن‌تر است که خطر باگ‌ها در برنامه شما را کاهش می‌دهد.

لاگ‌های فرمت JSON

تابع slog.NewTextHandler() که در این فصل استفاده کرده‌ایم، یک handler ایجاد می‌کند که ورودی‌های لاگ متنی ساده می‌نویسد. اما امکان ایجاد یک handler که ورودی‌های لاگ را به عنوان اشیاء JSON می‌نویسد با استفاده از تابع slog.NewJSONHandler() وجود دارد. مانند این:

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

هنگام استفاده از handler JSON، خروجی لاگ شبیه این خواهد بود:

{"time":"2024-03-18T11:29:23.00000000+00:00","level":"INFO","msg":"starting server","addr":":4000"}
{"time":"2024-03-18T11:29:23.00000000+00:00","level":"ERROR","msg":"listen tcp :4000: bind: address already in use"}

حداقل سطح لاگ

همانطور که چند بار ذکر کردیم، پکیج log/slog چهار سطح شدت را پشتیبانی می‌کند: Debug، Info، Warn و Error به ترتیب. Debug کم‌شدت‌ترین سطح است و Error شدیدترین سطح است.

به طور پیش‌فرض، حداقل سطح لاگ برای یک لاگر ساختاریافته Info است. این به معنای آن است که هر ورودی لاگ با شدت کمتر از Info — یعنی ورودی‌های سطح Debug — به طور خاموش دور ریخته می‌شوند.

می‌توانید از ساختار (struct) slog.HandlerOptions برای بازنویسی این و تنظیم حداقل سطح روی Debug (یا هر سطح دیگری) استفاده کنید اگر می‌خواهید:

logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
    Level: slog.LevelDebug,
}))

موقعیت فراخوان‌کننده

همچنین می‌توانید handler را سفارشی کنید تا نام فایل و شماره خط کد منبع فراخوانی را در ورودی‌های لاگ شامل کند، مانند این:

logger := slog.New(slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
    AddSource: true,
}))

ورودی‌های لاگ شبیه این خواهند بود، با موقعیت فراخوان‌کننده ثبت شده تحت کلید source:

time=2024-03-18T11:29:23.000+00:00 level=INFO source=/home/alex/code/snippetbox/cmd/web/main.go:32 msg="starting server" addr=:4000

لاگ‌گیری جدا شده

در این فصل، لاگر ساختاریافته خود را برای نوشتن ورودی‌ها به os.Stdout — جریان خروجی استاندارد — تنظیم کرده‌ایم.

مزیت بزرگ نوشتن ورودی‌های لاگ به os.Stdout این است که برنامه و لاگ‌گیری شما جدا شده‌اند. خود برنامه شما نگران مسیریابی یا ذخیره‌سازی لاگ‌ها نیست، و این می‌تواند مدیریت لاگ‌ها را بسته به محیط متفاوت آسان‌تر کند.

در طول توسعه، مشاهده خروجی لاگ آسان است زیرا جریان خروجی استاندارد در ترمینال نمایش داده می‌شود.

در محیط‌های استیجینگ یا تولید، می‌توانید جریان را به مقصد نهایی برای مشاهده و بایگانی هدایت کنید. این مقصد می‌تواند فایل‌های روی دیسک یا یک سرویس لاگ‌گیری مانند Splunk باشد. در هر صورت، مقصد نهایی لاگ‌ها می‌تواند توسط محیط اجرای شما مستقل از برنامه مدیریت شود.

به عنوان مثال، می‌توانیم جریان خروجی استاندارد را هنگام راه‌اندازی برنامه به یک فایل روی دیسک هدایت کنیم، مانند این:

$ go run ./cmd/web >>/tmp/web.log

لاگ‌گیری همزمان

لاگرهای سفارشی ایجاد شده توسط slog.New() از نظر همزمانی (concurrency-safe) امن هستند. می‌توانید یک لاگر واحد را به اشتراک بگذارید و از آن در چندین گوروتین و در HTTP handlerهای خود استفاده کنید بدون نیاز به نگرانی در مورد شرایط مسابقه (race conditions).

با این حال، اگر چندین لاگر ساختاریافته دارید که به همان مقصد می‌نویسند، باید مراقب باشید و اطمینان حاصل کنید که متد Write() زیربنایی مقصد نیز برای استفاده همزمان امن است.