使用 twisted.logger 进行日志记录

基础知识

日志记录包含两个主要端点:发出事件的应用程序和接收和处理这些事件的观察者。事件只是一个 dict 对象,其中包含描述应用程序中发生的有趣事件的相关数据。例如:Web 服务器在处理每个请求后可能会发出一个事件,其中包含请求资源的 URI、响应的状态代码、传输的字节数等等。所有这些信息都可能包含在一对表示请求和响应的对象中,因此记录此事件可能与以下代码一样简单

log.info(request=request, response=response)

上面的 API 对许多日志记录系统的用户来说似乎令人困惑,这些系统是围绕将字符串发出到文件的想法构建的。毕竟,上面的调用中没有字符串。在这样的系统中,人们可能希望 API 如下所示

log.info(
    "{uri}: status={status}, bytes={size}, etc..."
    .format(uri=request.uri, status=response.code, size=response.size)
)

在这里,通过格式化来自请求和响应对象的数据来呈现字符串。该字符串可以轻松地附加到日志文件中,以便管理员稍后读取,或者可能通过一些脚本或日志收集工具提取出来。

这方面的一个缺点是,旨在供人类阅读的字符串不一定容易(甚至不可能)让软件可靠地处理。虽然文本文件是存储日志的常见媒介,但人们可能希望编写代码来注意到某些类型的事件并执行一些除了存储事件之外的操作。

在 Web 服务器示例中,如果来自给定 IP 地址的许多请求导致身份验证失败,则可能有人试图侵入服务器。也许阻止来自该 IP 地址的请求将很有用。接收上述事件作为字符串的观察者将不得不求助于解析字符串以提取相关信息,这可能会执行效率低下,并且根据事件的格式化程度,也可能难以避免错误。此外,任何未编码到字符串中的信息都不可用;如果 IP 地址不在字符串中,则无法从事件中获取它。

但是,如果 requestresponse 对象可供观察者使用,如第一个示例所示,则可以编写一个观察者来访问这些对象的任何属性。编写一个通过将这些对象序列化为 JSON、数据库中的行等格式来发出结构化信息的观察者也会容易得多。

事件作为字符串确实具有一个优势,即很明显编写字符串的观察者(例如写入文件)会发出什么。我们可以通过在事件中提供一个可选的格式字符串来更灵活地解决这个问题,该字符串可用于此目的

log.info(
    "{request.uri}: status={response.status}, bytes={response.size}, etc...",
    request=request, response=response
)

请注意,这看起来非常像事件作为字符串版本的 API,只是字符串不是由调用者呈现的;我们将其留给观察者,如果需要的话。观察者还可以直接访问请求和响应对象及其属性。现在,基于文本的观察者可以以规定的方式格式化文本,而想要以其他方式处理这些事件的观察者也可以这样做。

用于发出应用程序的用法

发出日志记录事件的应用程序首先需要做的是实例化一个 Logger 对象,它提供了发出事件的 API。一个 Logger 可以为模块全局创建

from twisted.logger import Logger
log = Logger()

def handleData(data):
    log.debug("Got data: {data!r}.", data=data)

一个 Logger 也可以与一个类相关联

from twisted.logger import Logger

class Foo(object):
    log = Logger()

    def oops(self, data):
        self.log.error(
            "Oops! Invalid data from server: {data!r}",
            data=data
        )

当以这种方式与类相关联时,"log_source" 键将在事件中设置。例如

logsource.py

from twisted.logger import Logger


class MyObject:
    log = Logger()

    def __init__(self, value):
        self.value = value

    def doSomething(self, something):
        self.log.info(
            "Object with value {log_source.value!r} doing {something}.",
            something=something,
        )


MyObject(7).doSomething("a task")

此示例将显示字符串“具有值 7 的对象正在执行任务”,因为 log_source 键会自动设置为 MyObject 实例,该实例是从中检索 Logger 的。

捕获失败

Logger 提供了一个 failure 方法,它允许人们方便地捕获 Failure 对象

from twisted.logger import Logger
log = Logger()

try:
    1 / 0
except BaseException:
    log.failure("Math is hard!")

发出的事件将具有设置的 "log_failure" 键,它是一个 Failure,它捕获了异常。观察者可以使用它来获取回溯。例如,FileLogObserver 会将回溯附加到其输出

