日志分析处理:GoAccess 篇

1,681 阅读7分钟

本文使用「署名 4.0 国际 (CC BY 4.0)」许可协议,欢迎转载、或重新修改使用,但需要注明来源。 署名 4.0 国际 (CC BY 4.0)

本文作者: 苏洋

创建时间: 2020年12月16日 统计字数: 6951字 阅读时间: 14分钟阅读 本文链接: soulteary.com/2020/12/16/…


日志分析处理:GoAccess 篇

这篇文章原计划在 2020 年中智源大会举办完毕之后整理出来,奈何各种事情阻塞,一直拖延至今。恰逢年末跑一些数据,以及计划搭建一些日常辅助业务运营的实时看板,借着机会把内容整理出来。

本篇是第一篇,聊聊怎么使用 GoAccess 进行各种常见场景,进行常规日志行为数据分析。

写在前面

面对几个G、甚至上百 GB 的原始日志,如果我们想进行分析,除了导入 ELK、ClickHouse 、云服务日志 SaaS 系统之外,其实使用轻巧的 GoAccess就可以满足多数基本分析要求。

针对日志进行基础处理

不论使用哪一种工具进行日志分析,在分析前,我们首先要准备合理、正确的数据源。如果你的日志是由 Nginx 、Apache 输出,类似下面这样:

172.22.0.1 - - [15/Dec/2020:06:07:43 +0000] "GET / HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 11_0_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36" "-"

那么可以直接跳到下一节进行实战了解。但是如果你的日志并非单纯由结构化的内容构成,混杂了一些其他的信息,我们则需要进行一些清理,比如在 Nginx 1.19 版本中,我们得到的默认日志输出会是这样:

/docker-entrypoint.sh: /docker-entrypoint.d/ is not empty, will attempt to perform configuration
/docker-entrypoint.sh: Looking for shell scripts in /docker-entrypoint.d/
/docker-entrypoint.sh: Launching /docker-entrypoint.d/10-listen-on-ipv6-by-default.sh
10-listen-on-ipv6-by-default.sh: Getting the checksum of /etc/nginx/conf.d/default.conf
10-listen-on-ipv6-by-default.sh: Enabled listen on IPv6 in /etc/nginx/conf.d/default.conf
/docker-entrypoint.sh: Launching /docker-entrypoint.d/20-envsubst-on-templates.sh
/docker-entrypoint.sh: Configuration complete; ready for start up
172.22.0.1 - - [15/Dec/2020:06:07:43 +0000] "GET / HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 11_0_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36" "-"

可以看到,除了预期内的日志内容外,还有一些意料之外的文本输出内容,这些内容,GoAccess 默认是无法解析的,所以需要进行日志的“简单清洗”,处理掉这些程序不支持的数据。

如果你能够确保日志只有头部有这些信息,并且可以确认出现的内容行数数量,可以使用 tail 命令来“跳过”指定的行数,来确保日志结构一致:

tail -n +8 nginx-example.log

但是如果你无法确保这些“意外”的日志会出现在哪里,出现的次数有多少,则需要使用 grep 进行符合内容的日志的筛选,比如我们要筛选出 2020 年的访问请求:

grep -i /2020: nginx-example.log > nginx-2020.log

有的时候,我们的应用会给原本的访问日志进行一些修改,比如在日志头或尾部添加一些内容,类似下面这样:

ngx-logs_1  | 172.22.0.1 - - [15/Dec/2020:06:07:43 +0000] "GET / HTTP/1.1" 200 612 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 11_0_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36" "-"
ngx-logs_2  | 172.22.0.1 - - [15/Dec/2020:06:07:43 +0000] "GET /favicon.ico HTTP/1.1" 404 555 "http://localhost:8080/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 11_0_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/87.0.4280.88 Safari/537.36" "-"

那么我们首先要使用 cutawk 对原始数据中的不必要数据进行剔除,比如剔除掉每行行首的 ngx-logs_1 |,并对每行内容进行 trim 操作:

cat nginx-example.log | awk '!($1=$2="")' | awk '{$1=$1};1' > nginx-trimed.log

此外,因为一些特殊情况,比如测试,或者日志切分导出时间有重合,我们可能面临数据有重复的情况,也需要使用 uniq 进行数据去重:

cat nginx-example.log | uniq > nginx-uniq.log

