配置 AWS Lambda Python Logging | 隔叶黄莺 Yanbin Blog

2022-01-25 | 阅读(547)

通常在 Python 应用中简单的配置使用内置的 logging 是这样的

import logging

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
logging.basicConfig(level=logging.INFO, format=logging_format)

logging.info('hello world')

import logging

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'

logging.basicConfig(level=logging.INFO, format=logging_format)

logging.info('hello world')

假如文件名为 test.py, 用 python test.py 执行后输出

2022-01-25 21:02:47,231 - INFO - test(<module>:6) - hello world

在 Lambda 中的现象

可是这同样的代码放到 AWS Lambda Python 代码中却不灵验了，logging.info() 将得不到任何输出。

import json
import logging


def lambda_handler(event, context):
    logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
    logging.basicConfig(level=logging.INFO, format=logging_format)
    
    logging.info('hello world')
    
    return {
        'statusCode': 200,
        'body': json.dumps('Hello from Lambda!')
    }

import json

import logging

def lambda_handler(event, context):

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'

logging.basicConfig(level=logging.INFO, format=logging_format)

logging.info('hello world')

return {

'statusCode': 200,

'body': json.dumps('Hello from Lambda!')

}

在 Lambda 中高亮行 logging.info('hello world' 没有输出，

START RequestId: c06cd902-7e80-49ec-8a6e-d9b11999d55b Version: $LATEST
END RequestId: c06cd902-7e80-49ec-8a6e-d9b11999d55b

但把它改成

logging.error('hello world')

1	logging.error('hello world')

就行了

START RequestId: dec1e35c-296a-4dd3-a52b-e49b9fc3cafe Version: $LATEST
[ERROR] 2022-01-26T03:10:17.920Z dec1e35c-296a-4dd3-a52b-e49b9fc3cafe hello world
END RequestId: dec1e35c-296a-4dd3-a52b-e49b9fc3cafe

问题分析

有了以上的现象，我们就能开始分析问题了

首先 Python 的内置 logging 在 AWS Lambda 中是可以工作的
logging.basicConfig(level=logging.INFO) 改变不了 logging 的默认输出级别(默认为 ERROR)
想要改变 logging 的默认级别需从它处下手

于是 Google, 在 AWS 的 Working with Python/Logging library 中提到用下面方式在 Lambda 中修改默认 Logger 级别

import logging
logger = logging.getLogger()
logger.setLevel(logging.INFO)

logging.info('hello world')

import logging

logger = logging.getLogger()

logger.setLevel(logging.INFO)

logging.info('hello world')

INFO 级别的日志能够被输出

START RequestId: 5ac709c9-b741-4330-a2ca-3974ef188a33 Version: $LATEST
[INFO] 2022-01-26T03:17:39.884Z 5ac709c9-b741-4330-a2ca-3974ef188a33 hello world
END RequestId: 5ac709c9-b741-4330-a2ca-3974ef188a33

继续问题

是什么让 logging.basicConfig() 不再生效呢？
如何定制 Lambda 中 logging 输出的格式？

显示 Lambda 在启动 Python 代码前有所动作，这就把我们拉回到了我之前的构建 AWS Lambda Python Docker 镜像文中一个相关问题，AWS 是通过 awslambdaric 启动 Lambda 的，到源代码中寻着它的 __main__ 到 bootstrap, 看到 https://github.com/aws/aws-lambda-python-runtime-interface-client/blob/main/awslambdaric/bootstrap.py#L375

logging.Formatter.converter = time.gmtime
logger = logging.getLogger()
logger_handler = LambdaLoggerHandler(log_sink)
logger_handler.setFormatter(
    logging.Formatter(
        "[%(levelname)s]\t%(asctime)s.%(msecs)dZ\t%(aws_request_id)s\t%(message)s",
        "%Y-%m-%dT%H:%M:%S",
    )
)
logger_handler.addFilter(LambdaLoggerFilter())
logger.addHandler(logger_handler)
...
request_handler = _get_handler(handler)
...
while True:
    ...
    handle_event_request(
        lambda_runtime_client,
        request_handler,
....

logging.Formatter.converter = time.gmtime

logger = logging.getLogger()

logger_handler = LambdaLoggerHandler(log_sink)

logger_handler.setFormatter(

logging.Formatter(

"[%(levelname)s]\t%(asctime)s.%(msecs)dZ\t%(aws_request_id)s\t%(message)s",

"%Y-%m-%dT%H:%M:%S",

)

logger_handler.addFilter(LambdaLoggerFilter())

logger.addHandler(logger_handler)

...

request_handler = _get_handler(handler)

...

while True:

...

handle_event_request(

lambda_runtime_client,

request_handler,

....

原因就在这个 Handler，handler 中的格式设置优先于 logging.basicConfig() 的配置。我们立马对 handler 的功能进行一个测试

test.py

handler = logging.StreamHandler()
formatter = logging.Formatter('<DEMO> %(asctime)s - %(name)s - %(levelname)s - %(message)s')
handler.setFormatter(formatter)

logger = logging.getLogger()
logger.setLevel(logging.DEBUG)
logger.addHandler(handler)

logger.debug('debug message - 1')
logging.debug('debug message - 2')

handler = logging.StreamHandler()

formatter = logging.Formatter('<DEMO> %(asctime)s - %(name)s - %(levelname)s - %(message)s')

handler.setFormatter(formatter)

logger = logging.getLogger()

logger.setLevel(logging.DEBUG)

logger.addHandler(handler)

logger.debug('debug message - 1')

logging.debug('debug message - 2')

上面给 logger.addHandler() 加了一个 handler, 在 handler 中设置了 format, 并对 logging.getLogger() 设置了默认 DEBUG 级别。看用 python test.py 得到的输出

<DEMO> 2022-01-25 21:44:18,671 - root - DEBUG - debug message - 1
<DEMO> 2022-01-25 21:44:18,671 - root - DEBUG - debug message - 2

在有 handler 的情况下，logging 和 logging.getLogger() 的日志输出方法同时受到 logger.setLevel() 和 handler 的影响。

再做个测试

logging.basicConfig(level=logging.INFO, format='<DEMO> %(asctime)s - %(name)s - %(levelname)s - %(message)s')

logger = logging.getLogger('abc')

logger.info('info message - 1')
logging.info('info message - 2')

logging.basicConfig(level=logging.INFO, format='<DEMO> %(asctime)s - %(name)s - %(levelname)s - %(message)s')

logger = logging.getLogger('abc')

logger.info('info message - 1')

logging.info('info message - 2')

python test.py 后

<DEMO> 2022-01-25 22:13:54,277 - abc - INFO - info message - 1
<DEMO> 2022-01-25 22:13:54,277 - root - INFO - info message - 2

说明，在没有 handler 的情况下，logging.basicConfig() 也同时影响到 logging 和 logging.getLogger() 的日志输出。

多种解决办法

明白了这以后，我们就可以对 AWS Lambda 中的代码进行干预，如果有 logging.getLogger.handlers 的话就把 handlers[0] 中的 formatter 改了, level 的改变调用 logging.getLogger().setLevel(loggin.INFO) 即可。

修改 Lambda 内置的 logger handler

这样修改 Lambda

import json
import logging

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
logger = logging.getLogger()
if logger.handlers:  # for AWS Lambda
    logger.handlers[0].setFormatter(logging.Formatter(logging_format))
    logger.setLevel(logging.INFO)


def lambda_handler(event, context):
    logging.info('hello world')
    
    return 'Hello from Lambda!'

import json

import logging

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'

logger = logging.getLogger()

if logger.handlers: # for AWS Lambda

logger.handlers[0].setFormatter(logging.Formatter(logging_format))

logger.setLevel(logging.INFO)

def lambda_handler(event, context):

logging.info('hello world')

return 'Hello from Lambda!'

执行后输出为

START RequestId: 136693dc-e114-4986-b11c-3c7f5af925a0 Version: $LATEST
2022-01-26 03:54:23,265 - INFO - lambda_function(lambda_handler:12) - hello world
END RequestId: 136693dc-e114-4986-b11c-3c7f5af925a0

移除 Lambda 注册的 Logger Handler

或者蛮横一点，把 awslambdaric 注册的 logger Handler 整个拿掉，logging.basicConfig 又能再次用上

import json
import logging

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
logger = logging.getLogger()
for handler in logger.handlers:  # for AWS Lambda
    logger.removeHandler(handler)
    
logging.basicConfig(level=logging.INFO, format=logging_format)


def lambda_handler(event, context):
    logging.info('hello world')
    
    return 'Hello from Lambda!'

import json

import logging

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'

logger = logging.getLogger()

for handler in logger.handlers: # for AWS Lambda

logger.removeHandler(handler)

logging.basicConfig(level=logging.INFO, format=logging_format)

def lambda_handler(event, context):

logging.info('hello world')

return 'Hello from Lambda!'

这样无论 awslambdaric 在自定义的 Logger Handler 中加了什么功能都被无视

针对性的解决办法

本最后采取的是一种更保守的方式，由于自己的包被 ECS 和 Lambda 共用，所以在包的 __init__.py 文件中加上了

import logging


def init_logging():
    logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
    logger = logging.getLogger()
    if logger.handlers:  # for AWS Lambda
        logger.handlers[0].setFormatter(logging.Formatter(logging_format))
        logger.setLevel(logging.INFO)
    else:
        logging.basicConfig(level=logging.INFO, format=logging_format)


init_logging()

import logging

def init_logging():

logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'

logger = logging.getLogger()

if logger.handlers: # for AWS Lambda

logger.handlers[0].setFormatter(logging.Formatter(logging_format))

logger.setLevel(logging.INFO)

else:

logging.basicConfig(level=logging.INFO, format=logging_format)

init_logging()

其实只要把上面的代码放到能被执行到的地方就行。

用 basicConfig 的 force=True 清除已有 Handlers[2024-10-21 增补]

这是继对 Python logging 更深入研究 Python logging 使用笔记之后找到的更简单方法, 做法是

import logging
from logging import StreamHandler

stdout_handler = StreamHandler()
logging.basicConfig(level=logging.INFO, force=True, handlers=[stdout_handler])

import logging

from logging import StreamHandler

stdout_handler = StreamHandler()

logging.basicConfig(level=logging.INFO, force=True, handlers=[stdout_handler])

force=True 会强制清除 logging 中已注册的所有 handler 及与之关联的 filter.

关于 Logger Name

最后补充一下关于 logger 名称的内容

logger 名称，在 format 中用 %(name)s 输出
logging.info() 和 logging.getLogger().info() 的 logger name 都是 root
每个模块中用 logging.getLogger(__name__) 是常用的方式，这时候的 logger name 是完整包名和模块名，如 pk1.pk2.md1
只想用模块名的话就用 logging.getLogger('md1')，写成 logging.getLogger(__name__.split('.')[-1]) 估计太麻烦了
最后一种便捷的方式，统一用 logging.xxx() 输出日志，都是 root, 不用管它，format 中用 %(module)s 假装把模块名当 logger 名来显示

链接：

本文链接 https://yanbin.blog/config-aws-lambda-python-logging/, 来自隔叶黄莺 Yanbin Blog

best coffee on SciPy 最优化之最小化I wanted to take a moment to commend you on the outstanding quality of...
seetimee on 体验 Python FastAPI 的并发能力及线, 进程模型感谢
Yanbin on Mockito 3.4.0 开始可 Mock 静态方法有一个补救，新写了一篇 https://yanbin.blog/mockito-mock-static-method-in-multiple...
Yanbin on 升级到 Spring Boot 3 后 javax.inject.Named 不可用怎么，被抄袭了！算是被机器翻译引用的？
oleksi on 升级到 Spring Boot 3 后 javax.inject.Named 不可用https://www.springcloud.io/post/2023-02/springboot-3-javax-inject-name...