Math is hard!

Traceback (most recent call last):
--- <exception caught here> ---
  File "/tmp/test.py", line 8, in <module>
    1/0
exceptions.ZeroDivisionError: integer division or modulo by zero

请注意,此 API 旨在捕获意外和未处理的错误(即:错误,这就是为什么保留回溯的原因)。因此,它默认以 critical 级别进行日志记录。在记录已由软件适当地处理的预期错误条件时,通常更适合使用 log.error()

命名空间

所有 Logger 都具有命名空间,可用于对事件进行分类。可以通过将 namespace 参数传递给 Logger 的初始化程序来指定命名空间,但如果没有给出命名空间,则记录器将从实例化它的可调用对象的模块名称派生其命名空间,或者,在类的情况下,从类的完全限定名称派生其命名空间。一个 Logger 将向其发出的事件添加一个 log_namespace 键。

在上面的第一个示例中,命名空间将是 some.module,在第二个示例中,它将是 some.module.Foo

日志级别

Logger 提供了许多用于发出事件的方法。这些方法都具有相同的签名,但每个方法都会将特定的 log_level 键附加到事件。日志级别由 LogLevel 常量容器定义。这些是

调试

调试事件:对软件开发人员有用的信息,通常对运行软件的人员来说没有兴趣,除非他们试图诊断软件问题。

信息

信息事件:有关应用程序状态的常规信息,例如传入连接、子系统启动等。

警告

警告事件:可能需要比信息事件更多关注的事件,但不是系统性故障条件,例如授权失败、来自网络客户端的错误数据等。此类事件可能对系统管理员感兴趣,并且应该以某种方式表达,或者记录下来,以便指示管理员可能采取的缓解警告的措施。

错误

错误条件:指示系统性故障的事件。例如,资源耗尽,或与外部系统(例如数据库或 API 端点)的连接丢失,没有这些连接,任何有用的工作都无法进行。与警告类似,与操作参数相关的错误可能对系统管理员可操作,并且应提供管理员可能用来解决这些错误的资源的参考。

严重

严重故障:指示系统性故障(即服务中断)、数据损坏、即将发生的数据丢失等必须立即处理的错误。这包括软件未预料到的错误,例如未处理的异常,其中原因和后果未知。

在上面的第一个示例中,对 log.debug 的调用将在发出的事件中添加一个 log_level 键,其值为 LogLevel.debug。在第二个示例中,调用 self.log.error 将使用 LogLevel.error 的值。

以上描述只是指导,但值得注意的是,如果日志级别使用不一致,则它们的价值会降低。如果应用程序中的一个模块将消息视为信息,而另一个模块将类似消息视为错误,那么基于日志级别的过滤将变得更加困难。如果所讨论的模块是由不同的方开发的,那么这种情况更有可能发生,就像外部源库和框架经常发生的那样。(如果一个模块倾向于使用比另一个模块更高的级别,则可以使用命名空间来校准日志级别的相对使用,但这显然不是最佳选择。)坚持上述指南将有助于解决这个问题。

发射器方法签名

发射器方法(debuginfowarn 等)都接受一个可选的格式字符串作为第一个参数,然后是将包含在发出的事件中的关键字参数。

请注意,本 HOWTO 开头部分中的所有三个示例都符合此签名。第一个省略了格式,这不利于文本记录。第二个省略了关键字参数,这不利于除文本记录之外的任何其他内容,因此不建议这样做。最后,第三个提供了两者,这是推荐的使用方法。

这些方法都是围绕 emit 方法的便利包装器,该方法将 LogLevel 作为其第一个参数。

格式字符串

格式字符串为观察者提供了一种标准方法,用于将事件格式化为适合人类阅读的文本。格式化是使用函数 eventAsText 完成的。编写格式字符串时,请注意以对人类读者最有意义的方式呈现它。特别是,格式字符串不需要考虑可解析性或机器可读性。如果您想将日志事件与其结构一起保存,然后稍后分析它们,请参阅下一节,关于 “保存事件以备后用”

格式字符串应该是

