Golang логирование ошибок

Содержание статьи

• Разделение логирования для разных задач
• Логирование ошибок от HTTP-сервера
• Дополнительные методы логирования
• Конкурентное логирование в Golang
• Логирование сообщений в файл

Логгирование можно поделить на два различных типа, или уровня. К первому типу относятся информационные сообщения (вроде «Запуск сервера на :4000«), а ко второму типу относятся сообщения об ошибках.

Давайте усовершенствуем наше приложение, добавив возможность многоуровнего логирования, чтобы информационные сообщения и сообщения об ошибках обрабатывались по-разному. А именно:

• Информационным сообщениям добавим префикс "INFO". Такое сообщение будет выводиться в стандартный поток вывода (stdout);
• Сообщениям об ошибках добавим префикс "ERROR". Такие сообщения будут выводиться в стандартный поток ошибок (stderr) вместе с соответствующим названием файла и номером строки, которая вызвала логгер для записи (это поможет в отладке на будущее).

Есть несколько способов использования разных логгеров, но самый простой и понятный подход заключается в использовании функции log.New() для создания двух новых настраиваемых логгеров.

Откройте файл main.go и обновите его код следующим образом:

Отлично… проверим эти изменения в действии!

Попробуйте запустить приложение, затем откройте другое окно терминала и попробуйте запустить его во второй раз. В результате должна появится сообщение об ошибке, потому что сетевой адрес, который наш сервер хочет прослушать (":4000"), уже используется другим процессом.

Логи во втором терминале должны выглядеть следующим образом:

Обратите внимание, что у этих двух сообщений разные префиксы — чтобы их можно было легко различить в терминале — и наше сообщение об ошибке также включает в себя название файла и номер строки (main.go:37), которая вызывает логгер для записи возникнувшей ошибки.

На заметку: Если вы хотите включить весь путь файла в лог  вместо просто названия файла, при создании логгера можно использовать флаг log.Llongfile вместо log.Lshortfile. Вы также можете заставить свой логгер  использовать UTC дату (вместо локальной), добавив флаг log.LUTC.

Разделение логирования для разных задач

Большое преимущество логирования сообщений в стандартных потоках (stdout и stderr), как у нас, заключается в том, что само приложение и логирование не связаны. Само приложение не занимается маршрутизацией или хранением логов, и это может упростить управление логами, которое будет различаться в зависимости от среды.

Стандартные потоки отображаются в терминале, поэтому вывод логов можно легко посмотреть после запуска приложения из терминала.

Если приложение запущено в рабочем режиме и обслуживает реальных пользователей, то наши логи должны записываться в специальном месте. Таким местом могут быть файлы на диске или различные сервисы мониторинга работы приложения. В любом случае, конечное место хранения логов может быть указано в самой среде выполнения независимо от приложения.

Например, можно перенаправить потоки из stdout и stderr в файлы на диске при запуске приложения из терминала следующим образом:

Логирование ошибок от HTTP-сервера

Нам нужно внести еще одно изменение в коде нашего веб-приложения. По умолчанию, если HTTP-сервер обнаруживает ошибку, он логирует её с помощью стандартного логгера. Но, лучше использовать наш новый логгер errorLog.

Нам требуется инициализировать новую структуру http.Server, содержащую параметры конфигурации для сервера, вместо использования http.ListenAndServe().

Проще всего будет показать это на примере:

Дополнительные методы логирования

До сих пор мы использовали методы Println(), Printf() и Fatal() для записи логов. Однако Go предоставляет ряд других методов, с которыми стоит ознакомиться.

Как правило, лучше избегать использования методов Panic() и Fatal() за пределами функции main(). Вместо этого рекомендуется возвращать возникшие ошибки, а паниковать или принудительно завершать приложение непосредственно из самого main().

Конкурентное логирование в Golang

Новые логгеры, созданные с помощью log.New(), конкурентно-безопасны. Вы можете делиться одним логгером и использовать его в нескольких горутинах, не беспокоясь об возможных конфликтах между ними из за записи сообщений в одном и том же логгере.

Если у вас есть несколько логгеров, использующих для записи одно и то же место назначения, вам требуется убедиться, что базовый метод  Write() также безопасен для конкурентного использования.

Логирование сообщений в файл

Как было сказано выше, лучше записывать вывод в стандартные потоки и перенаправлять вывод в файл при запуске приложения из командной строки. Но, если вы не хотите этого делать, всегда можно открыть файл в Go и использовать его в качестве места назначения лога. Например:

Скачать исходный код сайта

В конце каждой статьи, вы можете скачать готовый код нашего веб-приложения. В каждой статье мы обновляем код добавляя что-то новое.

Скачать: snippetbox-11.zip

Structured logging involves producing log records in a well-defined format
(usually JSON), which adds a level of organization and consistency to
application logs, making them easier to process. Such log records are composed
of key-value pairs that capture relevant contextual information about the event
being logged, such as the severity level, timestamp, source code location, user
ID, or any other relevant metadata.

This article will delve deep into the world of structured logging in Go with a
specific focus on the
recently accepted slog proposal
which aims to bring high-performance structured, leveled logging to the Go
standard library.

We will begin by examining the existing log package in Go and its limitations,
then do a deep dive into slog by covering all its most important concepts. We
will also briefly discuss some of the Go ecosystem’s most widely-used
third-party structured logging packages and how they can integrate with slog
before wrapping up the article.

The standard library log package

