一款短小精悍的日誌分析工具web_log_analyse

（項目最新進展請見github）

web_log_analyse

This tool aim at trouble shooting and performance optimization based on web logs, it's not a generally said log analyse/statistics solution. It preprocess logs on all web server with a specified period and save the intermediate results into mongodb for finally use(with log_show.py)

日誌分析在平常中故障排查、性能分析方面有着很是重要的做用。該項目的側重點不是一般的PV，UV等展現，而是在指定時間段內提供細粒度（最小分鐘級別）的異常定位和性能分析。

Dependencies

• Python 3.4+
• pymongo-3.7.2+
• MongoDB-server 3.4+

先明確幾個術語：
uri指不包含參數的請求；request_uri指原始的請求，包含參數；args指請求中的參數部分。（參照nginx中的定義）
uri_abs和args_abs是指對uri和args進行抽象處理後的字符串（以便分類），例如：
"/sub/0/100414/4070?channel=ios&version=1.4.5"經抽象處理轉換爲uri_abs: "/sub/*/*/*"，args_abs: "channel=*&version=*"

功能

1. 提供統一的日誌分析入口：經由此入口，可查看站點在全部server上產生的日誌的彙總分析；亦可根據時間段和server兩個維度進行過濾
2. 支持對 request_uri，ip 和 response_code 三大類進行分析；每一類又基於請求數、響應大小、響應時間三個維度進行分析。另外不一樣子項又各有特色
3. request_uri 分析能直觀展現哪類請求數量多、哪類請求耗時多、哪類請求佔流量；另外可展現某一類請求在不一樣時間粒度裏(minute, ten_min, hour, day)各指標隨時間的分佈變化；也能夠針對某一 uri_abs 分析其不一樣 args_abs 各指標的分佈
4. IP 分析將全部請求分爲3種來源(from_cdn/proxy, from_reverse_proxy, from_client_directly)，三種來源各自展現其訪問量前 N 的 IP 地址；而且可展現某一 IP 訪問的各指標隨時間的分佈；也可針對某一 IP 分析其產生的不一樣 uri_abs 各指標的分佈

特色

1. 核心思想: 對request_uri進行抽象歸類，將其中變化的部分以 「*」 表示，這樣留下不變的部分就能表明具體的一類請求。其實是換一種方式看待日誌，從 「以具體的一行日誌文本做爲最小分析單位」 抽象上升到 「以某一功能點，某一接口或某一模塊最爲最小分析單位」
2. 兼容plaintext和json格式的日誌內容
3. 配置方便，不須要寫正則。只要將nginx中定義的log_format複製到config文件中便可
4. 經過4分位數概念以實現對響應時間和響應大小更準確的描述，由於對於日誌中的響應時間，算數平均值的參考意義不大
5. 支持定製抽象規則，可靈活指定請求中的某些部分是否要抽象處理以及該如何抽象處理
6. 高效，本着誰產生的日誌誰處理的思想，日誌分析腳本log_analyse要在web服務器上定時運行（有點相似分佈式），於是log_analyse的高效率低資源也是重中之重。經測試，在筆者的服務器上（磁盤：3*7200rpm RAID5，千兆局域網），處理速度在20000行/s~30000行/s之間

實現思路：

分析腳本（log_analyse.py）部署到各臺web server，並經過crontab設置定時運行。log_analyse.py利用python的re模塊經過正則表達式對日誌進行分析處理，取得uri、args、時間當前、狀態碼、響應大小、響應時間、server name 等信息並進行初步加工而後存儲進MongoDB。查看腳本（log_show.py）做爲入口便可對全部web server的日誌進行分析查看，至於實時性，取決於web server上log_analyse.py腳本的執行頻率。

配置文件

日誌格式決定了代碼中的正則表達式，可根據本身狀況參考config.py中的正則定義進行定製)。項目中預約義的日誌格式對應以下：

LOG_FORMAT = '$remote_addr - [$time_local] "$request" '\
             '$status $body_bytes_sent $request_time "$http_referer" '\
             '"$http_user_agent" - $http_x_forwarded_for'

對於異常日誌的處理

