为何Python Twisted的.rpy模块每次刷新会被多次调用？

问题 #

第一天学习Python，使用命令：

/usr/bin/python3 -m twisted web --http=80 --path=/website

启动Twisted Web服务器，添加了/test.rpy脚本页面，代码如下：

from twisted.web.resource import Resource
from twisted.python import log

import subprocess

class MyResource(Resource):
    def render_GET(self, request):
        log.startLogging(open('/root/test.log', 'a'))
        log.msg('test')
        request.setHeader(b"content-type", b"text/html")
        return b'abc'

resource = MyResource()

访问页面时浏览器正常显示"abc"，但/test.log中每次刷新页面，日志条目数递增：第一次1条'test'，第二次2条，第三次3条，同时出现日志目标重复的警告，日志示例如下：

# tail -f test.log 
2023-03-24 14:08:49+0000 [-] Warning: primary log target selected twice at </usr/lib/python3/dist-packages/twisted/python/log.py:208> - previously selected at </usr/lib/python3/dist-packages/twisted/application/runner/_runner.py:140>.  Remove one of the calls to beginLoggingTo.
2023-03-24 14:08:49+0000 [_GenericHTTPChannelProtocol (TLSMemoryBIOProtocol),0,x.x.x.x] Log opened.
2023-03-24 14:08:49+0000 [_GenericHTTPChannelProtocol (TLSMemoryBIOProtocol),0,x.x.x.x] test

2023-03-24 14:08:58+0000 [-] Warning: primary log target selected twice at </usr/lib/python3/dist-packages/twisted/python/log.py:208> - previously selected at </usr/lib/python3/dist-packages/twisted/python/log.py:208>.  Remove one of the calls to beginLoggingTo.
2023-03-24 14:08:58+0000 [-] Warning: primary log target selected twice at </usr/lib/python3/dist-packages/twisted/python/log.py:208> - previously selected at </usr/lib/python3/dist-packages/twisted/python/log.py:208>.  Remove one of the calls to beginLoggingTo.
2023-03-24 14:08:58+0000 [_GenericHTTPChannelProtocol (TLSMemoryBIOProtocol),0,x.x.x.x] Log opened.
2023-03-24 14:08:58+0000 [_GenericHTTPChannelProtocol (TLSMemoryBIOProtocol),0,x.x.x.x] Log opened.
2023-03-24 14:08:58+0000 [_GenericHTTPChannelProtocol (TLSMemoryBIOProtocol),0,x.x.x.x] test
2023-03-24 14:08:58+0000 [_GenericHTTPChannelProtocol (TLSMemoryBIOProtocol),0,x.x.x.x] test

期望每次加载页面时日志仅输出一次，而非多次，请求解释原因。

原因分析 #

问题核心在于render_GET方法内的log.startLogging调用：

• Twisted的log.startLogging并非替换已有日志配置，而是每次执行都会新增一个日志观察者，指向你指定的文件。
• 每次刷新页面，render_GET就会被触发一次，相当于给日志系统多绑定一个文件输出端。当调用log.msg('test')时，所有已绑定的观察者都会各自输出一条日志，因此条目数会随刷新次数递增。
• 重复添加相同类型的日志目标，会触发Twisted的内置警告，提示日志初始化逻辑被重复调用。

解决方法 #

将日志初始化代码移到请求处理逻辑之外，确保仅执行一次：

from twisted.web.resource import Resource
from twisted.python import log

import subprocess

# 仅初始化一次日志输出
log.startLogging(open('/root/test.log', 'a'))

class MyResource(Resource):
    def render_GET(self, request):
        log.msg('test')
        request.setHeader(b"content-type", b"text/html")
        return b'abc'

resource = MyResource()

修改后，每次请求只会触发一次log.msg('test')，日志文件中只会新增一条对应记录，重复警告也会消失。

内容的提问来源于stack exchange，提问作者zeb3142