python日志实时分析

python随着人工智能的发展，越来越火热。但其实python在运维测试方面，也是一把利器。 最近就碰到了个需求，就顺手写了个python程序。用惯了go，不过发现python好像更简单点 😃
涉及到的主要python包和系统命令：

1. datetime #用于处理时间
2. subprocess #用于调用命令行工具
3. tail -f logFile #获取logFile新增内容

废话不多说，下面说一下场景需求和具体解决方案。

1. [场景需求]

最近参与了一个区块链项目，在项目测试过程中，通过日志发现出块不稳定，为了定位问题，需要精确的统计出块时间。截取一段日志如下：

I[2019-07-11|16:57:24.139][45712] reapMaxBytesMaxGas                           module=mempool mempoolTxNum=0 reapTxNum=0 maxNumPerBlock=2000
I[2019-07-11|16:57:24.220][45712] [60]---------- BeginBlock[4367] ----------   module=main
I[2019-07-11|16:57:24.224][45712] Executed block                               module=state height=4367 validTxs=0 invalidTxs=0
D[2019-07-11|16:57:24.307][45712] Commit synced                                module=main commit=436F6D6D697449447B5B333520342031383720363120343120313336203137312031203137302032343120323220313230203836203233382031333120313634203231302031323420313530203233322036203434203130342033322036302031303220343120323530203131352031323720313138203134355D3A313130467D
I[2019-07-11|16:57:24.307][45712] BlockHeight<4367>, BeginBlock<0ms>, DeliverTx<0ms>, EndBlock<0ms>, Commit<82ms>, Tx<0> module=main
I[2019-07-11|16:57:24.307][45712] BlockHeight<4367>, Abci<82ms>, Tx<0>, fullfilled<0>, pending<0>, canceled<0>, expired<0>, partialfilled<0> module=main
I[2019-07-11|16:57:24.307][45712] Committed state                              module=state height=4367 txs=0 appHash=2304BB3D2988AB01AAF1167856EE83A4D27C96E8062C68203C6629FA737F7691
I[2019-07-11|16:57:25.208][45712] reapMaxBytesMaxGas                           module=mempool mempoolTxNum=0 reapTxNum=0 maxNumPerBlock=2000
I[2019-07-11|16:57:25.284][45712] [60]---------- BeginBlock[4368] ----------   module=main

2. [日志分析]

日志中Committed state代表状态持久化，也就是区块生命周期的末尾。 因此我们使用Committed state来对日志进行过滤，并用最新一条日志的时间戳减去上条日志时间戳作为本区块出块时间。

3. [代码]

#!/usr/bin/python
#encoding=utf-8
#Filename: block_time.py

import subprocess
from datetime import datetime
import time

logFile = "./blockchain.log"
lastDateTime = datetime.now()

#主程序
def monitorLog(logFile):
   print("monitor logFile: %s" % logFile)
   stopTime = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(time.time()+100)) #脚本100秒后退出
   popen = subprocess.Popen(["tail", "-f", logFile], stdout=subprocess.PIPE, stderr=subprocess.PIPE) #启动子进程执行tail命令
   while True:
      line = popen.stdout.readline().strip() #按行获取日志
      if line:
         if 'Committed state' in line:
            getBlockInterval(line)  #分析日志
      now = time.strftime("%Y-%m-%d %H:%M:%S", time.localtime(time.time())) #当前时间
      if now >= stopTime: #如果当前时间超过stopTime，表示不再分析日志，退出程序
           popen.kill()
           print("kill subprocess")
           break

#计算连续两条日志的时间差
def getBlockInterval(line): 
   t = getDateTime(line)
   global lastDateTime
   blockInterval = (t-lastDateTime).total_seconds() #将datetime时间差用seconds计算
   blockHeight = getBlockHeight(line)

   lastDateTime = t
   print('%s, interval=%s' % (blockHeight, blockInterval)) #打印结果

#获取区块高度
def getBlockHeight(line): 
   return line.split('module')[1].split(' ')[1]

#获取每行日志的时间戳
def getDateTime(line): 
   line = line.split('[')[1][:-1].split('.')[0].replace('|', ' ')
   t = datetime.strptime(line, "%Y-%m-%d %H:%M:%S")
   return t

if __name__ == '__main__':
   monitorLog(logFile)

4. [日志分析结果]

height=4343, interval=1.0
height=4344, interval=1.0
height=4345, interval=1.0
height=4346, interval=1.0
height=4347, interval=1.0
height=4348, interval=1.0
height=4349, interval=2.0
height=4350, interval=1.0
height=4351, interval=1.0