Before we discuss the new
structured logging proposal, let’s
briefly examine the standard library log package which provides a simple way
to write log messages to the console, a file, or any type that implements the
io.Writer interface. Here’s the most basic way to write log messages in Go:

package main

import "log"

func main() {
    log.Println("Hello from Go application!")
}

2023/03/08 11:43:09 Hello from Go application!

The output contains the log message and a timestamp in the local time zone that
indicates when the entry was generated. The Println() method is one of the
methods accessible on the preconfigured global Logger, and it prints to the
standard error. The following other methods are available:

log.Print()
log.Printf()
log.Fatal()
log.Fatalf()
log.Fatalln()
log.Panic()
log.Panicf()
log.Panicln()

The difference between the Fatal and Panic family of methods above is that
the former calls os.Exit(1) after logging a message, while the latter calls
panic().

You can customize the default Logger by retrieving it through the
log.Default() method. Afterward, call the relevant method on the returned
Logger. The example below configures the default logger to write to the
standard output instead of the standard error:

func main() {
    defaultLogger := log.Default()
    defaultLogger.SetOutput(os.Stdout)
    log.Println("Hello from Go application!")
}

You can also create a completely custom logger through the log.New() method
which has the following signature:

func New(out io.Writer, prefix string, flag int) *Logger

The first argument is the destination of the log messages produced by the
Logger which can be anything that implements the io.Writer interface. The
second is a prefix that is prepended to each log message, while the third
specifies a set of constants that can
add details to each log message.

func main() {
    logger := log.New(os.Stdout, "", log.LstdFlags)
    logger.Println("Hello from Go application!")
}

The above logger is configured to print to the standard output, and it uses the
initial values for the default logger. Therefore, the output remains the same as
before:

2023/03/08 11:44:17 Hello from Go application!

Let’s customize it further by adding the application name, file name, and line
number to the each log entry. We’ll also add microseconds to the timestamp, and
record the UTC time instead of the local time:

logger := log.New(
  os.Stderr,
  "MyApplication: ",
  log.Ldate|log.Ltime|log.Lmicroseconds|log.LUTC|log.Lshortfile,
)

MyApplication: 2023/03/08 10:47:12.348478 main.go:14: Hello from Go application!

The MyApplication: prefix appears at the beginning of each log entry, and the
UTC timestamp now includes microseconds. The file name and line number are also
included in the output to help you locate the source of each entry in the
codebase.

Limitations of the log package

Although the log package in Go provides a convenient way to initiate logging,
it is not ideal for production use due to several
limitations, such as the following:

1. Lack of log levels: log levels are one of the
   staple features in most logging packages, but they are missing from the log
   package in Go. All log messages are treated the same way, making it difficult
   to filter or separate log messages based on their importance or severity.

2. No support for structured logging: the log package in Go only outputs
   plain text messages. It does not support structured logging, where the events
   being recorded are represented in a structured format (usually JSON), which
   can be subsequently parsed and analyzed programmatically for monitoring,
   alerting, auditing, creating dashboards, and other forms of analysis.

3. No context-aware logging: the log package does not support
   context-aware logging, making it difficult to attach contextual information
   (such as request IDs, User IDs, and other variables) to log messages
   automatically.

4. No support for log sampling: log sampling is useful for reducing the
   volume of logs in high-throughput applications. Third-party logging libraries
   often provide this functionality, but it is missing from log.

5. Limited configuration options: the log package only supports basic
   configuration options, such as setting the log output destination and prefix
   are supported. Advanced logging libraries offer way more configuration
   opportunities, such as custom log formats, filtering, automatically adding
   contextual data, enabling asynchronous logging, error handling behavior, and
   more!

In light of the aforementioned limitations, a new logging package called slog
has been
proposed
to fill the existing gap in Go’s standard library. In short, this package aims
to enhance logging capabilities in the language by introducing structured
logging with levels, and create a standard interface for logging that other
packages can extend freely.

Structured logging in Go with Slog

The slog package has its origins in
this GitHub discussion opened by Jonathan Amsterdam,
which later led to the proposal
describing the exact design of the package. Once finalized and implemented in a
Go release, it is expected to reside at log/slog. Until then, you can find its
preliminary implementation at
golang.org/x/exp/slog.

Let’s begin our discussion of slog by walking through its design and
architecture. The package provides three main types that you need to be familiar
with:

• Logger: this is the «frontend» for logging with slog. It provides level
  methods such as (Info() and Error()) for recording events of interest.
• Record: it represents each self-contained log record object created by a
  Logger.
• Handler: this is the «backend» of the slog package. It is an interface that,
  once implemented, determines the formatting and destination of each Record.
  Two handlers are included with the slog package by default: TextHandler
  and JSONHandler.

In the following sections, we will present a comprehensive examination of each
of these types, accompanied by relevant examples. Please note that although the
proposal has been accepted, certain details can change prior to the final
release.

To follow along with the examples presented below, install slog into your
project using the following command:

go get golang.org/x/exp/slog@latest

The exact version used in the examples below is:

v0.0.0-20230522175609-2e198f4a06a1

Getting started with Slog

Like most logging frameworks for Go, the slog package
exposes a default Logger accessible through top-level functions on the
package. This logger defaults to the INFO level, and it logs a plaintext
output to the standard output (similar to the log package):

package main

import (
    "golang.org/x/exp/slog"
)

