Nginx 訪问日志增长暴增出现尖刀的具体分析

前言:

         Nginx日志里面Mobileweb_access.log增长特别大。一天上百兆。将近100W的訪问记录。依照我们眼下的规模,热点用户才500个左右。就算人人用手机app訪问,怎么可能会有这么大的url訪问量?曾经仅仅是安装使用nginx。还没有抽空细致研究。这回须要彻底的去分析nginx日志了。

 

1。日志分类

主要2种,一种是错误日志。一种是訪问日志,这些配置都在/usr/local/nginx/conf/nginx.conf里面。默认都是打开的。自己也能够选择关闭。

 

1.1,訪问日志

訪问日志主要记录每个訪问nginx的请求。格式能够自定义。在nginx.conf文件里面,通过訪问日志,你能够看到每个请求的具体信息。对于訪问日志的格式,主要是配置文件里的log_format来限制的。


1.1.1 log_format日志格式

$request_time:整个请求的总时间。

$time_iso8601:訪问的时间与时区。比方18/Jul/2012:17:00:01 +0800,时间信息最后的"+0800"表示server所处时区位于UTC之后的8小时。

$upstream_response_time:请求过程中,upstream的响应时间。

$request_method:client请求的动作,通常为GETPOST

$request_uri:是浏览器发过来的值。该值是rewrite后的值。

比如做了internal redirects后。

$args:这个变量等于请求行中(GET请求)的參数,比如foo=123&bar=blahblah;

$query_string:与$args相同。

$proxy_add_x_forwarded_for:变量包括client请求头中的"X-Forwarded-For",与$remote_addr用逗号分开。假设没有"X-Forwarded-For" 请求头,则$proxy_add_x_forwarded_for等于$remote_addr

$upstream_addrupstream的地址,即真正提供服务的主机地址。

$status:记录请求返回的http状态码,比方成功是200

$http_user_agent:client浏览器信息

$http_range

$sent_http_content_length:发送内容的长度

$body_bytes_sent:发送给client的文件主体内容的大小,比方899。能够将日志每条记录中的这个值累加起来以粗略预计server吞吐量。

$http_referer:记录从哪个页面链接訪问过来的。

$host:请求主机头字段,否则为server名称。

$http_x_forwarded_for:client的真实ip。通常webserver放在反向代理的后面。这样就不能获取到客户的IP地址了。通过$remote_add拿到的IP地址是反向代理server的iP地址。反向代理server在转发请求的http头信息中,能够添加x_forwarded_for信息,用以记录原有client的IP地址和原来client的请求的server地址。

$http_user_agent:client浏览器信息

$body_bytes_sent:发送给client的文件主体内容的大小,比方899,能够将日志每条记录中的这个值累加起来以粗略预计server吞吐量。


$ssl_protocolSSL协议版本号,比方TLSv1

$ssl_cipher:交换数据中的算法,比方RC4-SHA


生产环境上的范例:

log_format  main  '$proxy_add_x_forwarded_for  $remote_user [$time_local] "$request" '

                      '$status $body_bytes_sent "$http_referer" '

                      '"$http_user_agent" "$http_x_forwarded_for" '

                      'upsteam: $upstream_addr';

    access_log  logs/access.log  main;

    log_not_found off;


1.1.2,訪问日志路径

access_log  logs/access.log  main;

Nginx支持为每个location指定强大的日志记录。相同的连接能够在同一时间输出到不止一个的日志中。

假设想关闭日志,能够例如以下:

access_log off;

能够使用access_log指令的字段包括:httpserverlocation

PSNginx进程设置的用户和组必须对日志路径有创建文件的权限,否则,会报错。



1.2,错误日志

错误日志主要记录client訪问Nginx出错时的日志,格式不支持自定义。通过错误日志,你能够得到系统某个服务或server的性能瓶颈等。

因此,将日志好好利用,你能够得到非常多有价值的信息。错误日志由指令error_log来指定,具体格式例如以下:

error_log path(存放路径) level(日志等级)

        path含义同access_loglevel表示日志等级,具体例如以下:

        [ debug | info | notice | warn | error | crit ]

    从左至右,日志具体程度逐级递减,即debug最具体,crit最少,举例说明例如以下:

        error_log  logs/mobileweb_error.log error;

    须要注意的是:error_log off并不能关闭错误日志,而是会将错误日志记录到一个文件名称为off的文件里。正确的关闭错误日志记录功能的方法例如以下:

        error_log /dev/null;

    上面表示将存储日志的路径设置为“垃圾桶”。

 

2,为每个project定义特定的日志

location ~* ^/mobileWeb/.*$ {

           client_max_body_size 5m;

           include deny.conf;

           proxy_pass http://mobilewebbackend;

           include proxy.conf;

           error_log  logs/mobileweb_error.log error;

           access_log  logs/mobileweb_access.log  main;

           include gzip.conf;

}