若是想靠空格或雙引號來分割各段的話，主要問題是面對各類不規範的記錄時(緣由不一而足，並且也是樣式繁多)，沒法作到將各類異常都考慮在內，因此項目中採用了re模塊而不是簡單的split()函數。代碼裏對一些「能夠容忍」的異常記錄經過一些判斷邏輯予以處理；對於「沒法容忍」的異常記錄則返回空字符串並將日誌記錄於文件。
其實對於上述的這些不規範的請求，最好的辦法是在nginx中定義日誌格式時，用一個特殊字符做爲分隔符，例如「|」。這樣就不須要re模塊，直接字符串分割就能正確的獲取到各段(性能會好些)。

log_show.py使用說明：

幫助信息

[ljk@demo ~]$ log_show --help
Usage:
  log_show <site_name> [options] request [distribution [<request>]|detail <uri>]
  log_show <site_name> [options] ip [distribution <ip>|detail <ip>]
  log_show <site_name> [options] error [distribution <error_code>|detail <error_code>]

Options:
  -h --help                   Show this screen.
  -f --from <start_time>      Start time. Format: %y%m%d[%H[%M]], %H and %M is optional
  -t --to <end_time>          End time. Format is same as --from
  -l --limit <num>            Number of lines in output, 0 means no limit. [default: 5]
  -s --server <server>        Web server hostname
  -g --group_by <group_by>    Group by every minute, every ten minutes, every hour or every day,
                              valid values: "minute", "ten_min", "hour", "day". [default: hour]

  distribution                Show distribution(about hits,bytes,time,etc) of:
                              all or specific 'request', the specific 'ip', the specific 'error_code' in every period.
                              Period is specific by --group_by
  detail                      Show details of:
                              detail 'args' analyse of the specific 'uri'(if it has args);
                              detail 'uri' analyse of the specific 'ip' or 'error_code'

  Notice: it's best to put 'request_uri', 'uri' and 'ip' in quotation marks.

全部示例都可經過-f，-t，-s參數對起始時間和指定server進行過濾

request子命令：

對指定站點今日已入庫的數據進行分析

[ljk@demo ~]$ log_show api request -l 3
====================
Total_hits:×××05 invalid_hits:581
====================
      hits  percent      time_distribution(s)         bytes_distribution(B)            uri_abs
    430210   43.06%  %50<0.03 %75<0.06 %100<2.82   %50<61 %75<63 %100<155              /api/record/getR
    183367   18.35%  %50<0.03 %75<0.06 %100<1.73   %50<196 %75<221 %100<344            /api/getR/com/*/*/*
    102299   10.24%  %50<0.02 %75<0.05 %100<1.77   %50<3862 %75<3982 %100<4512         /view/*/*/*/*.js
====================
Total_bytes:1.91 GB
====================
     bytes  percent      time_distribution(s)         bytes_distribution(B)            uri_abs
   1.23 GB   64.61%  %50<0.04 %75<0.1 %100<1.96    %50<17296 %75<31054 %100<691666     /api/NewCom/list
 319.05 MB   16.32%  %50<0.02 %75<0.05 %100<1.77   %50<3862 %75<3982 %100<4512         /view/*/*/*/*.js
 167.12 MB    8.55%  %50<0.19 %75<0.55 %100<2.93   %50<3078 %75<3213 %100<11327        /api/getR/com/*/*