func main() {
    slog.Debug("Debug message")
    slog.Info("Info message")
    slog.Warn("Warning message")
    slog.Error("Error message")
}

2023/03/15 12:55:56 INFO Info message
2023/03/15 12:55:56 WARN Warning message
2023/03/15 12:55:56 ERROR Error message

You can also create a custom Logger instance through the slog.New() method.
It accepts a non-nil Handler interface, which determines how the logs are
formatted and where they are written to. Here’s an example that uses the
built-in JSONHandler type to log to the standard output in JSON format:

func main() {
    logger := slog.New(slog.NewJSONHandler(os.Stdout, nil))
    logger.Debug("Debug message")
    logger.Info("Info message")
    logger.Warn("Warning message")
    logger.Error("Error message")
}

{"time":"2023-03-15T12:59:22.227408691+01:00","level":"INFO","msg":"Info message"}
{"time":"2023-03-15T12:59:22.227468972+01:00","level":"WARN","msg":"Warning message"}
{"time":"2023-03-15T12:59:22.227472149+01:00","level":"ERROR","msg":"Error message"}

Notice that the custom logger also defaults to INFO, which causes the
suppression of the DEBUG entry. If you use the TextHandler type instead,
each log record will be formatted according to the
logfmt standard:

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

time=2023-03-15T13:00:11.333+01:00 level=INFO msg="Info message"
time=2023-03-15T13:00:11.333+01:00 level=WARN msg="Warning message"
time=2023-03-15T13:00:11.333+01:00 level=ERROR msg="Error message"

Customizing the default logger

To configure the default Logger, the most straightforward approach is to
utilize the slog.SetDefault() method, which allows you to substitute the
default logger with a custom one.

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

    slog.SetDefault(logger)

    slog.Info("Info message")
}

{"time":"2023-03-15T13:07:39.105777557+01:00","level":"INFO","msg":"Info message"}

You should observe that the package’s top-level logging methods now produce JSON
logs as seen above. Also, note that using the SetDefault() method alters the
default log.Logger employed by the log package. This modification enables
existing applications that utilize log.Printf() and similar methods to
transition to structured logging.

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

    slog.SetDefault(logger)

    log.Println("Hello from old logger")
}

{"time":"2023-03-16T15:20:33.783681176+01:00","level":"INFO","msg":"Hello from old logger"}

The slog.NewLogLogger() method is also available for converting an
slog.Logger to a log.Logger when you need to utilize APIs that require the
latter (such as http.Server.ErrorLog):

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

  logger := slog.NewLogLogger(handler, slog.LevelError)

  server := http.Server{
    ErrorLog: logger,
  }
}

Contextual logging in Go with Slog

Logging in a structured format offers a significant advantage over traditional
plaintext formats by allowing the inclusion of arbitrary attributes as key/value
pairs in log records. These attributes provide additional context about the
logged event, which can be valuable for tasks such as troubleshooting,
generating metrics, and various other purposes. Here is an example illustrating
how it works in slog:

logger.Info(
  "incoming request",
  "method", "GET",
  "time_taken_ms", 158,
  "path", "/hello/world?q=search",
  "status", 200,
  "user_agent", "Googlebot/2.1 (+http://www.google.com/bot.html)",
)

{
  "time":"2023-02-24T11:52:49.554074496+01:00",
  "level":"INFO",
  "msg":"incoming request",
  "method":"GET",
  "time_taken_ms":158,
  "path":"/hello/world?q=search",
  "status":200,
  "user_agent":"Googlebot/2.1 (+http://www.google.com/bot.html)"
}

All the level methods (Info(), Debug(), etc.) accept a log message as their
first argument, and an unlimited number of loosely-typed key/value pairs
thereafter. This API is similar to the SugaredLogger API in
Zap (specifically its level methods ending in
w) as it prioritizes brevity at the cost of additional allocations. However,
note that it can also lead to strange problems if you’re not careful. Most
notably, unbalanced key/value pairs will yield a problematic output:

logger.Info(
  "incoming request",
  "method", "GET",
  "time_taken_ms", // the value for this key is missing
)

Since the time_taken_ms key does not have a corresponding value, it will be
treated as a value with key !BADKEY:

{
  "time": "2023-03-15T13:15:29.956566795+01:00",
  "level": "INFO",
  "msg": "incoming request",
  "method": "GET",
  "!BADKEY": "time_taken_ms"



  


                       
  




}

This isn’t great because a property misalignment could lead to bad entries being
created, and you may not know about it until you need to use the logs. While the
proposal suggests a vet check to catch missing
key/value problems in methods where they can occur, extra care also needs to be
taken during the review process to ensure that each key/value pair in the entry
are balanced, and the types are correct.

To prevent such mistakes, it’s best only to use
strongly-typed contextual attributes
as shown below:

logger.Info(
  "incoming request",
  slog.String("method", "GET"),
  slog.Int("time_taken_ms", 158),
  slog.String("path", "/hello/world?q=search"),
  slog.Int("status", 200),
  slog.String(
    "user_agent",
    "Googlebot/2.1 (+http://www.google.com/bot.html)",
  ),
)

While this is a much better approach to contextual logging, it’s not fool-proof
as nothing is stopping you from mixing strongly-typed and loosely-typed
key/value pairs like this:

logger.Info(
  "incoming request",
  "method", "GET",
  slog.Int("time_taken_ms", 158),
  slog.String("path", "/hello/world?q=search"),
  "status", 200,
  slog.String(
    "user_agent",
    "Googlebot/2.1 (+http://www.google.com/bot.html)",
  ),
)