unicode,并使用 PEP 3101 语法来描述如何将事件呈现为人类可读的文本。为了向后兼容和在 python 2 中方便起见,也接受 UTF-8 编码的 bytes 作为格式字符串,但首选 unicode。此模块中使用的格式字符串与 PEP 3101 存在两种变体

  1. 不允许使用位置(数字)字段名(例如 {0})。事件键没有排序,这意味着位置字段名在这种情况下没有意义。但是,这不是偶然的限制,而是一个有意的设计决策。随着软件的演变,日志消息通常会增长以包含更多信息,同时仍然记录相同的概念事件。通过使用有意义的名称而不是不透明的索引来表示事件键,这些标识符对消息格式和提供的信息的未来更改更具鲁棒性。

  2. 以括号结尾的字段名(例如 {foo()})将调用引用的对象,不带任何参数,然后调用 str 来获取结果,而不是直接调用 str 来获取引用的对象。此对 PEP 3101 格式语法的扩展是为了尽可能轻松地将可能昂贵的操作推迟到必须发出日志消息时。例如,假设我们想记录一条消息,其中包含来自“request”对象的某些有用但可能昂贵的信息

    log.info("{request.uri} useful, but expensive: {request.usefulButExpensive()}",
             request=request)
    

    在这种情况下,如果此日志消息被过滤掉,因为没有兴趣并且没有保存,则根本不会进行任何格式化工作;并且由于我们可以将 PEP3101 属性访问语法与此括号扩展一起使用,因此调用者甚至不需要构建一个函数或绑定方法对象来作为单独的键传递。不支持在格式字符串中指定参数;目标是使表达稍后完成的工作成为习惯,而不是实现一个完整的 Python 表达式求值器。

系统添加的事件键

日志系统将向发出的事件添加键。日志系统插入的所有事件键都将具有 log_ 前缀,以避免与应用程序提供的事件键发生命名空间冲突。因此,应用程序不应使用 log_ 前缀插入事件键,因为该前缀是为日志系统保留的。系统提供的事件键包括

log_logger

Logger 对象,事件被发出到该对象。

log_source

发出事件的源对象。当 Logger 被访问为类的属性时,该类是源。当被访问为实例的属性时,该实例是源。在其他情况下,源是 None

log_level

与事件关联的 LogLevel

log_namespace

与事件关联的命名空间。

log_format

为希望将事件呈现为文本的观察者提供的格式字符串。这可能是 None,如果未提供格式字符串。

log_time

发出事件的时间,如 time 所返回。

log_failure

发出事件时捕获的 Failure 对象。

避免可变事件键

发出应用程序应谨慎地将可能稍后被修改的对象插入事件中。虽然观察者是同步调用的,但观察者可能会做一些事情,例如将事件排队以供稍后序列化,在这种情况下,序列化的对象可能与预期不同。

捕获日志事件以进行测试

如果您想测试您的代码是否记录了预期的事件,您可以使用 LogCapture 上下文管理器

from twisted.logger import Logger, LogLevel, capturedLogs
from twisted.trial.unittest import TestCase

class SomeTests(TestCase):

    def test_capture(self):
        foo = object()

        with capturedLogs() as captured:
            self.log.debug("Capture this, please", foo=foo)

        self.assertTrue(len(captured) == 1)
        self.assertEqual(captured[0]["log_format"], "Capture this, please")
        self.assertEqual(captured[0]["log_level"], LogLevel.debug)
        self.assertEqual(captured[0]["foo"], foo)

保存事件以备后用

出于兼容性原因,twistd 默认情况下会记录到基于文本的格式。但是,使用结构化的日志文件格式要好得多,它可以保留有关正在记录的事件的信息。 twisted.logger 提供两个 API:jsonFileLogObservereventsFromJSONLogFile,它们允许您以基本保真度保存和检索结构化日志事件。日志事件被序列化为 JSON 字典,序列化规则尽可能宽松;任何未知值都将被替换为简单的占位符值。

jsonFileLogObserver 将创建一个日志观察器,它将事件保存为结构化数据,如下所示

saver.py

import io

from twisted.logger import Logger, jsonFileLogObserver

log = Logger(observer=jsonFileLogObserver(open("log.json", "a")), namespace="saver")


def loggit(values):
    log.info("Some values: {values!r}", values=values)