这样。就会在日志路径/usr/local/nginx/logs/以下生成mobileWebproject的专门日志mobileweb_error.log 以及mobileweb_access.log 日志,假设想查询mobileWebproject的訪问记录,就能够单独去查看这2个日志。

 

3,開始分析

依据来源ip进行分组统计分析,看看哪个ip的訪问量最多

[root@wgq_idc_web_1_21 tmp]# cat mobileweb_access.log |grep "14/Oct/2014" |awk '{print $1}'|sort -nr |uniq -c |sort -nr |more

705980 1xx.xx.xx.185,

190273 6x.1x4.1xx.35,

14900 1xx.xxx.xx.xx3,

14670 1xx.xxx.x3.8x,

结果发现,这几个ip都是我们公司广场公用的wifi出口ip地址,属于安全地址,不是私人的IP地址。非常大程度上排除了从外部恶意攻击我们站点的可能性。接下来就须要重点分析,为什么会有这么多的URL记录。

 

细致排查来源为1xx.xx.xx.185的日志记录。发现有非常多$http_user_agent为空的记录,大概90%的记录都是如此,看记录例如以下:

1xx.xx.xx.185, 10.2xx.xx1.xx0 - [10/Oct/2014:10:52:11 +0800] "POST /mobileWeb/square/queryCounts.htm?

HTTP/1.1" 200 82 "-" "-" "1xx.xx.xx.185"upsteam: 110.xx7.1.22:7100

 

推測是否不是手机app訪问的记录?仅仅有自己停掉wifi,用手机的4G网络,去登录我们的移动app应用,操作完,点击了几下赞。訪问了一些页面。操作时间2分钟。然后使用自己的移动4Gip地址“2xx.10x.5.129”去检索下nginx下的mobileweb的记录,4nginx记录。每一台40个左右url訪问,4台就是160个记录,以下是一台的记录

[root@wgq_idc_web_1_22 logs]# more mobileweb_access.log |grep "2xx.10x.5.129"

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:01 +0800] "POST /mobileWeb/userMobileCenter/queryUserNameAndIconByIds.htm? HTTP/1.1" 200 20 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:37 +0800] "POST /mobileWeb/square/queryCounts.htm?

HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:42 +0800] "POST /mobileWeb/square/query.htm? HTTP/1.1" 200 9485 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:42 +0800] "POST /mobileWeb/square/query.htm?

HTTP/1.1" 200 9485 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:49 +0800] "POST /mobileWeb/square/clickSupport.htm? HTTP/1.1" 200 46 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:51 +0800] "POST /mobileWeb/square/clickSupport.htm? HTTP/1.1" 200 46 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:54 +0800] "POST /mobileWeb/square/clickSupport.htm?

HTTP/1.1" 200 46 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:55 +0800] "POST /mobileWeb/square/query.htm? HTTP/1.1" 200 4831 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:54:57 +0800] "POST /mobileWeb/userMobileCenter/queryUserNameAndIconByIds.htm?

HTTP/1.1" 200 20 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:03 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm? HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:04 +0800] "POST /mobileWeb/version/queryVersion.htm? HTTP/1.1" 200 160 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:06 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm?

HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:06 +0800] "POST /mobileWeb/mobile/loadCart.htm?

HTTP/1.1" 200 940 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:07 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm? HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:07 +0800] "POST /mobileWeb/square/queryCounts.htm? HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:07 +0800] "POST /mobileWeb/userMobileCenter/findAllinterfaceVersion.htm? HTTP/1.1" 200 411 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:13 +0800] "POST /mobileWeb/userMobileCenter/unReadNumsMobile.htm?

HTTP/1.1" 200 239 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:56 +0800] "POST /mobileWeb/userMobileCenter/queryUserNameAndIconByIds.htm? HTTP/1.1" 200 20 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:57 +0800] "POST /mobileWeb/userMobileCenter/findAllinterfaceVersion.htm? HTTP/1.1" 200 411 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:58 +0800] "POST /mobileWeb/userMobileCenter/unReadNumsMobile.htm?

HTTP/1.1" 200 239 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:58 +0800] "POST /mobileWeb/version/queryVersion.htm? HTTP/1.1" 200 160 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:55:59 +0800] "POST /mobileWeb/userMobileCenter/unReadNumsMobile.htm? HTTP/1.1" 200 239 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:00 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm?

HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:06 +0800] "POST /mobileWeb/userMobileCenter/findAllinterfaceVersion.htm?

HTTP/1.1" 200 411 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:07 +0800] "POST /mobileWeb/userMobileCenter/unReadNumsMobile.htm?