To guarantee type safety when adding contextual attributes to your records, you
must use the LogAttrs() method like this:

logger.LogAttrs(
  context.Background(),
  slog.LevelInfo,
  "incoming request",
  slog.String("method", "GET"),
  slog.Int("time_taken_ms", 158),
  slog.String("path", "/hello/world?q=search"),
  slog.Int("status", 200),
  slog.String(
    "user_agent",
    "Googlebot/2.1 (+http://www.google.com/bot.html)",
  ),
)

This method only accepts the slog.Attr type for custom attributes, so it’s not
possible to have an unbalanced key/value pair. However, its API is more
convoluted as you always need to pass a context (or nil) and the log level to
the method in addition to the log message and custom attributes.

Grouping contextual attributes

Slog also provides the ability to group multiple attributes under a single name
name. The way it is displayed depends on the Handler in use. For example, with
JSONHandler, the group is treated as a separate JSON object:

logger.LogAttrs(
  context.Background(),
  slog.LevelInfo,
  "image uploaded",
  slog.Int("id", 23123),
  slog.Group("properties",
    slog.Int("width", 4000),
    slog.Int("height", 3000),
    slog.String("format", "jpeg"),
  ),



  


                       
  




)

{
  "time":"2023-02-24T12:03:12.175582603+01:00",
  "level":"INFO",
  "msg":"image uploaded",
  "id":23123,
  "properties":{
    "width":4000,
    "height":3000,
    "format":"jpeg"
  }
}

When using the TextHandler, each key in the group will be prefixed by the
group name like this:

time=2023-02-24T12:06:20.249+01:00 level=INFO msg="image uploaded" id=23123
  properties.width=4000 properties.height=3000 properties.format=jpeg

Creating and using child loggers

Including the same attributes in all records within a specific program scope can
be beneficial to ensure their presence without repetitive logging statements.
This is where child loggers prove helpful, as they create a new logging context
inheriting from their parent logger while allowing the addition of additional
fields.

In slog, creating child loggers is accomplished using the Logger.With()
method. It accepts one or more key/value pairs, and returns a new Logger that
includes the specified attributes. Consider the following code snippet that adds
the program’s process ID and the Go version used for compilation to each log
record, storing them in a program_info property:

It’s sometimes helpful to include the same attributes in all the records
produced within a given scope of a program so that they are present in all the
records without being repeated at log point. This is where child loggers come in
handy as they create a new logging context that inherits from their parents, but
with additional fields.

Creating child loggers in slog is done through the With() method on a
Logger which accepts a mix of strongly-typed and loosely-typed key/value pairs
and returns a new Logger instance. For example, here’s a snippet that adds the
program’s process ID and the Go version used to compile it to each log record in
a program_info property:

func main() {
    handler := slog.NewJSONHandler(os.Stdout, nil)
    buildInfo, _ := debug.ReadBuildInfo()

    logger := slog.New(handler)

    child := logger.With(
        slog.Group("program_info",
            slog.Int("pid", os.Getpid()),
            slog.String("go_version", buildInfo.GoVersion),
        ),



  


                       
  




    )

    . . .
}

With this configuration in place, all records created by the child logger will
contain the specified attributes under the program_info property as long as it
is not overridden at log point:

func main() {
    . . .

    child.Info("image upload successful", slog.String("image_id", "39ud88"))
    child.Warn(
        "storage is 90% full",
        slog.String("available_space", "900.1 mb"),
    )
}

{
  "time": "2023-02-26T19:26:46.046793623+01:00",
  "level": "INFO",
  "msg": "image upload successful",
  "program_info": {
    "pid": 229108,
    "go_version": "go1.20"
  },
  "image_id": "39ud88"
}
{
  "time": "2023-02-26T19:26:46.046847902+01:00",
  "level": "WARN",
  "msg": "storage is 90% full",
  "program_info": {
    "pid": 229108,
    "go_version": "go1.20"
  },
  "available_space": "900.1 MB"
}

You can also use the WithGroup() method to create a child logger that starts a
group such that all attributes added to the logger (including those added at log
point) will be nested under the group name:

handler := slog.NewJSONHandler(os.Stdout, nil)
buildInfo, _ := debug.ReadBuildInfo()
logger := slog.New(handler).WithGroup("program_info")

child := logger.With(
  slog.Int("pid", os.Getpid()),
  slog.String("go_version", buildInfo.GoVersion),
)

child.Info("image upload successful", slog.String("image_id", "39ud88"))
child.Warn(
  "storage is 90% full",
  slog.String("available_space", "900.1 MB"),
)

{
  "time": "2023-05-24T19:00:18.384085509+01:00",
  "level": "INFO",
  "msg": "image upload successful",
  "program_info": {
    "pid": 1971993,
    "go_version": "go1.20.2",
    "image_id": "39ud88"
  }
}
{
  "time": "2023-05-24T19:00:18.384136084+01:00",
  "level": "WARN",
  "msg": "storage is 90% full",
  "program_info": {
    "pid": 1971993,
    "go_version": "go1.20.2",
    "available_space": "900.1 mb"
  }
}

Customizing log levels

The slog package provides four log levels by default, and each one is
associated with an integer value: DEBUG (-4), INFO (0), WARN (4), and
ERROR (8). The gap of 4 between each level is a deliberate design decision
made to accommodate logging schemes with custom levels between the default ones.
For example, you can create a custom NOTICE level between INFO and WARN
with a value of 1, 2, or 3.