loggit([1234, 5678])
loggit([9876, 5432])

eventsFromJSONLogFile 可以再次加载这些事件;在这里,您可以看到该事件保留了足够的信息以再次格式化为人类可读的格式

loader.py

import io
import sys

from twisted.logger import eventsFromJSONLogFile, textFileLogObserver

output = textFileLogObserver(sys.stdout)

for event in eventsFromJSONLogFile(open("log.json")):
    output(event)

当然,您也可以随意访问您加载的 event 对象中的任何键;基本结构,如列表、数字、字典和字符串(任何可以使用 JSON 序列化的内容)都将被保留

loader-math.py

import io

from twisted.logger import eventsFromJSONLogFile

for event in eventsFromJSONLogFile(open("log.json")):
    print(sum(event["values"]))

实现观察器

观察器必须提供 ILogObserver 接口。该接口只是描述一个带有一个参数的可调用对象,该参数接受一个 dict,因此一个简单的实现可能只是在一个接受一个参数的函数上使用方便的 provider 装饰器

from zope.interface import provider
from twisted.logger import ILogObserver, eventAsText

@provider(ILogObserver)
def simpleObserver(event):
    print(eventAsText(event))

eventAsText 函数返回事件的文本 (unicode) 表示。

虽然建议,但在大多数情况下,观察器不需要声明它们对 ILogObserver 的遵守。这种灵活性是为了允许预先存在的可调用对象和 lambda 表达式用作观察器。例如,如果有人想在 list 中累积事件,那么 list.append 可以用作观察器。

但是,在实现您自己的日志观察器时,您应该始终牢记,与 Twisted 中的大多数对象不同,日志观察器必须是线程安全的

具体来说,日志观察器

  • 必须准备好从主线程(或 I/O 线程或反应器线程)以外的线程中调用

  • 必须准备好从多个线程并发调用

  • 在没有采取预防措施(如使用 callFromThread)的情况下,不得与其他 Twisted API(这些 API 不是明确的线程安全的)交互

请记住,即使您选择不从您的程序中显式地与任何线程交互,这也是正确的。Twisted 本身可能会从线程中记录消息,并且 Twisted 可能会在内部使用 callInThread 等 API;例如,Twisted 使用线程在进行传出连接时查找主机名。

鉴于此额外的复杂性,在实现您自己的代码之前,最好看看是否可以找到一个现有的日志观察器实现来满足您的需求;线程安全可能很难实现。幸运的是,twisted.logger 附带了一些有用的观察器,这些观察器在下面有记录。

编写用于事件分析的观察器

Twisted 包含日志观察器,这些观察器负责大多数“正常”的日志记录用途,例如将消息写入文件、将它们保存为文本、过滤它们等等。您可能想要编写自己的日志观察器有两个常见的原因。第一个是将日志消息发送到 Twisted 本身不支持的另一种外部系统。如果您阅读了以上内容,您现在已经了解了如何做到这一点;只需实现一个函数,将字典转换为适合您的外部系统或文件格式的内容,然后将其发送到那里或保存它。第二个任务是进行某种分析,无论是实时地在您的进程中进行,还是事后离线进行。

您可能需要从您自己的代码和您使用的库(包括 Twisted 本身)中聚合信息,并且您可能对这些消息的组织方式没有太多控制。您也可能试图将来自临时消息的信息聚合到某种结构中。

提取这种半结构化信息的一种方法是将您的日志馈送到像 logstash 这样的外部系统,并在那里处理它们。这些系统非常强大,twisted.logger 不会试图取代它们。但是,这些系统必然是外部的,因此,如果您想您的应用程序中对日志分析做出反应 - 例如,响应滥用客户端而拒绝访问 - 您将不得不编写一些粘合代码将消息从您的日志分析系统推回您的应用程序。对于这种情况,能够将日志分析代码编写为日志观察器非常有用。

假设您感兴趣的分析其日志事件的库正在使用 twisted.logger,您可以实时分析日志事件(在它们被记录时),也可以从保存的日志文件中加载它们。

如果您正在编写代码来直接记录事件以进行潜在分析,那么您应该简单地将您的消息结构化为包含所有必要信息作为序列化友好的值,然后简单地将它们拉出来,就像上面的 loader-math.py 示例一样。

