实时诊断日志记录，如何监视 Go Web 应用

日志记录对于任何野蛮生长的应用必不可少。通常，我们会回顾性的查阅日志以了解过去，但在某些情况下，实时访问有关特定用户操作的详细流程是识别问题的最佳(有时是唯一)方法。让我们看看如何使用 Go 及 Slog 包实现这种日志记录功能。

当用户开始抱怨应用中的特定功能不起作用时，该怎么办？首先，你可能会评估症状并验证用户是否存在意料之外的行为。然后，你可以检查你的错误跟踪服务（这里没什么可看的）、正常运行时间和重要指标（一切正常）。最后，任何潜在有用信息的最后一个来源都隐藏在日志中的某个地方。但是，默认生产日志级别为“INFO”（对吗？），因此，尽管可能存在一些警告和错误，但这些日志不太可能包含有关问题的足够信息。下一步该怎么做？

在这篇文章中，我想探讨不同的选项，包括如何临时启用详细（通常是选择性）日志记录以进行故障排除，以及如何使这些类型的日志能够随时随地实时轻松访问。这种日志记录有时称为诊断日志记录。

在本文中，我们将探讨一些不同的策略，用于将诊断日志记录引入由 slog 包支持的 Go 应用程序，并涵盖该过程中的以下主题：

更新全局日志级别 (无论是否重启)
Slog 是大道，大道至简
多 handler Slogging
提高性能的方法

更新全局日志级别 (无论是否重启)

让我们从一些简单明了且适用于任何应用程序的东西开始，而不仅仅是那些用 Go 编写的应用程序。

你可以暂时将应用程序日志级别更新为“DEBUG”并重新启动它。现在，你已经记录了大量日志，并且（我希望）有一个不错的日志收集和查看服务（即不是普通文件）来搜索相关事件。问题解决了，牛逼。

对吗? 但是，如果您不能仅仅为了调试而重新启动应用程序怎么办? 这正是 AnyCable 或任何其他服务于数千个持久连接的应用程序（例如，在线活动平台）的情况。在这种情况下，重新启动服务器将需要重新初始化所有活动客户端（重新建立连接并恢复状态）。从用户体验的角度来看，这并不好，从服务器的角度来看也不好，而且大规模的重新连接（也称为连接雪崩）可能会导致严重的负载峰值。

因此，重新启动服务器不是一种选择。因此我们更改日志记录设置的唯一方法是向应用程序添加一些自定义逻辑。所以，让我们开始写一些 Go。

Slog 是大道，大道至简

让我们注意 slog 包的两个主要概念：

slog.Logger 是日志记录入口点，是调用 Info() 、 Debug() 等函数的结构。
slog.Handler 是一个接口，负责处理日志条目（或记录）并执行对日志记录设备的写入、级别过滤、格式化等。

下面是一个使用的基本示例：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13


package main

import "log/slog"

func main() {
	opts := &slog.HandlerOptions{
		Level: slog.LevelInfo,
	}
	logger := slog.New(
		slog.NewTextHandler(os.Stdout, opts),
	)
	// ...
}

请注意，日志记录级别是 handler 的特征，而不是 logger 实例的特征。没有 logger.SetLogLevel(lvl) 函数或任何类似的机制（如在许多日志记录库中）来更改日志级别。那么，我们如何动态地更改日志级别呢？

有很多解决方法，但我更喜欢的一种如下：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23


package main

import "log/slog"

var LOG_LEVEL = new(slog.LevelVar)

func main() {
	LOG_LEVEL.Set(slog.LevelInfo)

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

	// ...
}

// SetLogLevel updates the application log level
func SetLogLevel(lvl slog.Level) {
	LOG_LEVEL.Set(lvl)
}

在这里，我们使用特殊 slog.LevelVar 变量作为当前日志记录级别的容器。现在，如果我们想在不中断应用程序的情况下更改日志记录级别，我们可以调用该 SetLogLevel 函数。为了演示，我们可以设置一个 SIGQUIT 信号处理程序来在“DEBUG”和“INFO”之间切换日志值（您可以在此 this gist 找到一个完整的工作示例）。

如果我们能够轻松访问日志，并且能够满足不断大海捞针的需要，那么这种方法就足够好了，因为在全局范围内启用详细日志记录会产生大量日志。

我们在开发故障排除日志功能时考虑了两个用例：

为用户提供轻松的日志访问。
通过后台管理 UI 访问日志。

在这两种情况下，都无法对日志的收集方式做出任何假设。因此，我们需要一种独立于基础设施的方式来按需流式传输详细日志。因此，我们开始寻找同时将日志写入多个输出的方法。