You’ve probably noticed that all loggers are configured to log at the INFO
level by default, which causes events logged at a lower severity (such as
DEBUG) to be suppressed. You can customize this behavior through the
HandlerOptions type
as shown below:

func main() {
    opts := &slog.HandlerOptions{
        Level: slog.LevelDebug,
    }

    handler := slog.NewJSONHandler(os.Stdout, opts)

    logger := slog.New(handler)
    logger.Debug("Debug message")
    logger.Info("Info message")
    logger.Warn("Warning message")
    logger.Error("Error message")
}

{"time":"2023-05-24T19:03:10.70311982+01:00","level":"DEBUG","msg":"Debug message"}
{"time":"2023-05-24T19:03:10.703187713+01:00","level":"INFO","msg":"Info message"}
{"time":"2023-05-24T19:03:10.703190419+01:00","level":"WARN","msg":"Warning message"}
{"time":"2023-05-24T19:03:10.703192892+01:00","level":"ERROR","msg":"Error message"}

Note that this approach fixes the minimum level of the handler throughout its
lifetime. If you need the minimum level to be dynamically varied, you must use
the LevelVar type as illustrated below:

logLevel := &slog.LevelVar{} // INFO

opts := slog.HandlerOptions{
  Level: logLevel,
}

// you can change the level anytime like this
logLevel.Set(slog.LevelDebug)

Creating custom log levels

If you need custom levels beyond what slog provides by default, you can create
them by implementing the
Leveler interface which is
defined by a single method:

type Leveler interface {
    Level() Level
}

It’s also easy to implement the Leveler interface through the Level type as
shown below (since Level itself implements Leveler):

const (
    LevelTrace  = slog.Level(-8)
    LevelNotice = slog.Level(2)
    LevelFatal  = slog.Level(12)
)

Once you’ve defined custom levels as above, you can use them as follows:

opts := &slog.HandlerOptions{
    Level: LevelTrace,
}

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

ctx := context.Background()
logger.Log(ctx, LevelTrace, "Trace message")
logger.Log(ctx, LevelNotice, "Notice message")
logger.Log(ctx, LevelFatal, "Fatal level")

{"time":"2023-02-24T09:26:41.666493901+01:00","level":"DEBUG-4","msg":"Trace level"}
{"time":"2023-02-24T09:26:41.66659754+01:00","level":"INFO+2","msg":"Notice level"}
{"time":"2023-02-24T09:26:41.666602404+01:00","level":"ERROR+4","msg":"Fatal level"}

Notice how the custom levels are labelled in terms of the defaults. This
probably isn’t what you want, so you should customize the level names through
the HandlerOptions type:

. . .

var LevelNames = map[slog.Leveler]string{
    LevelTrace:      "TRACE",
    LevelNotice:     "NOTICE",
    LevelFatal:      "FATAL",
}

func main() {
    opts := slog.HandlerOptions{
        Level: LevelTrace,
        ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
            if a.Key == slog.LevelKey {
                level := a.Value.Any().(slog.Level)
                levelLabel, exists := LevelNames[level]
                if !exists {
                    levelLabel = level.String()
                }

                a.Value = slog.StringValue(levelLabel)
            }

            return a
        },
    }

    . . .
}

{"time":"2023-02-24T09:27:51.747625912+01:00","level":"TRACE","msg":"Trace level"}
{"time":"2023-02-24T09:27:51.747732118+01:00","level":"NOTICE","msg":"Notice level"}
{"time":"2023-02-24T09:27:51.747737319+01:00","level":"FATAL","msg":"Fatal level"}

The ReplaceAttr() function is used to customize how each key/value pair in a
Record is handled by a Handler. It can be used to customize the name of the
key, or transform the value in some way. In the above example, it maps the
custom log levels to their respective labels: TRACE, NOTICE, and FATAL.

Customizing Handlers

As mentioned earlier, both TextHandler and JSONHandler can be customized
using the HandlerOptions type. You’ve already learned how to adjust the
minimum level and modify attributes before they are logged. Another
customization that can be accomplished through HandlerOptions is adding the
source of the log message, if required:

opts := slog.HandlerOptions{
  AddSource: true,
  Level: slog.LevelDebug,
}

{"time":"2023-05-24T19:39:27.005871442+01:00","level":"DEBUG","source":{"function":"main.main","file":"/home/ayo/dev/demo/slog/main.go","line":30},"msg":"Debug message"}
{"time":"2023-05-24T19:39:27.005940778+01:00","level":"INFO","source":{"function":"main.main","file":"/home/ayo/dev/demo/slog/main.go","line":31},"msg":"Info message"}
{"time":"2023-05-24T19:39:27.00594459+01:00","level":"WARN","source":{"function":"main.main","file":"/home/ayo/dev/demo/slog/main.go","line":32},"msg":"Warning message"}
{"time":"2023-05-24T19:39:27.005947669+01:00","level":"ERROR","source":{"function":"main.main","file":"/home/ayo/dev/demo/slog/main.go","line":33},"msg":"Error message"}

It’s also easy to switch handlers based on the application environment. For
example, you might prefer to use the TextHandler for your development logs
since its a little easier to read, then switch to JSONHandler in production
for greater compatibility with various logging tools. You can easily enable such
behavior through an environmental variable:

var appEnv = os.Getenv("APP_ENV")

