لاگ‌گیری ساختاریافته (Structured Logging)

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

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

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

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

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

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

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

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

ایجاد یک لاگر ساختاریافته (Creating a Structured Logger)

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

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

کد ایجاد یک لاگر به این صورت است:

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

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

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

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

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

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

استفاده از یک لاگر ساختاریافته (Using a Structured Logger)

پس از ایجاد یک لاگر ساختاریافته، می‌توانید با فراخوانی متدهای 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() متدهای variadic هستند که تعداد دلخواهی از ویژگی‌های اضافی (جفت‌های کلید-مقدار) را می‌پذیرند. به این صورت:

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=/

افزودن لاگ‌گیری ساختاریافته به برنامه ما (Adding Structured Logging to Our Application)

خوب، بیایید فایل 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 حاوی محتوای پیام خطا است و هیچ ویژگی اضافی وجود ندارد.

اطلاعات اضافی (Additional Information)

ویژگی‌های ایمن‌تر (Safer Attributes)

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

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() ویژگی‌هایی با نوع خاصی از مقدار ایجاد کنید.

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

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

لاگ‌های فرمت‌شده به صورت JSON (JSON-formatted Logs)

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

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

هنگام استفاده از مدیریت‌کننده 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"}

حداقل سطح لاگ (Minimum Log Level)

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

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

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

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

مکان فراخوانی (Caller Location)

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

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/letsgofa/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() برای همزمانی ایمن هستند. می‌توانید یک لاگر را به اشتراک بگذارید و از آن در چندین گوروتین و در مدیریت‌کننده‌های HTTP خود استفاده کنید بدون اینکه نگران شرایط مسابقه باشید.

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

واژه‌نامه اصطلاحات فنی