Nginx日志分析(一)---shell预处理

在这篇文章里,先介绍了Nginx的日志格式。然后结合使用shell命令中的awk、grep、uniq等命令对日志作了简单解析。最后是一个分析自己网站的日志实例,并发现了一些之前没注意到的安全问题。

1. 当我们在谈Web数据挖掘的时候,我们在谈什么

目前数据挖掘、机器学习等都是当前极其火的领域。在我们的日常生活中,Web数据挖掘就有非常广泛的应用。例如,电商根据我们的购买行为来精确投放广告。网易云音乐根据我们的听歌历史推荐我们可能想听的歌单。网站根据用户的访问频度、访问行为识别垃圾流量甚至是非法攻击等等。简而言之,我们可以通过用户的访问行为来描述用户的画像,再根据我们的业务需求做出相应的工作。
要进行Web数据挖掘,首先得要有数据吧。数据来自哪里?最基础的,就是apache、nginx等web服务器提供的访问日志文件。在这些日志文件里通常会记录了来源ip、访问时间、访问路径等信息。当然,以文件形式保存的原始数据可能不便于我们进行数据分析。通常我们会把这个访问日志文件进行切割,并存放在数据库中,以使用各种分析工具、挖掘算法。不过这些都是后话了,首先我们需要认识和处理这些日志文件。
因为能拿到的日志资源有限,所以在这里我暂时先用自己网站的博客的日志来练手。看看平时访问我博客的用户都有怎样的特点~我的网站使用的是lnmp(Linux Nginx Mysql Php)框架,所以这里处理分析的也就是Nginx的log文件。

2. Nginx日志格式

Nginx的配置文件在nginx.conf里面
我的博客使用lnmp一键安装包搭建,配置文件的路径为

1
/usr/local/nginx/conf

Nginx里每个虚拟server的log定义在conf文件的access_log字段里。
这里有官方文档以及Nginx中文文档关于httplog格式的说明

2.1 log_format

这里定义log日志文件的格式,默认情况下有一个名为combined的格式

1
2
3
Syntax: 	log_format name [escape=default|json] string ...;
Default: log_format combined "...";
Context: http

combined的格式定义是这样的

1
2
3
log_format combined '$remote_addr - $remote_user [$time_local] '
'"$request" $status $body_bytes_sent '
'"$http_referer" "$http_user_agent"';

log_format可以包含公共变量和只在日志写入时存在的变量。
你可以在Alphabetical index of variablesModule ngx_http_log_module中找到这些变量的说明。
以这么一条访问记录为例

1
60.191.38.77 - - [07/Aug/2017:22:09:36 +0800] "GET / HTTP/1.1" 200 2781 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:47.0) Gecko/20100101 Firefox/47.0"

默认情况下的参数及说明如下:

参数 说明 示例
$remote_addr 客户端地址 60.191.38.77
$remote_user Basic授权的客户端用户名 -
$time_local 通用日志格式下的本地时间 07/Aug/2017:22:09:36 +0800
$request 完整的原始请求行,包括:请求方法、请求路径、遵循协议 GET / HTTP/1.1
$status 响应状态 200
$body_bytes_sent 发送给客户端的字节数,单位为Byte 2781
$http_referer url跳转来源 -
$http_user_agent 用户身份标识(如浏览终端等等) Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:47.0) Gecko/20100101 Firefox/47.0

备注:

  • 上述字段中,如果值不存在,则用’-‘表示。
  • time_local中的+0800表示的是比格林威治时间要晚8个小时,即北京时间。

2.2 Access_log

1
2
3
4
5

Syntax: access_log path [format [buffer=size] [gzip[=level]] [flush=time] [if=condition]];
access_log off;
Default: access_log logs/access.log combined;
Context: http, server, location, if in location, limit_except

使用方式就是

1
access_log    要保存的log的路径    log的格式

通过上面的配置,Nginx应该就能正常地记录日志了。

3. 用shell分析Access.log

通过几个Shell命令以及管道|的应用,我们可以快速地对日志文件作一些简易分析。这里主要用到的Shell命令包括

1
2
3
4
5
6
cat:    用以打印文件内容
grep: 用正则表达式匹配内容
awk: 一种处理文本文件的语言
uniq: 删除重复行
sort: 将文本文件内容加以排序
wc: 统计文档中的行数、字符数、单词数、字节数