func main() {
    opts := &slog.HandlerOptions{
        Level: slog.LevelDebug,
    }

    var handler slog.Handler = slog.NewTextHandler(os.Stdout, opts)
    if appEnv == "production" {
        handler = slog.NewJSONHandler(os.Stdout, opts)
    }

    logger := slog.New(handler)

    logger.Info("Info message")
}

time=2023-02-24T10:36:39.697+01:00 level=INFO msg="Info message"

APP_ENV=production go run main.go

{"time":"2023-02-24T10:35:16.964821548+01:00","level":"INFO","msg":"Info message"}

Creating custom Handlers

Since Handler is an interface, you can also create custom handlers for
formatting the logs differently, or writing them to some other destination. Its
signature is as follows:

type Handler interface {
    Enabled(context.Context, Level) bool
    Handle(context.Context, r Record) error
    WithAttrs(attrs []Attr) Handler
    WithGroup(name string) Handler
}

Here’s what each of the methods do:

• Enabled() determines if a log record should be handled or discarded based on
  its level. The context can also used to make a decision.
• Handle() processes each log record sent to the handler. It is called only if
  Enabled() returns true.
• WithAttrs() creates a new handler from an existing one and adds the
  specified attributes it.
• WithGroup() creates a new handler from an existing one and adds the
  specified group name to it such that subsequent attributes are qualified by
  the name.

Here’s an example that uses the log, json, and
color packages to implement a prettified
development output for log records:

// NOTE: Not well tested, just an illustration of what's possible
package main

import (
    "context"
    "encoding/json"
    "io"
    "log"

    "github.com/fatih/color"
    "golang.org/x/exp/slog"
)

type PrettyHandlerOptions struct {
    SlogOpts slog.HandlerOptions
}

type PrettyHandler struct {
    slog.Handler
    l *log.Logger
}

func (h *PrettyHandler) Handle(ctx context.Context, r slog.Record) error {
    level := r.Level.String() + ":"

    switch r.Level {
    case slog.LevelDebug:
        level = color.MagentaString(level)
    case slog.LevelInfo:
        level = color.BlueString(level)
    case slog.LevelWarn:
        level = color.YellowString(level)
    case slog.LevelError:
        level = color.RedString(level)
    }

    fields := make(map[string]interface{}, r.NumAttrs())
    r.Attrs(func(a slog.Attr) bool {
        fields[a.Key] = a.Value.Any()

        return true
    })

    b, err := json.MarshalIndent(fields, "", "  ")
    if err != nil {
        return err
    }

    timeStr := r.Time.Format("[15:05:05.000]")
    msg := color.CyanString(r.Message)

    h.l.Println(timeStr, level, msg, color.WhiteString(string(b)))

    return nil
}

func NewPrettyHandler(
    out io.Writer,
    opts PrettyHandlerOptions,
) *PrettyHandler {
    h := &PrettyHandler{
        Handler: slog.NewJSONHandler(out, &opts.SlogOpts),
        l:       log.New(out, "", 0),
    }

    return h
}

When you use the PrettyHandler in your code like this:

func main() {
    opts := PrettyHandlerOptions{
        SlogOpts: slog.HandlerOptions{
            Level: slog.LevelDebug,
        },
    }
    handler := NewPrettyHandler(os.Stdout, opts)
    logger := slog.New(handler)
    logger.Debug(
        "executing database query",
        slog.String("query", "SELECT * FROM users"),
    )
    logger.Info("image upload successful", slog.String("image_id", "39ud88"))
    logger.Warn(
        "storage is 90% full",
        slog.String("available_space", "900.1 MB"),
    )
    logger.Error(
        "An error occurred while processing the request",
        slog.String("url", "https://example.com"),
    )
}

You will observe the following colorized output when you execute the program:

Hiding sensitive fields with the LogValuer interface

The LogValuer interface allows you to determine what output will be produced
when a custom type is logged. Here’s its signature:

type LogValuer interface {
    LogValue() Value
}

A prime use case for implementing this interface is for hiding sensitive fields
in your custom types. For example, here’s a User type that does not implement
the LogValuer interface. Notice how sensitive details are exposed when type is
logged:

// User does not implement `LogValuer` here
type User struct {
    ID        string `json:"id"`
    FirstName string `json:"first_name"`
    LastName  string `json:"last_name"`
    Email     string `json:"email"`
    Password  string `json:"password"`
}

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

    u := &User{
        ID:        "user-12234",
        FirstName: "Jan",
        LastName:  "Doe",
        Email:     "jan@example.com",
        Password:  "pass-12334",
    }

    logger.Info("info", "user", u)
}

{
  "time": "2023-02-26T22:11:30.080656774+01:00",
  "level": "INFO",
  "msg": "info",
  "user": {
    "id": "user-12234",
    "first_name": "Jan",
    "last_name": "Doe",
    "email": "jan@example.com",
    "password": "pass-12334"
  }
}

Without implementing the LogValuer interface, the entire User type will be
logged as shown above. This is problematic since the type contains secret fields
that should not be present in the logs (such as emails and passwords), and it
can also make your logs unnecessarily verbose.

You can solve this issue by specifying how you’d like the type to be handled in
the logs. For example, you may specify that only the ID field should be logged
as follows:

// implement the `LogValuer` interface
func (u *User) LogValue() slog.Value {
    return slog.StringValue(u.ID)
}

You will now observe the following output:

