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请求流量为通用日志格式。此功能通过在InfluxDB配置文件的[http]部分将log-enabled选项设置为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所示。