以上的命令的具体使用,都可以通过man 命令来查看。例如我不懂uniq的用法,就可以使用man uniq来查看uniq的用法。

  • 统计总访问记录数
    1
    wc -l access.log

access.log里面,每一行就是一条记录,所以这里统计整个access.log的行数,就是总的访问记录数了。这里没有忽略掉重复行,因为可能会有一秒内有多个相同的请求,我这里希望也能统计下来。

1
2
3
qiu/Users/qiu $ grep -n '18/Jul/2017:18:06:53' access.log                                                                                                                                                                                                      16:26:32
87219:207.46.13.20 - - [18/Jul/2017:18:06:53 +0800] "GET /robots.txt HTTP/1.1" 404 162 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)"
87220:207.46.13.20 - - [18/Jul/2017:18:06:53 +0800] "GET /robots.txt HTTP/1.1" 404 162 "-" "Mozilla/5.0 (compatible; bingbot/2.0; +http://www.bing.com/bingbot.htm)"

3.1 执行解释

  • 统计某一天内访问次数最多的前10个页面
    1
    grep '28/Jul' access.log|awk '{print $7}'|sort|uniq -c|sort -nr|head -n 10

在这里,你可以把管道命令一个个添加看我们做了些什么。

1
grep '28/Jul' access.log

通过grep先把包含’28/Jul’的行提取出来。
例如提取出来的结果是:

1
2
3
4
5
6
173.244.48.178 - - [28/Jul/2017:21:45:37 +0800] "HEAD http://1.2.3.4:80/phpmyAdmin/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
173.244.48.178 - - [28/Jul/2017:21:45:38 +0800] "HEAD http://1.2.3.4:80/phpmyadmin2/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
173.244.48.178 - - [28/Jul/2017:21:45:38 +0800] "HEAD http://1.2.3.4:80/phpmyadmin3/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
104.34.199.41 - - [28/Jul/2017:21:50:41 +0800] "HEAD http://1.2.3.4:80/pma2015/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
104.34.199.41 - - [28/Jul/2017:21:51:00 +0800] "HEAD http://1.2.3.4:80/pma2015/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
104.34.199.41 - - [28/Jul/2017:21:50:41 +0800] "HEAD http://1.2.3.4:80/pma2016/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"

(这么简单地看了一下, 就发现有很多暴力扫描后台的访问了。。。)

把处理出来的结果发给awk去处理。awk来顺序扫描这些行,并通过分隔符来分隔成一个个。这里我没有指定分割符,则默认通过空格来分隔。分隔出来的每一个域,用$+数字表示。$1表示第一个域、$2表示第二个域等等。这里的$7就是访问的路径。
以一条数据比较完整的访问记录为例

1
60.191.38.77 - - [07/Aug/2017:22:09:36 +0800] "GET / HTTP/1.1" 200 2781 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:47.0) Gecko/20100101 Firefox/47.0"

默认按空格分割之后