{
  "time": "2023-02-26T22:43:28.184363059+01:00",
  "level": "INFO",
  "msg": "info",
  "user": "user-12234"
}

You can also group multiple attributes like this:

func (u *User) LogValue() slog.Value {
    return slog.GroupValue(
        slog.String("id", u.ID),
        slog.String("name", u.FirstName+" "+u.LastName),
    )
}

{
  "time": "2023-03-15T14:44:24.223381036+01:00",
  "level": "INFO",
  "msg": "info",
  "user": {
    "id": "user-12234",
    "name": "Jan Doe"
  }
}

Third-party structured logging libraries to consider

While structured logging capabilities are now being built into Go’s standard
library, there are already several third-party logging packages available that
offer additional features and customization options. These packages can enhance
your logging experience, and provide more flexibility in capturing and analyzing
log data. Here are a few notable ones to consider:

1. Zerolog

Zerolog is a structured logging package for Go that features a great
development experience and
impressive performance
when compared to alternative libraries. It offers a chaining API that allows you
to specify the type of each
field added to a log entry which helps avoid unnecessary allocations and
reflection. Zerolog only supports JSON or the lesser-known
Concise Binary Object Representation (CBOR) format, but it
also provides a native way to prettify its output in development environments.

package main

import (
    "github.com/rs/zerolog"
)

func main() {
    logger := zerolog.New(os.Stdout)
    loger.Info().
        Str("name", "John").
        Int("age", 9).
        Msg("hello from zerolog")
}

{"level":"info","name":"John","age":9,"time":"2022-08-11T21:28:12+01:00","message":"hello from zerolog"}

You can import a pre-configured global logger, or use zerolog.New() to create
a customizable logger instance as shown above. You can also create child loggers
with additional context just like in slog. Zerolog also helps you adequately log
errors by providing the ability to include a formatted stack trace through its
integration with the popular errors package. It
also provides several
helper functions for
better integration with HTTP handlers.

If you’re interested in learning more, see our complete guide to production
logging with Zerolog.

2. Zap

Uber’s Zap library was a trailblazer in the reflection-free,
zero-allocation logging approach that Zerolog later adopted. It also offers a
more flexible, loosely typed API suitable for situations where ergonomics and
adaptability take precedence over performance and memory allocations.

package main

import (
    "fmt"
    "time"

    "go.uber.org/zap"
)

func main() {
    // returns zap.Logger, a strongly typed logging API
    logger := zap.Must(zap.NewProduction())

    defer logger.Sync()

    start := time.Now()

    logger.Info("Hello from zap Logger",
        zap.String("name", "John"),
        zap.Int("age", 9),
        zap.String("email", "john@gmail.com"),
    )

    // convert zap.Logger to zap.SugaredLogger for a more flexible and loose API
    // that's still faster than most other structured logging implementations
    sugar := logger.Sugar()
    sugar.Warnf("something bad is about to happen")
    sugar.Errorw("something bad happened",
        "error", fmt.Errorf("oh no!"),
    )
        "answer", 42,

    // you can freely convert back to the base `zap.Logger` type at the boundaries
    // of performance-sensitive operations.
    logger = sugar.Desugar()
    logger.Warn("the operation took longer than expected",
        zap.Int64("time_taken_ms", time.Since(start).Milliseconds()),
    )
}

{"level":"info","ts":1660252436.0265622,"caller":"random/main.go:16","msg":"Hello from zap Logger","name":"John","age":9,"email":"john@gmail.com"}
{"level":"warn","ts":1660252436.0271666,"caller":"random/main.go:24","msg":"something bad is about to happen"}
{"level":"error","ts":1660252436.0275867,"caller":"random/main.go:25","msg":"something bad happened","error":"oh no!","answer":42,"stacktrace":"main.mainnt/home/ayo/dev/demo/random/main.go:25nruntime.mainnt/usr/local/go/src/runtime/proc.go:250"}
{"level":"warn","ts":1660252436.0280342,"caller":"random/main.go:33","msg":"the operation took longer than expected","time_taken_ms":1}

Unlike Zerolog, Zap does not provide a functioning global logger by default, but
you can configure one yourself through its
ReplaceGlobals()
function. Another difference between the two is that Zap
does not support the TRACE log level
at the time of writing, which may be a deal-breaker for some, although you can
try to
add one yourself

In Zap’s favor, it offers much more customization options through the interfaces
in the Zapcore package. You can
learn more about Zap by reading our comprehensive guide here.

3. Logrus

Logrus has historically been the most
popular choice for structured logging in Go. However, it has since been
surpassed in performance by Zap and Zerolog.
Despite this, Logrus continues to offer unique advantages, particularly its API
compatibility with the standard library log package. This compatibility allows
seamless integration, and easy migration from the standard log package to
Logrus, enabling structured and leveled logging in
various formats including JSON.

package main

import (
    "os"

    "github.com/sirupsen/logrus"
)

func main() {
    log := logrus.New()
    log.Out = os.Stdout

    // Log as JSON instead of the default ASCII formatter.
    log.SetFormatter(&logrus.JSONFormatter{})

    log.WithFields(logrus.Fields{
        "player": "haaland",
        "goals":  "40",
    }).Info("Hello from Logrus!")
}

{"goals":"40","level":"info","msg":"Hello from Logrus!","player":"haaland","time":"2023-03-15T16:47:49+01:00"}

Currently, Logrus is in maintenance mode, implying that no new features will be
added to the library. However, it will continue to receive updates focused on
security, bug fixes, and performance improvements wherever feasible.

