从应用日志中提取监控metrics

孔飞@快猫星云 2022年11月4日

mtail 是谷歌开源的一款从应用日志中提取 metrics 的工具。categraf 将 mtail 作为一个插件集成了进来,并且兼容 mtail 的语法,简化了部署。原本 mtail 和日志文件之间是一对一的关系,即一般都是一个 mtail 进程处理一类日志,但是对于很高配的物理机,上面会部署很多不同的服务,每个服务进程都对应一个 mtail,此时机器上会出现特别多的 mtail 进程,较难维护。把 mtail 集成到 categraf 之后,复用 categraf 的多实例插件机制,可以做到一台机器上只有一个 categraf 进程即可读取解析多个服务的日志。示例图如下:

Mtail

下面来看如何使用这个插件从日志中提取metrics。

插件简介

插件启动

编辑mtail.toml文件, 注意每个instance 需要指定不同的progs参数(不同的progs文件或者目录)

输入

logs参数指定要处理的日志源, 支持模糊匹配, 支持多个log文件。

处理规则

progs指定具体的规则文件目录(或文件)

处理规则与语法

处理流程

for line in lines:
  for regex in regexes:
    if match:
      do something

语法

exported variable 

pattern { 
  action statements
} 

def decorator { 
  pattern and action statements
}

定义指标名称

前面也提过,指标仅支持 counter gauge histogram 三种类型。举一个🌰

counter lines
/INFO.*/ {
    lines++
}

注意,定义的名称只支持 C类型的命名方式(字母/数字/下划线),如果想使用"-" 要使用"as"导出别名。例如,

counter lines_total as "line-count"

这样获取到的就是line-count这个指标名称了

匹配与计算(pattern/action)

PATTERN {
ACTION
}

// examples:

/foo/ {
  ACTION1
}

variable > 0 {
  ACTION2
}

/foo/ && variable > 0 {
  ACTION3
}

支持RE2正则匹配

const PREFIX /^\w+\W+\d+ /

PREFIX {
  ACTION1
}

PREFIX + /foo/ {
  ACTION2
}

这样,ACTION1 是匹配以小写字符+大写字符+数字+空格的行,ACTION2 是匹配小写字符+大写字符+数字+空格+foo开头的行。

关系运算符

  • < 小于 <= 小于等于
  • > 大于 >= 大于等于
  • == 相等 != 不等
  • =~ 匹配(模糊) !~ 不匹配(模糊)
  • || 逻辑或 && 逻辑与 ! 逻辑非

数学运算符

  • | 按位或
  • & 按位与
  • ^ 按位异或
  • + - * / 四则运算
  • << 按位左移
  • >> 按位右移
  • ** 指数运算
  • = 赋值
  • ++ 自增运算
  • -- 自减运算
  • += 加且赋值

支持else与otherwise

/foo/ {
ACTION1
} else {
ACTION2
}

支持嵌套

/foo/ {
  /foo1/ {
     ACTION1
  }
  /foo2/ {
     ACTION2
  }
  otherwise {
     ACTION3
  }
}

支持命名与非命名提取

/(?P<operation>\S+) (\S+) \[\S+\] (\S+) \(\S*\) \S+ (?P<bytes>\d+)/ {
  bytes_total[$operation][$3] += $bytes
}

增加常量label

# test.mtail
# 定义常量label env
hidden text env
# 给label 赋值 这样定义是global范围;
# 局部添加,则在对应的condition中添加
env="production"
counter line_total by logfile,env
/^(?P<date>\w+\s+\d+\s+\d+:\d+:\d+)/ {
    line_total[getfilename()][env]++
}

获取到的metrics中会添加上env=production的label 如下:

# metrics
line_total{env="production",logfile="/path/to/xxxx.log",prog="test.mtail"} 4 1661165941788

如果要给metrics增加变量label,必须要使用命名提取。例如

# 日志内容
192.168.0.1 GET /foo
192.168.0.2 GET /bar
192.168.0.1 POST /bar
# test.mtail
counter my_http_requests_total by log_file, verb 
/^/ +
/(?P<host>[0-9A-Za-z\.:-]+) / +
/(?P<verb>[A-Z]+) / +
/(?P<URI>\S+).*/ +
/$/ {
    my_http_requests_total[getfilename()][$verb]++
}
# metrics
my_http_requests_total{logfile="xxx.log",verb="GET",prog="test.mtail"} 4242
my_http_requests_total{logfile="xxx.log",verb="POST",prog="test.mtail"} 42

命名提取的变量可以在条件中使用

/(?P<x>\d+)/ && $x > 1 {
nonzero_positives++
}

时间处理

不显示处理,则默认使用系统时间

默认emit_metric_timestamp=“false”(注意是字符串)

http_latency_bucket{prog="histo.mtail",le="1"} 0
http_latency_bucket{prog="histo.mtail",le="2"} 0
http_latency_bucket{prog="histo.mtail",le="4"} 0
http_latency_bucket{prog="histo.mtail",le="8"} 0
http_latency_bucket{prog="histo.mtail",le="+Inf"} 0
http_latency_sum{prog="histo.mtail"} 0
http_latency_count{prog="histo.mtail"} 0

参数 emit_metric_timestamp=“true”(注意是字符串)

http_latency_bucket{prog="histo.mtail",le="1"} 1 1661152917471
http_latency_bucket{prog="histo.mtail",le="2"} 2 1661152917471
http_latency_bucket{prog="histo.mtail",le="4"} 2 1661152917471
http_latency_bucket{prog="histo.mtail",le="8"} 2 1661152917471
http_latency_bucket{prog="histo.mtail",le="+Inf"} 2 1661152917471
http_latency_sum{prog="histo.mtail"} 3 1661152917471
http_latency_count{prog="histo.mtail"} 4 1661152917471

使用日志的时间

Aug 22 15:28:32 GET /api/v1/pods latency=2s code=200
Aug 22 15:28:32 GET /api/v1/pods latency=1s code=200
Aug 22 15:28:32 GET /api/v1/pods latency=0s code=200
histogram http_latency buckets 1, 2, 4, 8
/^(?P<date>\w+\s+\d+\s+\d+:\d+:\d+)/ {
        strptime($date, "Jan 02 15:04:05")
	/latency=(?P<latency>\d+)/ {
		http_latency=$latency
	}
}

日志提取的时间,一定要注意时区问题,有一个参数 override_timezone 可以控制时区选择,否则默认使用UTC转换。 比如我启动时指定 override_timezone=Asia/Shanghai, 这个时候日志提取的时间会当做东八区时间 转换为timestamp, 然后再从timestamp转换为各时区时间时 就没有问题了,如图:

timestamp

如果不带 override_timezone=Asia/Shanghai, 则默认将Aug 22 15:34:32 当做UTC时间,转换为timestamp。 这样再转换为本地时间时,会多了8个小时, 如图:

timestamp

其他日志处理方案

本文介绍的日志处理方案相对简单,就像一把瑞士军刀,小巧锋利,如果你已经把日志都收集到 ElasticSearch 中了,想对 ElasticSearch 中的日志做告警,这就需要另一个方案了,请参考《ElasticSearch日志告警

关于作者

本文作者孔飞,快猫星云工程师,文章内容是快猫技术团队共同沉淀的结晶。我们会持续输出监控、稳定性保障相关的技术文章,文章可转载,转载请注明出处,尊重技术人员的成果。