====================
Total_time:117048s
====================
 cum. time  percent      time_distribution(s)         bytes_distribution(B)            uri_abs
     38747   33.10%  %50<0.03 %75<0.06 %100<2.82   %50<61 %75<63 %100<155              /api/record/getR
     22092   18.87%  %50<0.03 %75<0.06 %100<1.73   %50<196 %75<221 %100<344            /api/getR/com/*/*/*
     17959   15.34%  %50<0.19 %75<0.55 %100<2.93   %50<3078 %75<3213 %100<11327        /api/getRInfo/com/*/*

經過上例可觀察指定時間內（默認當天0時至當前時間）hits/bytes/time三個維度的排名以及響應時間和響應大小的分佈狀況。例如，看到某個uri_abs只有比較少的hits確產生了比較大的bytes或耗費了較多的time，那麼該uri_abs是否值得關注一下呢。

ip子命令：

顯示基於ip地址的分析結果

[ljk@demo ~]$ log_show.py api ip -l 2
====================
From_cdn/Proxy:              hits  hits(%)       bytes  bytes(%)  time(%)
====================       199870    99.94   570.51 MB    99.99    99.99
          Last_cdn_ip
       xxx.57.xxx.189        1914     0.96   696.18 KB     0.12     0.68
      xxx.206.xxx.154        1741     0.87     1.56 MB     0.27     0.98
      User_ip_via_cdn
       xxx.249.xxx.56         787     0.39   154.82 KB     0.03     0.23
        xxx.60.xxx.86         183     0.09     1.05 MB     0.18     0.13
====================
From_reverse_proxy:          hits  hits(%)       bytes  bytes(%)  time(%)
====================           66     0.03    68.83 KB     0.01     0.01
    User_ip_via_proxy
       xxx.188.xxx.21           2     0.00     1.53 KB     0.00     0.00
          xxx.5.xxx.4           2     0.00    324.00 B     0.00     0.00
====================
From_client_directly:        hits  hits(%)       bytes  bytes(%)  time(%)
====================           64     0.03     8.32 KB     0.00     0.00
          Remote_addr
        192.168.1.202          29     0.01     58.00 B     0.00     0.00
        192.168.1.200          29     0.01     58.00 B     0.00     0.00

IP分析的思想是將請求按來源歸爲三大類：From_cdn/Proxy，From_reverse_proxy，From_client_directly，而後各自分類內按請求次數對IP地址進行排序

distribution 子命令：

1. 對 「全部request」 或 「指定uri/request_uri」 按 「分/十分/時/天」 爲粒度進行聚合統計
2. 對 「指定IP」 按 「分/十分/時/天」 爲粒度進行聚合統計

適用場景：查看request/IP隨時間在各聚合粒度內各項指標的變化狀況，例如針對某個uri發現其請求數（或帶寬）變大，則可經過distribution子命令觀察是某一段時間忽然變大呢，仍是比較平穩的變大

# 示例1: 分析指定request的分佈狀況, 指定按minute進行分組聚合, 默認顯示5行
[ljk@demo ~]$ python log_show.py api request distribution "/view/*/*.json" -g minute                
====================
uri_abs: /view/*/*.json
Total_hits: 17130    Total_bytes: 23.92 MB
====================
    minute        hits  hits(%)       bytes  bytes(%)      time_distribution(s)          bytes_distribution(B)            
201803091654      1543    9.01%     2.15 MB     8.98%  %50<0.03 %75<0.05 %100<1.07   %50<1593 %75<1645 %100<1982        
201803091655      1527    8.91%     2.13 MB     8.88%  %50<0.04 %75<0.05 %100<1.04   %50<1592 %75<1642 %100<2143        
201803091656      1464    8.55%     2.05 MB     8.57%  %50<0.04 %75<0.05 %100<1.03   %50<1592 %75<1642 %100<1952        
201803091657      1551    9.05%     2.15 MB     8.97%  %50<0.03 %75<0.04 %100<0.89   %50<1594 %75<1639 %100<1977        
201803091658      1458    8.51%     2.06 MB     8.61%  %50<0.03 %75<0.04 %100<2.35   %50<1596 %75<1644 %100<2146

經過上例，可展現"/view/*/*.json"在指定時間段內的分佈狀況，包括hits/bytes/time總量以及每一個粒度內個指標相對於總量的佔比；該子命令亦能展現各指標隨時間的「趨勢」。
說明：
minute字段爲指定的聚合（group）粒度，1803091654 表示「18年03月09日16時54分」
可經過-g參數指定聚合的粒度（minute/ten_min/hour/day）
distribution子命令後能夠跟具體的uri/request_uri（顯示該uri/request_uri以指定粒度隨時間的分佈）或不跟uri（顯示全部請求以指定粒度隨時間的分佈）

# 示例2: 分析指定IP產生的請求數/帶寬隨時間分佈狀況, 默認聚合粒度爲hour
[ljk@demo ~]$ python log_show.py api ip -t 180314 distribution "140.206.109.174" -l 0
====================
IP: 140.206.109.174
Total_hits: 10999    Total_bytes: 4.83 MB
====================
      hour        hits  hits(%)       bytes  bytes(%)