As you can see, several structured logging solutions are already available in
the Go ecosystem. However, this wide range of APIs can make it difficult to
support logging in a provider-agnostic manner, often necessitating the use of
abstractions to avoid coupling the logging implementation to a specific package.

The new slog package also addresses this issue by providing a common «frontend»
interface in the standard library through its Logger type, while these various
third-party options provide the «backend» by implementing the Handler
interface. See here for an example that
uses a slog frontend with a Zap backend, potentially providing the best of both
worlds.

Final thoughts

We hope this post has provided you with an understanding of the structured
logging package in Go, and how you can start using it in your projects. If you
want to explore this topic further, I recommend checking out the
full proposal here
and the package documentation here.

Thanks for reading, and happy logging!

Next article

→

Логирование программ Golang

Журнал пакетов стандартной библиотеки предоставляет базовую инфраструктуру для управления логами на языке GO. Основная цель ведения логов — отследить, что происходит в программе, где это происходит и когда это происходит. Логи могут обеспечивать отслеживание кода, профилирование и аналитику. Ведение журнала логирования( глаза и уши программиста) — это способ найти эти ошибки и узнать больше о том, как работает программа.

Для работы с журналом логов мы должны импортировать модуль Log:

import (
	"log"
)

В самом простом случае модуль Log формирует сообщения и отправляет их на стандартную проверку ошибок, как показано в следующем примере:

// Program in GO language to demonstrates how to use base log package.
package main
import (
	"log"		
)
func init(){
	log.SetPrefix("LOG: ")
	log.SetFlags(log.Ldate | log.Lmicroseconds | log.Llongfile)
	log.Println("init started")
}
func main() {
// Println writes to the standard logger.
	log.Println("main started")

// Fatalln is Println() followed by a call to os.Exit(1)
	log.Fatalln("fatal message")

// Panicln is Println() followed by a call to panic()
	log.Panicln("panic message")
}

После выполнения этого кода вывод будет выглядеть так:

LOG: 2017/06/25 14:49:41.989813 C:/golang/example38.go:11: init started
LOG: 2017/06/25 14:49:41.990813 C:/golang/example38.go:15: main started
LOG: 2017/06/25 14:49:41.990813 C:/golang/example38.go:18: fatal message
exit status 1

Стандартная запись логов содержит следующую информцию:
- префикс (log.SetPrefix("LOG: "))
- отметка даты и времени (log.Ldate)
- полный путь к файлу исходного кода записи в лог (log.Llongfile)
- строка кода

Эта часть информации автоматически генерируется для нас, информация о том, когда произошло событие, и информация о том, где оно произошло.

Println — это стандартный способ записи сообщений журнала.
Fatalln - библиотека выводит сообщение об ошибке, а затем вызывает os.Exit(1), заставляя программу завершить работу.
Panic — это встроенная функция, которая останавливает обычный поток управления и начинает паниковать. Когда функция F вызывает panic, выполнение F останавливается, все отложенные вызовы в F выполняются нормально, затем F возвращает управление вызывающей функции. Для вызывающей функции вызов F ведёт себя как вызов panic. Процесс продолжается вверх по стеку, пока все функции в текущей го-процедуре не завершат выполнение, после чего аварийно останавливается программа. Паника может быть вызвана прямым вызовом panic, а также вследствие ошибок времени выполнения, таких как доступ вне границ массива.

Программа на языке GO с реальным примером ведения журнала логов.
Теперь приведем пример из реального мира и реализуем вышеуказанный пакет log в своей программе.  Проверим, нормально ли работает SMTP-соединение. Для тестового примера я собираюсь подключиться к несуществующему SMTP-серверу smtp.smail.com, поэтому программа завершится с сообщением ошибки.

// Program in GO language with real world example of logging.
package main

import (
"log"
"net/smtp"
)
func init(){
	log.SetPrefix("TRACE: ")
	log.SetFlags(log.Ldate | log.Lmicroseconds | log.Llongfile)
	log.Println("init started")
}
func main() {
// Connect to the remote SMTP server.
client, err := smtp.Dial("smtp.smail.com:25")
	if err != nil {	
		log.Fatalln(err)
	}
client.Data()
}

Вывод:

TRACE: 2017/06/25 14:54:42.662011 C:/golang/example39.go:9: init started
TRACE: 2017/06/25 14:55:03.685213 C:/golang/example39.go:15: dial tcp 23.27.98.252:25: connectex: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
exit status 1

еще пример:

package main

import (
    "log"
    "os"
)

var (
    WarningLogger *log.Logger
    InfoLogger    *log.Logger
    ErrorLogger   *log.Logger
)

func init() {
    file, err := os.OpenFile("logs.txt", os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0666)
    if err != nil {
        log.Fatal(err)
    }

    InfoLogger = log.New(file, "INFO: ", log.Ldate|log.Ltime|log.Lshortfile)
    WarningLogger = log.New(file, "WARNING: ", log.Ldate|log.Ltime|log.Lshortfile)
    ErrorLogger = log.New(file, "ERROR: ", log.Ldate|log.Ltime|log.Lshortfile)
}

func main() {
    InfoLogger.Println("Starting the application...")
    InfoLogger.Println("Something noteworthy happened")
    WarningLogger.Println("There is something you should know about")
    ErrorLogger.Println("Something went wrong")
}

Просмотры: 1 740