但是,假设您正在尝试与一个像这样记录消息的系统交互

ad_hoc.py

from twisted.logger import Logger


class AdHoc:
    log = Logger(namespace="ad_hoc")

    def __init__(self, a, b):
        self.a = a
        self.b = b

    def logMessage(self):
        self.log.info(
            "message from {log_source} "
            "where a is {log_source.a} and b is {log_source.b}"
        )

在这个例子中,AdHoc 对象本身不可序列化,但它有两个相关的属性,日志消息的格式字符串将其作为 log_source 字段的属性调用,如上所述:ab

要分析此事件,我们不能采用上面 loader-math.py 中显示的相同策略。我们没有要直接检查的日志事件的任何键值对;ab 本身并不存在作为键。我们可以查找事件中的 log_source 键并访问其 ab 属性,但这在事件被序列化并再次加载后将不起作用,因为 AdHoc 实例不是可以保存到 JSON 的基本类型。

幸运的是,twisted.logger 提供了一个用于执行此操作的 API:extractField。您像这样使用它

analyze.py

from twisted.logger import extractField

fmt = "message from {log_source} " "where a is {log_source.a} and b is {log_source.b}"


def analyze(event):
    if event.get("log_format") == fmt:
        a = extractField("log_source.a", event)
        b = extractField("log_source.b", event)
        print("A + B = " + repr(a + b))

然后,这个 analyze 函数可以用两种方式使用。首先,您可以在应用程序“实时”运行时对其进行分析。

online_analyze.py

from ad_hoc import AdHoc
from analyze import analyze

from twisted.logger import globalLogPublisher

globalLogPublisher.addObserver(analyze)

AdHoc(3, 4).logMessage()

如果您运行此脚本,您将看到它从 AdHoc 对象的日志消息中提取了值。

但是,您也可以使用完全相同的代码分析保存的日志文件中的输出。首先,您需要使用来自 AdHoc 对象的消息生成一个日志文件

ad_hoc_save.py

import io

from ad_hoc import AdHoc

from twisted.logger import globalLogPublisher, jsonFileLogObserver

globalLogPublisher.addObserver(jsonFileLogObserver(open("log.json", "a")))

AdHoc(3, 4).logMessage()

如果您运行该脚本,它将生成一个 log.json 文件,该文件可以使用与上面的 loader.py 示例相同的方式进行分析

offline_analyze.py

import io

from analyze import analyze

from twisted.logger import eventsFromJSONLogFile

for event in eventsFromJSONLogFile(open("log.json")):
    analyze(event)

在进行分析时,总感觉您应该为以后保存更多结构化数据。但是,日志消息通常是在开发的早期以临时的方式编写的,在对哪些信息有用以及哪些信息冗余有了充分的了解之前。因此,日志消息是对系统开发过程中正在发生的事情的意识流评论。

extractField 允许您承认日志消息编写方式的混乱现实,但仍然能够在以后利用结构化分析。只需始终确保使用事件格式字段,而不是字符串连接,来引用有关特定事件的信息,您将能够轻松地将来自系统多个版本的草率编写的临时消息拆开,无论是在运行时还是保存日志文件后。

注册观察器

注册观察器的一种方法是使用它构造一个 Logger 对象

from twisted.logger import Logger
from myobservers import PrintingObserver

log = Logger(observer=PrintingObserver())

log.info("Hello")

这将导致记录器的所有事件都被发送到给定的观察器。在上面的示例中,记录器发出的所有事件(例如 "Hello")都将被打印出来。虽然这在某些情况下很有用,但通常会注册多个观察器,并且在应用程序中为所有(或大多数)记录器全局注册。

全局日志发布者

全局日志发布者是一个日志观察器,其目的是捕获未定向到特定观察器的日志事件。在典型的应用程序中,大多数日志事件将被发送到全局日志发布者。观察器可以向全局日志发布者注册自己,以便转发这些事件。

当创建 Logger 时,如果没有指定要发送事件的观察者,则记录器会将事件发送到全局日志发布者,可以通过名称 globalLogPublisher 访问。