1
2
3
4
5
6
7
8
9
10
11
12
13
14
$1 = 60.192.38.77
$2 = -
$3 = -
$4 = [07/Aug/2017:22:09:36
$5 = +0800]
$6 = "GET
$7 = /
$8 = HTTP/1.1"
$9 = 200
$10 = 2781
$11 = "-"
$12 = "Mozilla/5.0
$13 = (Macintosh;
...

在这里我们可以看到,使用默认的分割符来分割时,可能会遇到一点小小的问题。例如会把””里面的空格和分割了。如上述例子中,就会把user_agent也给切分开了。如果只是想粗略查看时,可以就只按默认的分割符来分割。或者也可以指定通过awk -F\"来指定让"成为分割符。在使用 awk 命令行快速分析 accesslog访问日志里面,提供了更多使用awk的方法。
使用sort把结果排序

1
2
3
4
5
6
http://1.2.3.4:80/phpmyAdmin/
http://1.2.3.4:80/phpmyadmin2/
http://1.2.3.4:80/phpmyadmin3/
http://1.2.3.4:80/pma2015/
http://1.2.3.4:80/pma2015/
http://1.2.3.4:80/pma2016/

uniq -c统计各行出现的次数,相邻重复行会累加到一起

1
2
3
4
5
1 http://1.2.3.4:80/phpmyAdmin/
1 http://1.2.3.4:80/phpmyadmin2/
1 http://1.2.3.4:80/phpmyadmin3/
2 http://1.2.3.4:80/pma2015/
1 http://1.2.3.4:80/pma2016

sort -nr把各行按出现次数从大到小排序

1
2
3
4
5
2 http://1.2.3.4:80/pma2015/
1 http://1.2.3.4:80/pma2016/
1 http://1.2.3.4:80/phpmyadmin3/
1 http://1.2.3.4:80/phpmyadmin2/
1 http://1.2.3.4:80/phpmyAdmin/

head -n 10展示前10个。这个数字可以自己定义

3.2 实例分析

  • 按日期查看每天的访问数量
    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    cat access.log|awk '{print substr($4,2,11)}'|uniq -c

    7 22/Jun/2017
    1752 23/Jun/2017
    20317 24/Jun/2017
    9014 25/Jun/2017
    3406 26/Jun/2017
    513 27/Jun/2017
    2052 28/Jun/2017
    1830 29/Jun/2017
    ...

发现24/Jun/2017这一天的访问次数莫名地很高,我们来查看这天的日志看看都发生了什么。

  • 统计某一天访问ip频次的前20位
    1
    2
    3
    4
    5
    6
    7
    8
    9
    grep '23/Jul' access.log|awk '{print $1}'|sort|uniq -c|sort -nr|head -n 20

    821 93.56.61.232
    609 59.100.217.106
    541 79.3.133.195
    456 91.192.190.33
    456 88.215.26.179
    456 83.98.141.143
    ...

这样我们可以找到有哪些访问异常高的ip,这些人居然丧心病狂地访问了几百次我的网站。
看看他们在干什么!

  • 查看特定ip在特定日期下的访问行为
1
2
3
4
5
6
7
8
9
10
11
12
13
cat access.log|grep '24/Jun'|grep 93.56.61.232

93.56.61.232 - - [24/Jun/2017:08:19:28 +0800] "HEAD http://1.2.3.4:80/mysql/admin/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:28 +0800] "HEAD http://1.2.3.4:80/mysql/dbadmin/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:28 +0800] "HEAD http://1.2.3.4:80/mysql/sqlmanager/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:28 +0800] "HEAD http://1.2.3.4:80/mysql/mysqlmanager/ HTTP/1.1" 404 0 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:29 +0800] "HEAD http://1.2.3.4:80/phpmyadmin/ HTTP/1.1" 200 0 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:29 +0800] "GET http://1.2.3.4:80/phpmyadmin/ HTTP/1.0" 200 14600 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:30 +0800] "GET /phpmyadmin/index.php?pma_username=popa3d&pma_password= HTTP/1.1" 200 14791 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:30 +0800] "GET /phpmyadmin/index.php?lang=en-utf-8& HTTP/1.1" 499 0 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:30 +0800] "GET /phpmyadmin/index.php?pma_username=popa3d&pma_password=popa3d HTTP/1.1" 200 15011 "-" "Mozilla/5.0 Jorgee"
93.56.61.232 - - [24/Jun/2017:08:19:31 +0800] "GET /phpmyadmin/index.php?lang=en-utf-8& HTTP/1.1" 499 0 "-" "Mozilla/5.0 Jorgee"
...

至此,我们就可以发现,这个ip一直在尝试暴力我的后台,而且也有些请求成功的记录。这对于刚刚接触vps的我的来说,确实是一个警示。况且,那时候由于贪图方便数据库使用的是弱密码。幸好没有那时候也没有什么特别重要的数据。

4. awk分割字符串忽略双引号空格

这段为可选段落,如果你没有遇到的话可以跳过。
上面在使用awk解析access.log的时候,nginx的日志格式不单纯的只有空格,而且还有双引号。之所以会有双引号,是因为这些字段里面也会有空格。
当我们使用awk默认的分割符解析时,这些字段也会被分割开,有时候,我们并不希望这些字段被解开。
例如:

1
60.191.38.77 - - [07/Aug/2017:22:09:36 +0800] "GET / HTTP/1.1" 200 2781 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10.11; rv:47.0) Gecko/20100101 Firefox/47.0"

