使用Redis记录日志

Published on 2017 - 06 - 07

在构建应用程序和服务的过程中,对正在运行的系统的相关信息的挖掘能力将变得越来越重要:无论是通过挖掘信息来诊断系统问题,还是发现系统中潜在的问题,甚至是挖掘与用户有关的信息——这些都需要用到日志。

在Linux和Unix的世界中,有两种常见的记录日志的方法。第一种是将日志记录到文件里面,然后随着时间流逝不断地将一个又一个日志行添加到文件里面,并在一段时间之后创建新的日志文件。包括Redis在内的很多软件都使用这种方法来记录日志。但这种记录日志的方式有时候可能会遇上麻烦:因为每个不同的服务都会创建不同的日志,而这些服务轮换(rolling)日志的机制也各不相同,并且也缺少一种能够方便地聚合所有日志并对其进行处理的常用方法。

syslog服务是第二种常用的日志记录方法,这个服务运行在几乎所有Linux服务器和Unix服务器的514号TCP端口和UDP端口上面。syslog接受其他程序发来的日志消息,并将这些消息路由(route)至存储在硬盘上的各个日志文件里面,除此之外,syslog还负责旧日志的轮换和删除工作。通过配置,syslog甚至可以将日志消息转发给其他服务来做进一步的处理。因为对指定日志的轮换和删除工作都可以交给syslog来完成,所以使用syslog服务比直接将日志写入文件要方便得多。

替换syslog无论读者使用上面列举的两种日志记录方法中的哪一种,都最好考虑把系统目前的syslog守护进程(通常是Rsyslogd)替换成syslog-ng。因为我经过使用并配置Rsyslogd和syslog-ng之后,发现syslog-ng用于管理和组织日志消息的配置语言使用起来更简单一些。

syslog的转发功能可以将不同的日志分别存储到同一台服务器的多个文件里面,这对于长时间地记录日志非常有帮助(记得备份)。在这一节中,我们将介绍如何使用Redis来存储与时间紧密相关的日志(time-sensitive log),从而在功能上替代那些需要在短期内被存储的syslog消息。首先让我们来看看,如何记录连续更新的最新日志消息(recent log message)。

最新日志

在构建一个系统的时候,判断哪些信息需要被记录是一件困难的事情:需要记录用户的登入和登出行为吗?需要记录用户修改账号信息的时间吗?还是只记录错误和异常就可以了?虽然我没办法替你回答这些问题,但我可以向你提供一种将最新出现的日志消息以列表的形式存储到Redis里面的方法,这个列表可以帮助你随时了解最新出现的日志都是什么样子的。

代码清单1的log_recent()函数展示了将最新日志记录到Redis里面的方法:为了维持一个包含最新日志的列表,程序使用LPUSH命令将日志消息推入一个列表里面。之后,如果我们想要查看已有日志消息的话,那么可以使用LRANGE命令来取出列表中的消息。除了LPUSH之外,函数还加入了一些额外的代码,用于命名不同的日志消息队列,并根据问题的严重性对日志进行分级,如果你觉得自己并不需要这些附加功能的话,也可以把相关的代码删掉,只保留基本的日志添加功能。

SEVERITY = {                                                    #A
    logging.DEBUG: 'debug',                                     #A
    logging.INFO: 'info',                                       #A
    logging.WARNING: 'warning',                                 #A
    logging.ERROR: 'error',                                     #A
    logging.CRITICAL: 'critical',                               #A
}                                                               #A
SEVERITY.update((name, name) for name in SEVERITY.values())     #A

def log_recent(conn, name, message, severity=logging.INFO, pipe=None):
    severity = str(SEVERITY.get(severity, severity)).lower()    #B
    destination = 'recent:%s:%s'%(name, severity)               #C
    message = time.asctime() + ' ' + message                    #D
    pipe = pipe or conn.pipeline()                              #E
    pipe.lpush(destination, message)                            #F
    pipe.ltrim(destination, 0, 99)                              #G
    pipe.execute()                                              #H
#A Set up a mapping that should help turn most logging severity levels into something consistent
#B Actually try to turn a logging level into a simple string
#C Create the key that messages will be written to
#D Add the current time so that we know when the message was sent
#E Set up a pipeline so we only need 1 round trip
#F Add the message to the beginning of the log list
#G Trim the log list to only include the most recent 100 messages
#H Execute the two commands

除了那些将日志的安全级别转换为字符串(如info和debug)的代码之外,log_recent()函数的定义非常简单——基本上就是一个LPUSH加上一个LTRIM。现在你已经知道怎样记录最新出现的日志了,是时候来了解一下该如何记录最常出现的(也可能是最重要的)日志消息了。

常见日志

如果实际运行一下log_recent()函数的话,你可能就会发现,尽管log_recent()函数非常适用于记录当前发生的事情,但它并不擅长告诉你哪些消息是重要的,哪些消息是不重要的。为了解决这个问题,我们可以让程序记录特定消息出现的频率,并根据出现频率的高低来决定消息的排列顺序,从而帮助我们找出最重要的消息。

代码清单2的log_common()函数展示了记录并轮换最常见日志消息的方法:程序会将消息作为成员存储到有序集合里面,并将消息出现的频率设置为成员的分值。为了确保我们看见的常见消息都是最新的,程序会以每小时一次的频率对消息进行轮换,并在轮换日志的时候保留上一个小时记录的常见消息,从而防止没有任何消息存在的情况出现。

def log_common(conn, name, message, severity=logging.INFO, timeout=5):
    severity = str(SEVERITY.get(severity, severity)).lower()    #A
    destination = 'common:%s:%s'%(name, severity)               #B
    start_key = destination + ':start'                          #C
    pipe = conn.pipeline()
    end = time.time() + timeout
    while time.time() < end:
        try:
            pipe.watch(start_key)                               #D
            now = datetime.utcnow().timetuple()                 #E
            hour_start = datetime(*now[:4]).isoformat()         #F

            existing = pipe.get(start_key)
            pipe.multi()                                        #H
            if existing and existing < hour_start:              #G
                pipe.rename(destination, destination + ':last') #I
                pipe.rename(start_key, destination + ':pstart') #I
                pipe.set(start_key, hour_start)                 #J
            elif not existing:                                  #J
                pipe.set(start_key, hour_start)                 #J

            pipe.zincrby(destination, message)                  #K
            log_recent(pipe, name, message, severity, pipe)     #L
            return
        except redis.exceptions.WatchError:
            continue                                            #M
#A Handle the logging level
#B Set up the destination key for keeping recent logs
#C Keep a record of the start of the hour for this set of messages
#D We are going to watch the start of the hour key for changes that only happen at the beginning of the hour
#E Get the current time
#F Find the current start hour
#G If the current list of common logs is for a previous hour
#H Set up the transaction
#I Move the old common log information to the archive
#J Update the start of the current hour for the common logs
#K Actually increment our common counter
#L Call the log_recent() function to record these there, and rely on its call to execute()
#M If we got a watch error from someone else archiving, try again

因为记录常见日志的函数需要小心地处理上一个小时收集到的日志,所以它比记录最新日志的函数要复杂得多:程序会在一个WATCH/MULTI/EXEC事务里面,对记录了上一个小时的常见日志的有序集合进行改名,并对记录了当前所处小时数的键进行更新。除此之外,程序还会将流水线对象传递给log_recent()函数,以此来减少记录常见日志和记录最新日志时,客户端与Redis服务器之间的通信往返次数。

参考文档