全局日志发布者是 LogPublisher 的私有子类的单例实例,它本身是一个 ILogObserver 。这意味着全局日志发布者接受事件,就像其他观察者一样,并且它将这些事件转发给其他观察者。可以通过调用 LogPublisher 方法 addObserver 来注册观察者以转发事件,并通过调用 removeObserver 来取消注册。

from twisted.logger import globalLogPublisher
from myobservers import PrintingObserver

log = Logger()

globalLogPublisher.addObserver(PrintingObserver())

log.info("Hello")

这里的结果与前面的示例相同,只是可以(并且可能已经)注册了额外的观察者。我们知道 "Hello" 将被打印。我们不知道,但很有可能,相同的事件也会被其他观察者处理。

没有支持的 API 来发现哪些其他观察者已注册到 LogPublisher ;通常,不需要知道。例如,如果应用程序在 twistd 中运行,则应用程序代码开始运行时,很可能会有一个观察者将事件流式传输到文件。如果它在 twistd web 容器中运行,则可能会有另一个观察者写入访问日志。

这里需要注意的是,事件是 dict 对象,它们是可变的,因此观察者可以修改它看到的事件。由于这样做会修改其他观察者将看到的内容,因此修改接收到的事件可能会出现问题,应强烈建议不要这样做。修改或删除现有事件键的内容尤其有害。此外,不保证观察者的调用顺序,因此此类修改对其他观察者的影响可能是不可预测的。

启动全局日志发布者

当创建全局日志发布者时,它使用 LimitedHistoryLogObserver (见下文)来存储应用程序在内存中记录的事件,直到启动日志记录。通过调用 beginLoggingTo 将第一组观察者注册到全局日志发布者来启动日志记录。

from twisted.logger import globalLogBeginner
from myobservers import PrintingObserver

log = Logger()

log.info("Hello")

observers = [PrintingObserver()]

globalLogBeginner.beginLoggingTo(observers)

log.info("Hello, again")

  • 将给定的观察者(在本例中为 PrintingObserver)添加到全局日志观察者

  • 将调用 beginLoggingTo 之前存储在内存中的所有事件转发给这些观察者

  • 删除 LimitedHistoryLogObserver,因为它不再需要。

多次调用 beginLoggingTo 是错误的。

注意

如果全局日志发布者从未启动,则内存中的事件缓冲区会无限期地保存(有限数量的)日志事件。这可能会意外地增加应用程序内存或 CPU 使用率。强烈建议尽早启动全局日志发布者。

提供的日志观察者

此模块为应用程序提供了一些预构建的观察者。

LogPublisher

将事件转发给其他发布者。这允许您创建一个观察者图。

LimitedHistoryLogObserver

存储有限数量的接收到的事件,并且可以稍后将这些存储的事件重新播放给另一个观察者。这对于在其他日志输出不可用时,将最近的日志历史记录保存在内存中以供检查很有用。

FileLogObserver

将事件格式化为文本,以时间戳和“系统标识符”为前缀,并将它们写入文件。系统标识符默认为事件的命名空间和级别的组合。

FilteringLogObserver

在应用一组过滤器谓词(ILogFilterPredicate 的提供者)后,将事件转发给另一个观察者。 LogLevelFilterPredicate 是一个谓词,可以配置为跟踪要过滤的不同命名空间的日志级别,并将过滤掉不在适当级别或更高级别的事件。

与标准库日志记录的兼容性

STDLibLogObserver 用于与标准库的 logging 模块兼容。日志级别在两个系统之间映射,并且标准库日志记录的各种属性被正确填充。

请注意,标准库日志记录是一个阻塞 API,并且可以配置日志记录以阻塞很长时间(例如,它可能写入网络)。没有提供保护措施来防止阻塞,因此此类配置可能会导致 Twisted 应用程序性能下降。

与 twisted.python.log 的兼容性

此模块提供了一些工具,使现有的 twisted.python.log 模块能够兼容地将其消息转发到此模块。因此,twisted.python.log 的现有客户端将开始间接使用此模块,而无需更改旧模块的 API。

增量移植观察者

观察者有一个增量路径可以移植到新模块。 LegacyLogObserverWrapper 是一个 ILogObserver,它包装了为旧模块编写的日志观察者。这允许以兼容的方式将旧式观察者注册到新式记录器或日志发布者。