HTTP/1.1" 200 239 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:07 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm? HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:08 +0800] "POST /mobileWeb/version/queryVersion.htm? HTTP/1.1" 200 160 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:08 +0800] "POST /mobileWeb/userMobileCenter/unReadNumsMobile.htm? HTTP/1.1" 200 239 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:08 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm? HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:16 +0800] "POST /mobileWeb/userMobileCenter/queryUserNameAndIconByIds.htm? HTTP/1.1" 200 20 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:19 +0800] "POST /mobileWeb/userMobileCenter/findAllinterfaceVersion.htm?

HTTP/1.1" 200 411 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:21 +0800] "POST /mobileWeb/userMobileCenter/unReadNumsMobile.htm? HTTP/1.1" 200 239 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:21 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm? HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:23 +0800] "POST /mobileWeb/userMobileCenter/queryUserNameAndIconByIds.htm? HTTP/1.1" 200 20 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:23 +0800] "POST /mobileWeb/userMobileCenter/findAllinterfaceVersion.htm?

HTTP/1.1" 200 411 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:24 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm? HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:24 +0800] "POST /mobileWeb/userMobileCenter/queryAdvertisement.htm? HTTP/1.1" 200 5175 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:24 +0800] "POST /mobileWeb/version/queryVersion.htm? HTTP/1.1" 200 160 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:25 +0800] "POST /mobileWeb/userMobileCenter/unReadNumsMobile.htm?

HTTP/1.1" 200 239 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:56:25 +0800] "POST /mobileWeb/mobile/getCartItemNum.htm? HTTP/1.1" 200 114 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:14:57:37 +0800] "POST /mobileWeb/square/queryCounts.htm? HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:00:37 +0800] "POST /mobileWeb/square/queryCounts.htm?

HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:02:07 +0800] "POST /mobileWeb/userMobileCenter/messageListMobile.htm?

HTTP/1.1" 200 106 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:02:08 +0800] "POST /mobileWeb/square/queryCounts.htm? HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:02:37 +0800] "POST /mobileWeb/square/queryCounts.htm? HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:05:07 +0800] "POST /mobileWeb/square/queryCounts.htm?

HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:05:08 +0800] "POST /mobileWeb/push/query.htm? HTTP/1.1" 200 97 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:05:37 +0800] "POST /mobileWeb/square/queryCounts.htm?

HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.21:7100

2xx.10x.5.129, 10.2xx.xx1.xx0 - [16/Oct/2014:15:11:44 +0800] "POST /mobileWeb/square/queryCounts.htm?

HTTP/1.1" 200 82 "-" "-" "2xx.10x.5.129"upsteam: 110.xx7.1.22:7100

[root@wgq_idc_web_1_22 logs]#

 

看到了我的訪问url记录,当中$http_user_agent差点儿都是为”-”空记录,奇怪,我也是用手机訪问的,询问andriod开发者。他说有些低版本号的手机在记录$http_user_agent后退回去会报错返回空界面,所以后来就不记录$http_user_agent信息了。

原来如此,并且看到这么多
url全是我訪问过的,移动mobileweb后台开发者说,移动app一个页面里面有很多url须要载入,所以你訪问1个页面就会载入Nlink连接去取各种数据值。

分析道这里,已经差点儿相同明了:就是一个登录用户訪问页面,会载入NN>10)个link连接url,这些url都被记录在nginx訪问日志里面。短短2分钟内。我訪问了一些页面,就有160个左右的记录,照这么算下来,一个小时就是5000个左右的记录,一天平均25分钟分钟。500个用户个就是SELECT 5000*25/60*500=1041667,差点儿相同100W左右了。通常来说nginx日志的量比較大是正常的。

 

           当中。半夜1点到6点左右,这个公司广场wifiip地址还会不停的訪问mobileweb,经过分析是由于登录了移动app应用,可是睡觉了没有退出应用,手机也没有关系,所以导致移动app依旧不停的在訪问mobile应用(由于1分钟左右会刷新一次去获取訪问当前登录用户的站内互动消息)。

 

      从此能够看出nginx的訪问日志记录了用户的全部訪问行为记录。并且具体到每个页面里内嵌的url记录,假设用适当的工具细致分析nginx日志。就会大概摸清楚用户的訪问习惯。这些数据对于市场部门、产品部门来说,是非常有价值的。


----------------------------------------------------------------------------------------------------------------

<版权全部,文章同意转载,但必须以链接方式注明源地址,否则追究法律责任!>
原博客地址: http://blog.itpub.net/26230597/viewspace-1305133/

原作者:黄杉 (mchdba)

----------------------------------------------------------------------------------------------------------------

原文地址:https://www.cnblogs.com/bhlsheji/p/5182053.html