基本操作就讲到这里,本篇文章先以个人网站小样本日志(几G)为例,聊聊实际如何处理日志并使用 GoAccess 进行分析。

处理 Nginx 访问日志

我的网站是运行在 Nginx 容器中的静态站点。在网站简要说明中有提到,在 2018 年后,我重新在阿里云上搭建了这个网站,两年以来,在更新软件版本的时候,我会执行手动日志导出,因为软件版本不同,以及导出方式不同,所以文件格式会有一些差异,如同上一小节提到的那样,和经历多次架构调整的真实业务场景类似:

# 有来自 compose 的日志
Attaching to soultearycom_www_2, soultearycom_www_1
www_2  | 111.199.191.xxx - - [25/Apr/2020:07:42:24 +0000] "GET /2020/03/08/use-docker-to-build-private-software-repositories-nexus-v3.html?utm_source=tuicool&utm_medium=referral HTTP/1.1" 200 51188 "-" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/81.0.4044.122 Safari/537.36" "111.199.191.xxx"

# 有来自 Traefik 的日志
54.36.148.xxx - - [29/Mar/2020:20:58:17 +0000] "GET /2012/01/19/%E7%BB%A7%E7%BB%AD%E8%BF%9B%E5%8C%96.html HTTP/2.0" 200 4909 "-" "-" 8 "wwwssl@docker" "http://172.19.0.4:80" 2ms

# 还有普通的 Nginx 在反向代理后的日志
114.244.132.xxx - - [29/Aug/2018:14:00:53 +0000] "GET /common.css?v=Whistle&t=20180505-1r HTTP/2.0" 200 166358 "https://soulteary.com/" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_13_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.106 Safari/537.36" 5 "Host-soulteary-com-www-soulteary-com-1" "http://172.19.0.4:80" 12ms

首先对日志类型进行分类,并进行重命名整理:

159M  6 25 19:04 compose-2020.04.25-2020.06.25.log
558M 11  8 14:50 compose-2020.04.25-2020.11.08.log
 87M 12  5 22:49 compose-2020.11.08-2020.12.05.log
170K 12  5 23:43 compose-2020.12.05-2020.12.05.log
1.5M 12  6 14:00 compose-2020.12.05-2020.12.06.log
 23M 12 15 15:29 compose-2020.12.06-2020.12.15.log
520M 12 15 14:57 traefik-2020.03.29-2020.12.15.log
1.7G  9 21 18:11 traefik-2018.08.29-2020.03.29.log
...

然后将相同格式的文件进行合并以及数据去重,以及使用 awk 去掉每行日志中的容器名称,例如:

cat compose-2020.* > compose.2020.04.25-2020.12.15.log
grep -i /2020: compose.2020.04.25-2020.12.15.log | uniq > compose.uniq.2020.04.25-2020.12.15.log
cat compose.uniq.2020.04.25-2020.12.15.log | awk '!($1=$2="")' | awk '{$1=$1};1' > compose.trimed.2020.04.25-2020.12.15.log

接着使用 du 查看文件,发现相比较原始文件,新日志文件确实尺寸小了不少,更小的文件可以减少程序接下来的分析计算时间:

836M	compose.2020.04.25-2020.12.15.log
758M	compose.uniq.2020.04.25-220.12.15.log
688M	compose.trimed.2020.04.25-2020.12.15.log

# 处理过的经过 traefik 访问日志尺寸几乎没有变化,说明重合数据几乎没有
2.3G	traefik.2018.08.29-2020.12.15.log
2.3G	traefik.uniq.2018.08.29-2020.12.15.log

在进行分析之前,还需要进一步对其两种日志数据格式:

# Traefik Format
<remote_IP_address> - <client_user_name_if_available> [<timestamp>] "<request_method> <request_path> <request_protocol>" <origin_server_HTTP_status> <origin_server_content_size> "<request_referrer>" "<request_user_agent>" <number_of_requests_received_since_Traefik_started> "<Traefik_router_name>" "<Traefik_server_URL>" <request_duration_in_ms>ms

# Nginx Format
$http_x_real_ip - $remote_user [$time_local] "$request" $status $body_bytes_sent "$http_referer" "$http_user_agent" "$http_x_forwarded_for"

通过观察可以看到,两种数据格式在 UA 之前的内容完全一致,而 UA 后的数据,我们几乎不需要,所以这里可以再次对日志进行清洗,摘除 UA 字段后的信息,将日志格式完全对齐。