2018031306        1273   11.57%   765.40 KB    15.47%
2018031307        2133   19.39%  1004.74 KB    20.31%
2018031308        2211   20.10%     1.00 MB    20.74%
2018031309        2334   21.22%     1.05 MB    21.72%
2018031310        2421   22.01%   850.79 KB    17.20%
2018031311         627    5.70%   226.30 KB     4.57%

說明：
hour字段表示默認的聚合粒度，18031306表示「18年03月13日06時」
-l 0 表示不限制輸出行數（即輸出全部結果）

detail 子命令：

1. 對某一uri進行詳細分析，查看其不一樣參數（args）的各項指標分佈
2. 對某一IP進行詳細分析，查看其產生的請求在不一樣uri_abs間的分佈情

適用場景：好比定位到某一類型的uri_abs在某方面（hits/bytes/time）有異常，就能夠經過detail子命令對該類uri_abs進行更近一步的分析，精肯定位到是哪一種參數（args_abs）致使的異常；或者觀察到某個IP訪問異常，能夠再深刻一下該IP是泛泛的訪問呢，仍是隻對某些uri感興趣。

# 示例1:
[ljk@demo ~]$ python log_show.py api -f 180201 request detail "/recommend/update" -l 3
====================
uri_abs: /recommend/batchUpdate
Total_hits: 10069    Total_bytes: 7.62 MB
====================
    hits  hits(%)      bytes  bytes(%)  time(%)      time_distribution(s)          bytes_distribution(B)      args_abs
    4568   45.37%    3.46 MB    45.44%   47.96%  %50<0.06 %75<0.07 %100<0.47   %50<795 %75<845 %100<1484      uid=*&category_id=*&channel=*&version=*
    4333   43.03%    3.25 MB    42.64%   42.30%  %50<0.05 %75<0.07 %100<0.48   %50<791 %75<840 %100<1447      category_id=*&channel=*&uid=*&version=*
     389    3.86%  314.15 KB     4.03%    0.88%  %50<0.03 %75<0.04 %100<0.06   %50<802 %75<850 %100<1203      category_id=*&channel=*&version=*

經過上例可觀察到"/recommend/update"這個uri所對應的不一樣參數各個指標的狀況。另外還有一個附帶的發現：開發在書寫參數時相同的參數組合沒有按同一個順序書寫，雖不影響功能，但在精準的進行應用性能監控的時候會形成必定困擾。
說明：
detail子命令後跟隨uri（不含參數，含參數的話將忽略參數）

# 示例2: 觀察某個IP分別產生了多少種請求, 每種請求的(hits/bytes/time)指標
[ljk@demo ~]$ python log_show.py m -t 180314 ip detail "1.2.3.4"
====================
IP: 140.206.109.174
Total_hits: 10999    Total_bytes: 4.83 MB
====================
    hits  hits(%)      bytes  bytes(%)  time(%)  uri_abs
   10536   95.79%  405.47 KB     8.19%   92.01%  /introduction/watch
     147    1.34%    1.90 MB    39.31%    1.93%  /view/*/*.html
     138    1.25%  407.42 KB     8.23%    2.41%  /chapinfo/*/*.html
      42    0.38%  644.88 KB    13.03%    1.38%  /info/*.html
      30    0.27%  229.98 KB     4.65%    1.14%  /classify/*.json

log_analyse.py部署說明：

該腳本的設計目標是將其放到web server的的計劃任務裏，定時（例如每30分鐘或10分鐘，自定義）執行，在須要時經過log_show.py進行分析便可。

*/15 * * * * export LANG=zh_CN.UTF-8;python3 /home/ljk/log_analyse.py &> /tmp/log_analyse.log

Note

1. 其中uri_abs和args_abs是對uri和args進行抽象化（抽象出特定的請求模式，即將請求分類看待）處理以後的結果，默認規則以下
   uri：將request_uri以"/"和"."分割爲幾段，若某一段所有由數字組成則將其抽象爲一個"*"  
   args：將全部的value替換成"*"  
2. common/common.py中還有一些其餘有趣的函數