让我们看看如何使用 slog 实现多输出日志记录。

多 handler Slogging

我们可以使用扇出模式构建一个多输出记录器。让我们看一个例子：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56


package main

import "log/slog"

type MultiHandler struct {
	left slog.Handler
	right slog.Handler
}

func (t *MultiHandler) Enabled(ctx context.Context, level slog.Level) bool {
	return left.Enabled() || right.Enabled()
}

func (t *MultiHandler) Handle(ctx context.Context, r slog.Record) (err error) {
	if t.left.Enabled(ctx, r.Level) {
		err = t.left.Handle(ctx, r)
	}

	if t.right.Enabled(ctx, r.Level) {
		err = t.right.Handle(ctx, r)
	}

	return
}

func (t *MultiHandler) WithAttrs(attrs []slog.Attr) slog.Handler {
	return &MultiHandler{t.left.WithAttrs(attrs), t.right.WithAttrs(attrs)}
}

func (t *MultiHandler) WithGroup(name string) slog.Handler {
	return &MultiHandler{t.left.WithGroup(name), t.right.WithGroup(name)}
}

func main() {
	jsonHandler := slog.NewJSONHandler(
		os.Stdout,
		&slog.HandlerOptions{
			Level: slog.LevelInfo,
		},
	)

	textErrorHandler := slog.NewTextHandler(
		os.Stderr,
		&slog.HandlerOptions{
			Level: slog.LevelError,
		},
	)

	logger := slog.New(
		&MultiHandler{
			jsonHandler,
			textErrorHandler,
		},
	)
	// ...
}

我们的 MultiHandler 必须实现以下 slog.Handler 接口：该 Enabled() 函数是记录器用来决定处理程序是否要处理此条目的保护; 如果是，则生成 slog.Record 结构并将其传递给 Handle() 函数。

WithAttrs() and WithGroup() 函数用于创建附加了给定上下文的处理程序的副本。

现在，我们只需要创建一个自定义处理程序，即 spy handler ，当且仅当至少有一个用户请求日志时，它将使用所有日志。由于诊断日志记录可以在生产和高峰时段使用，因此存在与性能相关的重要注意事项：

将 spy handler 附加到记录器时，当它处于非活动状态时，不得产生明显的性能开销（即，它不应该向用户发送消息）
一旦激活， spy handler 不得导致性能下降。
spy handler 必须是非阻塞的（可以跳过一些消息来实现这一点）。

让我们分享一下我们为获得令人满意的效果而采取的步骤！

提高性能的方法

非阻塞的要求，意味着在单独的 Go 协程中处理日志条目，并使用通道作为传输。我们还需要跟踪处理程序状态，无论是活动还是非活动。因此，我们提出了这个 spy handler 的初始实现：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37


type SpyHandler struct {
	active bool
	ch     chan *slog.Record
}

func NewSpyHandler(callback func(*slog.Record)) *SpyHandler {
	h := &SpyHandler{
		ch: make(chan *slog.Record, 2048),
	}

	go func() {
		for r := range h.ch {
			callback(r)
		}
	}

	return h
}

func (h *SpyHandler) Enabled(ctx context.Context, level slog.Level) bool {
	return true
}

func (h *SpyHandler) Handle(ctx context.Context, r slog.Record) error {
	if h.active {
		h.enqueueRecord(&r)
	}

	return nil
}

func (h *SpyHandler) enqueueRecord(r *slog.Record) {
	select {
	case h.ch <- r:
	default:
	}
}

上面代码段中的重要部分如下：

该 select { ... default:} 模式的使用避免了可能阻塞通道写入操作（如果通道的缓冲区已满，则默认子句只会删除记录）。

Enabled() 函数中 return true ，我们的处理程序应该消费所有日志，对吧？

在我们继续完善此实现之前，我们最好运行一些性能测试并检查这种方法是否可行。幸运的是，在 Go 中编写性能测试（或基准测试）是一件轻而易举的事：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43


func BenchmarkSpy(b *testing.B) {
	handler := slog.NewTextHandler(os.Stderr, &slog.HandlerOptions{Level: slog.LevelError})
	callback: = func(r *slog.Record) {
		// Immitate some work to ensure that the spy is not blocking the logger
		time.Sleep(10 * time.Millisecond)
	}
	spy := NewSpyHandler(callback)

	configs := []struct {
		spy      *SpyHandler
		active   bool
	}{
		{spy, true},
		{spy, false},
		{nil, false},
	}

	for _, config := range configs {
		desc := "no spy"
		if config.spy != nil {
			desc = "active spy"
			if !config.active {
				desc = "inactive spy"
			}
		}
		b.Run(desc, func(b *testing.B) {
			var logger slog.Logger

			if config.spy != nil {
				config.spy.active = config.active
				logger = slog.New(&MultiHandler{handler, config.spy})
			} else {
				logger := slog.New(handler)
			}

			b.ResetTimer()

			for i := 0; i < b.N; i++ {
				logger.Debug("test", "key", 1, "key2", "value2", "key3", 3.14)
			}
		})
	}
}