针对 Nginx 格式删除最后一个字段,使用 awk 基础模式即可:

cat compose.trimed.2020.04.25-2020.12.15.log | awk 'NF{NF-=1};1' > nginx.2020.04.25-2020.12.15.log

针对 Traefik 格式需要删除最后四个字段,mac 自带的 awk 需要换成 gawk,并使用指定FPAT,忽略双引号内的分隔符:

cat traefik.uniq.2018.08.29-2020.12.15.log | gawk 'NF{NF-=4};1' FPAT='("[^"]+")|[^[:blank:]]+' > nginx.2018.08.29-2020.12.15.log

处理完毕后,可以看到日志尺寸进一步缩小。

2.3G 12 15 16:27 traefik.uniq.2018.08.29-2020.12.15.log
1.6G 12 15 21:10 nginx.2018.08.29-2020.12.15.log

688M 12 15 16:12 compose.trimed.2020.04.25-2020.12.15.log
640M 12 15 20:35 nginx.2020.04.25-2020.12.15.log

最后使用 grep 对日志进行拆分,合并相同时间段的日志,接下来就可以进行分析了。

cat uniq.logs|grep /2020: >2020.log

278M 12 16 10:15 2018.08.29-2018.12.31.log
857M 12 16 10:16 2019.01.01-2019.12.31.log
1.1G 12 16 10:18 2020.01.01-2020.12.15.log

按月拆分日志

如果需要按月拆分,加速处理、或者做更细节的分析,可以考虑使用下面的方案:

gawk 'BEGIN {
    split("Jan Feb Mar Apr May Jun Jul Aug Sep Oct Nov Dec ", months, " ")
    for (a = 1; a <= 12; a++)
        m[months[a]] = a
}
{
    split($4, array, "[:/]")
    year = array[3]
    month = sprintf("%02d", m[array[2]])

    current = year "-" month
    if (last != current)
        print current
    last = current

    print >> FILENAME "-" year "-" month ".txt"
}' your-accesslog 

使用 GoAccess 分析 Nginx 日志

使用 GoAccess 有几个注意事项,如果不是在容器内使用,尤其是 Mac 用户,需要声明 LANG ,避免程序解析异常,下面是针对 Nginx 日志格式的分析命令参考。(日志格式、时间和日期格式已配置好,直接使用就可以啦):

LANG="en_US.UTF-8" goaccess --no-global-config --log-format='%h - %^ [%d:%t %^] "%m %U %H" %s %b "%R" "%u" %^ "%v" "%^" %Dms' --date-format='%d/%b/%Y' --time-format='%T' --log-file=./2018.08.29-2018.12.31.log --output=./2018.html

顺利的话,你将看到程序在以每秒几万条速度以上进行文件处理。

Parsing... [3,143,104] [69,846/s]

执行完毕,就能够看到报告了。

GoAccess 默认统计部分界面

其他软件/平台日志格式

如果你使用的软件不是文中提到的 Nginx,可以参考官方文档进行日志定义。

给出一个曾经使用过的 SAE 的平台的日志格式:

log-format %v %h ^% %D %^[%d:%t %^] ^% ^% ^% "%m %U %H" %s %b "%R" "%u" %^
# time-format %T
time-format %H:%M:%S
date-format %d/%b/%Y

使用 GoAccess 进行实时分析

GoAccess 除了能够分析静态日志外,还能够支持动态日志,添加几个监听参数后,将输入修改为程序运行中使用的日志,即可获得一个实时更新的报告文件。

LANG="en_US.UTF-8" goaccess --no-global-config --addr=0.0.0.0 --port=7890 --ws-url=0.0.0.0 --real-time-html --log-format='%h - %^ [%d:%t %^] "%m %U %H" %s %b "%R" "%u" %^ "%v" "%^" %Dms' --date-format='%d/%b/%Y' --time-format='%T' --log-file=./access.log --output=./realtime.html

但需要注意的是,GoAccess 本身并不提供 Web Server 相关能力,仅支持 WebSocket Server 功能,其输出的报告文件仅为一个静态文件,如果需要拿他作为实时日志看板,需要在前面添加拥有 Web Server 能力的软件,比如:Nginx、Apache。

最后

暂且写到这里,后续展开聊聊如何处理大文件,以及结合容器搭建轻量的实时访问看板。

--EOF