Источник: Nuances of Programming
Независимо от того, какой язык вы используете, ведение логов наверняка облегчит процесс отладки приложения. Распечатка в stdout осуществляется на локальном компьютере, но как только вам понадобится выполнить развертывание, с этим уже будет сложнее справиться, особенно при масштабировании и запуске приложения на нескольких серверах.
Вот когда понадобятся внешние инструменты, такие как Kibana ( ELK Stack.), Greylog, Datadog … Что их объединяет? Все они требуют ведения логов стандартного формата, чаще всего JSON. Это предполагает использование структурированных регистраторов, которые записывают строки логов в текстовом формате JSON (или другом структурированном виде).
Выбор библиотеки
Go имеет множество библиотек, созданных для этой цели. Самые популярные — Logrus, Zap и Zerolog. Большинство из них похожи друг на друга по своему функционалу. Я использую Zerolog уже довольно давно, в том числе и в этом посте для демонстрации записей логов (вы можете применить большую часть руководства для других библиотек), но я бы не рекомендовал вам его применять. Почему?
В нижней части файла сведений Zerolog есть заявление об отказе от ответственности, в котором говорится::
Обратите внимание, что Zerolog не удаляет дубликатов полей. Использование одного и того же ключа несколько раз создает несколько ключей в конечной точке JSON: в этом случае многие потребители принимают последнее значение, но это не гарантированный вариант. Проверьте свои ключи, если сомневаетесь.
У меня не раз возникала такая проблема, когда логи пропадали с контрольной панели, поскольку агент не мог получить строки логов из-за отсутствия доступа к JSON.
Разработчик Zerolog утверждает, что у его продукта производительность выше, чем у других библиотек, но я не понимаю, как логирование влияет на производительность сервиса, если только речь не идет о чем-то критически важном.
Логирование в файле вместо стандартного вывода
Помимо структурированного логирования, некоторые агенты парсят логи из файла. Я использую lumberjack, чтобы добиться этого в Go.
z := zerolog.New(&lumberjack.Logger{
Filename: "file.log", // Имя файла
MaxSize: 100, // Размер в МБ до ротации файла
MaxBackups: 5, // Максимальное количество файлов, сохраненных до перезаписи
MaxAge: 30, // Максимальное количество дней для хранения файлов
Compress: true, // Следует ли сжимать файлы логов с помощью gzip
})
Инициализация регистратора
Первый шаг, который вам нужно сделать, — это запустить регистратор:
z := zerolog.New(&lumberjack.Logger{
Filename: cfg.Filename,
MaxSize: cfg.MaxSize, // m
MaxBackups: cfg.MaxBackups,
MaxAge: cfg.MaxAge,
Compress: cfg.Compress,
})
return z.With().Caller().Timestamp().Logger()
После запуска экземпляра Zerolog можно приступить к логированию. Иногда я создаю экземпляр глобального регистратора, чтобы иметь возможность обработать ошибку, зарегистрировав ее, и продолжить выполнение.
// Регистратор - глобальный
var Logger zerolog.Loggerz := zerolog.New(&lumberjack.Logger{
Filename: cfg.Filename,
MaxSize: cfg.MaxSize, // m
MaxBackups: cfg.MaxBackups,
MaxAge: cfg.MaxAge,
Compress: cfg.Compress,
})
z = z.With().Caller().Timestamp().Logger()
Logger = z
return z
Промежуточное ПО для логирования
Когда мой экземпляр логов готов, приходит время для регистрации http-запросов. Go имеет отличную поддержку промежуточного ПО, включая основной механизм логирования.
Я регистрирую запросы, ответы, коды состояния и многое другое. Логирование зачастую трактуется только как регистрация ошибок/предупреждений, а, в случае успеха, полагаются исключительно на показатели. Независимо от того, разделяете вы такой подход или нет, можете легко обновить промежуточное ПО, чтобы игнорировать/исключить записи со статусом <500.
func Logger(l zerolog.Logger) mux.MiddlewareFunc {
return func(next http.Handler) http.Handler {
// Записывает все ответы.
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
ww := NewWrapResponseWriter(w, r.ProtoMajor)
rec := httptest.NewRecorder() ctx := r.Context() path := r.URL.EscapedPath() reqData, _ := httputil.DumpRequest(r, false) logger := l.Log().Timestamp().Str("path", path).Bytes("request_data", reqData) defer func(begin time.Time) {
status := ww.Status() tookMs := time.Since(begin).Milliseconds()
logger.Int64("took", tookMs).Int("status_code", status).Msgf("[%d] %s http request for %s took %dms", status, r.Method, path, tookMs) }(time.Now())
// Замените "logger" пользовательским типом, например ContextKey("logger")
ctx = context.WithValue(ctx, "logger", logger)
next.ServeHTTP(rec, r.WithContext(ctx)) // копирует записанный ответ в response writer
for k, v := range rec.Header() {
ww.Header()[k] = v
} ww.WriteHeader(rec.Code)
rec.Body.WriteTo(ww)
})
}
}
Это базовый HTTP регистратор промежуточного программного обеспечения. Он регистрирует путь доступа, запрос данных, текущее состояние и период ожидания. Он также добавляет контекст, чтобы его можно было использовать в дальнейшем. Код NewWrapResponseWriter можно найти в Gist, который позволяет подключаться к ResponseWriter и получать фактический статус/заголовки.
Обычно у вас есть промежуточное программное обеспечение аутентификации, которое парсит сессионные куки-файлы/токен/JWT и авторизует запросы. В этом промежуточном программном обеспечении я регистрирую идентификатор пользователя, имя пользователя, куки-файлы/токен и, возможно, пользовательский объект.
// Промежуточное ПО для аутентификации
token := r.Header.Get("Authorization")
user := getUserFromToken(token)// Do actual authorizationctx := r.Context()
logger := context.Value(r.Context(), "logger").(*zerolog.Event)
logger.Str("user_id", user.ID).Str("user_name", user.Username).Str("token", token)r = r.WithContext(context.WithValue(ctx, "logger", logger))
Поскольку вы будете передавать контекст в своем коде, вы можете легко извлечь регистратор и зарегистрировать конкретные поля, которые вам могут понадобиться. У меня есть вспомогательная функция, которая извлекает регистратор из контекста, а если ее у вас нет, создайте новый экземпляр регистратора.
func FromContext(ctc context.Context) *zerolog.Event{
logger, ok := ctx.Value(ContextKey("logger")).(*zerolog.Event)
if ok {
return logger
}
return Logger.Log().Timestamp()
}
Промежуточное программное обеспечение для восстановления
Если у вас есть промежуточное программное обеспечение восстановления (собственно, оно должно у вас быть), вы можете зарегистрировать трассировку стека, фактическую ошибку и тревожные сигналы, такие как:
// Устраните тревожные сигналы от upstream-систем
func Recover(next http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
defer func() {
if err := recover(); err != nil {
ctx := r.Context()
logger := zlog.FromContext(ctx)
stack := make([]byte, 8096)
stack = stack[:runtime.Stack(stack, false)]
logger.Bytes("stack", stack).Str("level", "fatal").Interface("error", err) hasRecovered, ok := ctx.Value(polymer.ContextKey("has_recovered")).(*bool)
if ok {
*hasRecovered = true
} http.Error(w, http.StatusText(http.StatusInternalServerError), http.StatusInternalServerError)
}
}() next.ServeHTTP(w, r)
})
}
Я использую значение hasRecoveredв контексте, чтобы не дать ZeroLog дважды регистрировать поле level. Вместо этого, регистрирую его на уровне fatal. Если вы регистрируете тревожные сигналы на уровне error, вам не нужно этого делать.
Привязки и постоянный контекст логирования
Есть определенные вещи, которые вам надо включить в каждую строку логов. Речь идет о таких данных, как sha1 коммита, дата/номер сборки, дата начала.
С X-флагами Go довольно легко передать sha1 исполняемому файлу Go. Как только вы его получите, добавить его в регистратор станет еще проще:
type TraceDisableHook struct {
nonLocal bool
}// Запуск реализует интерфейс привязки
func (t TraceDisableHook) Run(e *zerolog.Event, lvl zerolog.Level, _ string) {
if t.nonLocal && lvl == zerolog.TraceLevel {
e.Discard()
}
}func New(apiVersion string, nonLocal bool, cfg Config) zerolog.Logger {
traceDisableHook := TraceDisableHook{nonLocal: nonLocal}
return zerolog.New(os.Stdout).With().Timestamp().
Str("api_version", apiVersion).
Str("github_link", fmt.Sprintf("https://github.com/organization/project/tree/%s", apiVersion)).
Caller().Logger().Hook(traceDisableHook)
Номер коммита и дата сборки/начала — это статические значения, определенные во время сборки/запуска сервера. Но некоторые значения являются динамическими, и регистратор не может быть создан с их помощью. Привязки — это способ динамического добавления данных в логи, поддерживаемый большинством основных библиотек для логирования.
В приведенном выше примере TraceDisableHook отключает все записи уровня trace для нелокальных сред (есть лучший способ сделать это с помощью ZeroLog). Привязки предлагают отличный способ легко расширить ваши логи в рамках нужного вам контекста.
Читайте также:
Читайте нас в Telegram, VK и Яндекс.Дзен
Перевод статьи Emir Ribic: HTTP logging in Go