我们得到的结果如下：

1
2
3
4


BenchmarkSpy
BenchmarkSpy/active_spy            401.4 ns/op
BenchmarkSpy/inactive_spy          266.0 ns/op
BenchmarkSpy/no_spy                8.142 ns/op

哇！监视调试日志比没有监视慢 40 倍。但这并不奇怪：如果我们将基本处理程序的日志级别设置为“DEBUG”，我们将在“无监视”场景中看到类似（甚至更高）的数字。换句话说，在我们的例子中，附加一个活跃的监视大致等于全局启用详细日志。更有趣的是，即使监视处于非活动状态，我们仍然可以观察到明显的开销：数百纳秒 vs 约十几纳秒。

虽然当有人读取诊断日志时，有一些开销是可以的，但总是有开销是不可接受的。

我决定仔细研究一下 slog 是如何工作的，以便弄清楚这种开销可能来自哪里。下面是由 Info() 、 Debug() 等函数调用的 slog.Logger.log() 函数：

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18


func (l *Logger) log(ctx context.Context, level Level, msg string, args ...any) {
	if !l.Enabled(ctx, level) {
		return
	}
	var pc uintptr
	if !internal.IgnorePC {
		var pcs [1]uintptr
		// skip [runtime.Callers, this function, this function's caller]
		runtime.Callers(3, pcs[:])
		pc = pcs[0]
	}
	r := NewRecord(time.Now(), level, msg, pc)
	r.Add(args...)
	if ctx == nil {
		ctx = context.Background()
	}
	_ = l.Handler().Handle(ctx, r)
}

你可以看到，它做的第一件事是调用 Enabled() 函数，它依赖于与处理程序相同的函数。然后，如果处理程序响应“是，我已启用”，我们将分多个阶段生成日志条目记录。看完这段代码后，我意识到了什么？我知道有两个函数（特别是 Enabled() 和 Handle() ）的存在是有原因的：构建日志记录不是一个免费操作;从性能的角度来看，首先构建记录，然后才检查日志级别（如果我们只有函数 Handle() ）将不是最佳的。

您可能已经意识到我们需要应用的快速修复程序，以避免在非活动状态期间进行间谍开销：

1
2
3
4


 func (h *SpyHandler) Enabled(ctx context.Context, level slog.Level) bool {
-  return true
+  return h.active
 }

而这个变化之后的基准测试结果要好得多：

我们可以看到，开销现在在误差范围内。

当我们将这个概念验证转变为更强大的解决方案时，让我跳过这一部分（通过用原子替换布尔活动字段以实现安全的并发，并在输出中引入缓冲区）。相反，我想谈谈我们在查看 slog 源代码时发现的另一个优化。

嘿，您可以在 GitHub 上找到完整版的 SpyHandler：palkan/slog-spy. 。它是从 AnyCable+ 中提取的，并且是开源的，尽情享受吧！

IgnorePC的故事

你有没有注意到这个内部配置参数， internal.IgnorePC ？它负责将调用方指针附加到日志记录，因此我们可以将该 AddSource: true 选项与内置处理程序一起使用。

在开发中向日志添加源代码行是一个不错的功能，但在生产中不需要。因此，我决定看看禁用此功能是否会带来任何性能提升。为此，我调整了 slog 源代码，将 IgnorePC var 设置为 true，然后再次运行基准测试：

The effect of removing the caller information from the log record turned out to be quite good. I wondered why there wasn’t an option to disable this feature (or why we don’t automatically disable it when the AddSource option is set to false). There was an opportunity for a pull request and a contribution here but… this fairy tale had no happy ending: this situation is already known to the Go team (and actually, there’s a benchmark in the slog package) and they decided not to overoptimize. Maybe, that will change in the future. We’ll see.

现在，您可以使用一些编译器级别的 hacky 来更改项目中的值 IgnorePC ，如下所示：

1
2


//go:linkname IgnorePC log/slog/internal.IgnorePC
var IgnorePC = true

如果你想让日志记录更快，请将这个咒语放在代码中的某个位置。（不过，对于大多数应用程序来说，slog 肯定已经足够快了——投入其中的工作和想法非常出色。

参考

本文翻译于 Realtime diagnostic logging, or how to really spy on your Go web apps