我们希望可以直接用$5代表”GET / HTTP/1.1”,但是又不希望用"作为分割符,因为这样我们就不能用$1表示ip了。通过google发现,这种需求确实真不少。像
google讨论
stack overflow:wk consider double quoted string as one token and ignore space in between
[How to make awk ignore the field delimiter inside double quotes?] (https://stackoverflow.com/questions/29642102/how-to-make-awk-ignore-the-field-delimiter-inside-double-quotes)
如果一定要用awk去解析的话,需要用到awk的一个内置变量FPAT
gwak manual里有这么一个例子
有一个csv是这样子的

1
Robbins,Arnold,"1234 A Pretty Street, NE",MyTown,MyState,12345-6789,USA

如果直接使用-F,来定义逗号为分割符,那么"1234 A Pretty Street, NE"也会被分割开为"1234 A Pretty StreetNE"。但是我们希望直接用$3来表示1234 A Pretty Street, NE
我们吧FPAT这个变量定义为一个正则表达式

1
FPAT = "([^,]+)|(\"[^\"]+\")"

然后在awk的语句块里添加

1
2
3
BEGIN {
FPAT = "([^,]+)|(\"[^\"]+\")"
}

stackoverflow里的这个答案解释了这个正则表达式。在这里作一个简单的翻译。
匹配一个包含逗号的非空字符串

1
[^,]+

匹配一个被""包围的字符串,并且双引号内至少包含一个字符,且这个字符不是"

1
"[^"]+"

把两个条件联合起来并且对特殊字符做转义,就变成了

1
"([^,]+)|(\"[^\"]+\")"

Robbinss是能符合一个pattern的最长字符串。
然后遇到,不能匹配任何一个pattern。
然后遇到Arnold,能匹配一个的pattern。
然后遇到,不能匹配任何一个pattern。
然后遇到"""能匹配第二个pattern。
如果是我们平时使用的这个表达式,应该会重新和[^,]+去比较。但是这里好像会尽量长地匹配给定的FPAT,即遇到"的时候,第一个([^,]+)子模式失败时,不会马上停止,而会继续匹配第二个子模式("[^"]+")。所以整个1234 A Pretty Street, NE会作为一个filed。
对于我们的日志分析的例子,把上面给出的FPAT中的,改为空格就好了。
例如

1
cat access.log|head -n 20|awk 'BEGIN {FPAT="([^ ]+)|(\"[^\"]+\")"} {print $6}'

得出的结果就是

1
"GET / HTTP/1.1"

这就作为一个整体而可以用$6直接访问了。

5. 总结

  1. 通过shell命令可以直接在命令行对Nginx的日志作一些简单分析,例如查看一些异常流量之类的。但是这种方式并不是非常地直观、解析起来也有点麻烦。
  2. 使用awk去解析文本时,需要去了解一下awk的语法。另外FPAT这个内置变量需要awk版本在4.x才可以。我一开始的时候把日志下载到MAC上面分析时,发现结果和linux上操作的结果不同。后来才发现和awk的版本有关。关于awk的版本可以使用awk -V来查看。
  3. 后面考虑对日志文件里的数据进行挖掘以及可视化。Python在数据挖掘方面有很多做的不错的库。所以考虑用Python来读取和处理文件,以方便做更深入的工作。
  4. 一定要加强安全意识。当我们的服务器放在网络上时,就面临着各种各样的攻击。不要随意暴露服务器的ip。当我们使用一键安装脚本的时候,不说要自己实现,但最起码要留个心,注意这个脚步装了什么,配置了什么。有些容易被猜到的路径一定要修改,像各种web的管理界面啊。如果你不加更改,又使用了弱密码,网站就很容易被攻破了。

参考资料

  1. 服务器日志法网站分析的原理及优缺点
  2. Web攻击日志分析的过去现在与未来
  3. 使用 awk 命令行快速分析 accesslog访问日志
  4. Nginx攻击日志分析
  5. linux下使用awk,wc,sort,uniq,grep对nginx日志进行分析和统计
  6. Nginx 日志分析及性能排查
  7. awk FPAT variable: Working