InfluxDB 1.5.0 日志改进
作者：Stuart Carnie / 产品, 开发者, 公司
2018 年 3 月 6 日
导航至
在解决问题时，日志文件是非常有价值的资产。如果出现问题，您几乎总是会被要求“发送日志”。 InfluxDB 1.5 对日志记录进行了一些改进，以简化分析此数据的任务。
日志记录
InfluxDB 生成大量日志输出，记录其内部操作的许多方面。最新的更新改进了数据库记录关键信息的方式以及日志输出的格式。这些更改的主要目标是启用可以有效解析和分析日志数据的工具，并减少诊断问题所需的时间。
结构化日志记录
InfluxDB 1.5 可以生成 logfmt 或 JSON lines 格式的结构化日志。此功能位于配置文件的新部分，标题为 [logging]。默认日志格式为 auto，它根据 stderr 是否引用终端 (TTY) 来确定输出。如果 stderr 是 TTY，则选择不太详细的“控制台”格式；否则，输出将为 logfmt。如果您希望获得一致的输出，我们建议您显式地将格式设置为 logfmt。
当可以轻松提取日志事件的特定元素时，结构化日志记录的价值会大大提高。考虑到这一点，我们审查了现有的日志记录代码，以确保将重要的数据移动到单独的键中。以下示例显示了版本 1.3 中与打开文件相关的一些启动事件。请注意，某些条目在消息中包含路径和持续时间
[I] 2018-03-03T00:46:48Z /Users/stuartcarnie/.influxdb/data/db/autogen/510/000000001-000000001.tsm (#0) opened in 280.401827ms engine=tsm1 service=filestore
[I] 2018-03-03T00:46:48Z reading file /Users/stuartcarnie/.influxdb/wal/db/autogen/510/_00001.wal, size 15276 engine=tsm1 service=cacheloader
[I] 2018-03-03T00:46:54Z /Users/stuartcarnie/.influxdb/data/db/autogen/510 opened in 5.709152422s service=store从 1.5 开始，使用 logfmt 的相同事件现在看起来像这样
ts=2018-03-03T00:48:57.246371Z lvl=info msg="Opened file" log_id=06bLAgTG000 engine=tsm1 service=filestore path=/Users/stuartcarnie/.influxdb/data/db/autogen/510/000000001-000000001.tsm id=0 duration=61.736ms
ts=2018-03-03T00:48:57.246590Z lvl=info msg="Reading file" log_id=06bLAgTG000 engine=tsm1 service=cacheloader path=/Users/stuartcarnie/.influxdb/wal/db/autogen/510/_00001.wal size=15276
ts=2018-03-03T00:49:01.023313Z lvl=info msg="Opened shard" log_id=06bLAgTG000 service=store trace_id=06bLAgv0000 op_name=tsdb_open path=/Users/stuartcarnie/.influxdb/data/db/autogen/510 duration=3841.275ms请注意，path 和 duration 现在是单独的键。使用像 lcut 这样的工具，我们可以选择特定的键（ts、msg、path 和 duration）来重新格式化输出
2018-03-03T00:48:57.246371Z Opened file /Users/stuartcarnie/.influxdb/data/db/autogen/510/000000001-000000001.tsm 61.736ms
2018-03-03T00:48:57.246590Z Reading file /Users/stuartcarnie/.influxdb/wal/db/autogen/510/_00001.wal
2018-03-03T00:49:01.023313Z Opened shard /Users/stuartcarnie/.influxdb/data/db/autogen/510 3841.275ms整理日志事件
在 InfluxDB 进程的生命周期内，压缩等操作会持续运行，并在推进过程中生成多个事件。更复杂的是，当这些操作并发运行时，来自每个操作的事件将交织在一起。确定特定压缩的结果实际上是不可能的，因为无法独立地关联每个压缩的日志事件。为了解决这个问题，InfluxDB 1.5 添加了下表列出的键
| 键 | 注释 |
trace_id |
与单个操作运行的每个日志事件关联的唯一值 |
op_name |
可搜索的标识符，例如 tsm1.compact_group，分配给每种操作类型 |
op_event |
给定 start 或 end 值，指示这是操作的第一个还是最后一个事件 |
op_elapsed |
操作完成所花费的时间，以毫秒为单位。此键始终包含在 op_event=end 日志事件中 |
为了演示如何使用这些键，我们将使用以下（删节的）名为“influxd.log”的文件，该文件至少包含两个并发运行的压缩。
msg="TSM compaction (start)" trace_id=06avQESl000 op_name=tsm1_compact_group op_event=start
msg="Beginning compaction" trace_id=06avQESl000 op_name=tsm1_compact_group tsm1_files_n=2
msg="Compacting file" trace_id=06avQESl000 op_name=tsm1_compact_group tsm1_index=0 tsm1_file=/influxdb/data/db1/rp/10/000000859-000000002.tsm
msg="Compacting file" trace_id=06avQESl000 op_name=tsm1_compact_group tsm1_index=1 tsm1_file=/influxdb/data/db1/rp/10/000000861-000000001.tsm
msg="TSM compaction (start)" trace_id=06avQEZW000 op_name=tsm1_compact_group op_event=start
msg="Beginning compaction" trace_id=06avQEZW000 op_name=tsm1_compact_group tsm1_files_n=2
msg="invalid subscription token" service=subscriber
msg="Post http://kapacitor-rw:9092/write?consistency=&db=_internal&precision=ns&rp=monitor: dial tcp: lookup kapacitor-rw on 10.0.0.1: server misbehaving" service=subscriber
msg="Compacting file" trace_id=06avQEZW000 op_name=tsm1_compact_group tsm1_index=0 tsm1_file=/influxdb/data/db2/rp/12/000000027-000000002.tsm
msg="Compacting file" trace_id=06avQEZW000 op_name=tsm1_compact_group tsm1_index=1 tsm1_file=/influxdb/data/db2/rp/12/000000029-000000001.tsm
msg="Compacted file" trace_id=06avQEZW000 op_name=tsm1_compact_group tsm1_index=0 tsm1_file=/influxdb/data/db2/rp/12/000000029-000000002.tsm.tmp
msg="Finished compacting files" trace_id=06avQEZW000 op_name=tsm1_compact_group tsm1_files_n=1
msg="TSM compaction (end)" trace_id=06avQEZW000 op_name=tsm1_compact_group op_event=end op_elapsed=56.907ms
msg="Compacted file" trace_id=06avQESl000 op_name=tsm1_compact_group tsm1_index=0 tsm1_file=/influxdb/data/db1/rp/10/000000861-000000002.tsm.tmp
msg="Finished compacting files" trace_id=06avQESl000 op_name=tsm1_compact_group tsm1_files_n=1
msg="TSM compaction (end)" trace_id=06avQESl000 op_name=tsm1_compact_group op_event=end op_elapsed=157.739ms压缩由 op_name=tsm1_compact_group 标识，因此为了总结它们，我们可以使用以下命令输出跟踪 ID 和经过的时间
$ fgrep 'tsm1_compact_group' influxd.log | fgrep 'op_event=end' | lcut trace_id op_elapsed可以理解为
查找包含文本tsm1_compact_group和op_event=end的所有行，并显示trace_id和op_elapsed键
将生成以下输出
06avQEZW000 56.907ms
06avQESl000 157.739ms从这里，可以轻松地使用以下命令过滤跟踪 06avQESl000 的日志
$ fgrep '06avQESl000' influxd.log | lcut msg tsm1_file
TSM compaction (start)
Beginning compaction
Compacting file /influxdb/data/db1/rp/10/000000859-000000002.tsm
Compacting file /influxdb/data/db1/rp/10/000000861-000000001.tsm
Compacted file /influxdb/data/db1/rp/10/000000861-000000002.tsm.tmp
Finished compacting files
TSM compaction (end)我们可以提出更复杂的问题，例如
最慢的 10 个连续查询是什么？
使用类似以下的命令
$ fgrep 'continuous_querier_execute' influxd.log | fgrep 'op_event=end' | lcut trace_id op_elapsed | sort -r -h -k2 | head -10
06eXrSJG000 15007.940ms
06d7Ow3W000 15007.646ms
06axkRVG000 15007.222ms
06ay9170000 15007.118ms
06c9tbwG000 15006.701ms
06dUcXhG000 15006.533ms
06ekMi40000 15006.158ms
06c5FH7l000 15006.145ms
06bDHhkG000 15006.012ms
06a~ioYG000 15005.988ms总而言之，结构化日志记录将使我们能够使用现成的工具更有效地分析日志数据。
HTTP 访问日志
长期以来，InfluxDB 一直支持以 通用日志格式 输出 HTTP 请求流量。通过将 log-enabled 选项设置为 InfluxDB 配置的 [http] 部分中的 true 来启用此功能。
在 1.5 之前，所有日志输出都发送到 stderr，并且看起来像下面这样
[I] 2018-03-02T19:59:58Z compacted level 1 4 files into 1 files in 130.832391ms engine=tsm1
[I] 2018-03-02T20:00:09Z SELECT count(v0) FROM db.autogen.m0 WHERE time >= '2018-02-27T01:00:00Z' AND time < '2018-02-27T02:00:00Z' GROUP BY * service=query
[httpd] ::1 - - [02/Mar/2018:13:00:09 -0700] "GET /query?db=db&q=select+count%28v0%29+from+m0+where+time+%3E%3D+%272018-02-27T01%3A00%3A00Z%27+and+time+%3C+%272018-02-27T02%3A00%3A00Z%27+group+by+%2A HTTP/1.1" 200 0 "-" "curl/7.54.0" 4f39378e-1e54-11e8-8001-000000000000 726
[I] 2018-03-02T20:00:57Z retention policy shard deletion check commencing service=retention混合日志事件流需要额外的工作来分离它们，然后我们才能开始任何分析。最新版本添加了一个额外的配置选项，用于将访问日志写入单独的文件。例如，以下配置会将访问日志写入位于 /var/log/influxd/access.log 的文件中
[http]
# ...
log-enabled = true
access-log-path = "/var/log/influxd/access.log"
# ...当访问日志写入文件时，会剥离 [http] 前缀，以便标准 HTTP 日志分析和监控工具可以解析该文件，而无需进一步处理。例如，使用 lnav，管理员可以打开一个活动的日志文件，并使用多种不同的可视化方式显示数据，包括错误率和直方图，如下面的 asciinema 所示。
