如何配置uwsgi将日志记录编码为除了app输出之外的json

Question

我正在使用这些选项（以及其他）在Python Flask webapp周围运行uwsgi，以在stdout上获取JSON编码的日志记录：

fmt=$'{"timestamp": "${strftime:%FT%TZ}", "level": "DEBUG", "name": "uwsgi", "message": "${msg}"}\n'

uwsgi --env="TZ=UTC" --log-encoder="json ${fmt}" --logformat="%(status) [%(msecs)ms] %(method) %(uri)"

这很好地编写了来自uwsgi的stdout，但不幸的是还编码了我的应用程序的日志记录，它已经是JSON格式，所以我得到的结果如下：

{"timestamp": "2017-10-02T22:48:11Z", "level": "DEBUG", "name": "uwsgi", "message": "spawned uWSGI http 1 (pid: 75298)"}
{"timestamp": "2017-10-02T22:48:15Z", "level": "DEBUG", "name": "uwsgi", "message": "{\"timestamp\": \"2017-10-02T22:48:15.200Z\", \"message\": \"Descriptor requested\", \"request\": \"c6b08680-a7c3-11e7-9495-186590cba8eb\", \"name\": \"myapp.main\", \"level\": \"INFO\"}"}
{"timestamp": "2017-10-02T22:48:15Z", "level": "DEBUG", "name": "uwsgi", "message": "200 [11ms] GET /descriptor.json"}

中间记录包含在与uwsgi的其他输出相同的JSON编码中。

如何避免我的Flask应用程序的输出被编码，但保持uwsgi本身的其他输出的编码？

我尝试了--log-encoder和--log-req-encoder的各种组合，但后者似乎没有编码。关于两种选择之间的区别，文档并不十分清楚。

Answer 1

最后，我不得不删除--log-encoder并通过一个包含JSON输出的进程传递stdout（和stderr），除非已编码为JSON。

function log_json() { python -u -c "
    import sys
    import json
    import datetime
    log = dict(name='uwsgi', level='$1')
    line = sys.stdin.readline()
    while line:
        line = line.strip()
        if line.startswith('{') and line.endswith('}'):
            print(line)
        elif line:
            log['timestamp'] = datetime.datetime.utcnow().isoformat() + 'Z'
            log['message'] = line
            print(json.dumps(log))
        line = sys.stdin.readline()
"; }

{ uwsgi ... 2>&1 1>&3 3>&- | log_json ERROR; } 3>&1 1>&2 | log_json INFO

如果您只想对请求记录进行编码，请添加--logger-req=stdio选项以使--log-req-encoder正确编码请求记录。

Answer 2

另一种方法是将调用包装成uwsgi（答案很大程度上依赖于这个：Python read from subprocess stdout and stderr separately while preserving order）。在这里，我假设您有一个记录器配置为以正确的格式输出消息。如果没有，您可以构造JSON对象而不是调用logger.info()。

import json
import logging
import os
import subprocess as sp
import sys
from threading import Thread
import time


def reader(process, source):
    assert source in {'stdout', 'stderr'}
    if source == 'stdout':
        pipe = process.stdout
    else:
        pipe = process.stderr
    with pipe:
        for line in pipe:
            if line == '' and process.poll() is not None:
                return
            # check if the message is already formatted because it's emitted by the app
            if 'myapp.main' in line:
                continue
            if source == 'stdout':
                logger.info(line.strip())
            else:
                logger.error(line.strip())


if __name__ == '__main__':

    config_file_name = sys.argv[1]
    # configure_logging(...)
    logger = logging.getLogger('uwsgi')

    cmd = ["pipenv", "run", "--", "uwsgi",
           "--http", ":80",
           "--master",
           "--wsgi-file", "app.py",
           "--callable", "app",
           "--threads", "10",
           "--pyargv", config_file_name]
    process = sp.Popen(cmd, stdout=sp.PIPE, stderr=sp.PIPE, encoding='utf8')

    Thread(target=reader, args=[process], kwargs={'source': 'stdout'}).start()
    Thread(target=reader, args=[process], kwargs={'source': 'stderr').start()

    return_code = process.wait()

Answer 3

不是我的回答，但我想我会做出贡献，因为我也在努力工作几个小时，see here

我发现的唯一问题是启动消息仍未正确进行JSON编码，我认为因为没有默认的日志编码器。我得到的是：

*** Operational MODE: preforking+threaded ***
WSGI app 0 (mountpoint='') ready in 0 seconds on interpreter 0x55ac64f873c0 pid: 115 (default app)
*** uWSGI is running in multiple interpreter mode ***
spawned uWSGI master process (pid: 115)
spawned uWSGI worker 1 (pid: 120, cores: 2)
spawned uWSGI worker 2 (pid: 121, cores: 2)
spawned uWSGI worker 3 (pid: 123, cores: 2)
spawned uWSGI worker 4 (pid: 124, cores: 2)
spawned uWSGI http 1 (pid: 126)
{"timestamp":30-04-2019 04:20:56, "source": "request", "level":"INFO", "message":"[pid: 120|app: 0|req: 1/1] 10.0.75.1 () {48 vars in 3213 bytes} [Tue Apr 30 04:20:56 2019] GET /api/holidays =>generated 273 bytes in 4 msecs (HTTP/1.1 401) 2 headers in 82 bytes (1 switches on core 0)"}
{"timestamp":30-04-2019 04:21:00, "source": "app", "level":"INFO", "message":"/login - START"}
{"timestamp":30-04-2019 04:21:00, "source": "app", "level":"INFO", "message":"Trying to log in..."}
{"timestamp":30-04-2019 04:21:00, "source": "app", "level":"ERROR", "message":"Exception handling call 'login':
Traceback (most recent call last):
  File "/usr/local/lib/python3.6/site-packages/urllib3/connection.py", line 159, in _new_conn
    (self._dns_host, self.port), self.timeout, **extra_kw)
  File "/usr/local/lib/python3.6/site-packages/urllib3/util/connection.py", line 80, in create_connection
    raise err
  File "/usr/local/lib/python3.6/site-packages/urllib3/util/connection.py", line 70, in create_connection
    sock.connect(sa)
ConnectionRefusedError: [Errno 111] Connection refused"}

我的配置：

logger = uwsgilog stdio
logger = application stdio
log-route = application {
log-route = uwsgilog ^((?!{).)*$
log-encoder = json:uwsgilog {"timestamp":${strftime:%%d-%%m-%%Y %%H:%%M:%%S}, "source": "uWSGI", "level":"INFO", "message":"${msg}"}
log-encoder = format:application ${msg}
logger-req = stdio
log-req-encoder = json {"timestamp":${strftime:%%d-%%m-%%Y %%H:%%M:%%S}, "source": "request", "level":"INFO", "message":"${msg}"}
log-req-encoder = nl