配置 AWS Lambda Python Logging

calendar Jan 25, 2022   ---   · 4 min read · lambda AWS logging  ·
Share on: linkedin copy
通常在 Python 应用中简单的配置使用内置的 logging 是这样的
1import logging
2
3logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
4logging.basicConfig(level=logging.INFO, format=logging_format)
5
6logging.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() 将得不到任何输出。
 1import json
 2import logging
 3
 4
 5def lambda_handler(event, context):
 6    logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
 7    logging.basicConfig(level=logging.INFO, format=logging_format)
 8    
 9    logging.info('hello world')
10    
11    return {
12        'statusCode': 200,
13        'body': json.dumps('Hello from Lambda!')
14    }

在 Lambda 中高亮行 logging.info('hello world' 没有输出，
START RequestId: c06cd902-7e80-49ec-8a6e-d9b11999d55b Version: $LATEST
END RequestId: c06cd902-7e80-49ec-8a6e-d9b11999d55b
但把它改成
1logging.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

问题分析

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

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

于是 Google, 在 AWS 的 Working with Python/Logging library 中提到用下面方式在 Lambda 中修改默认 Logger 级别
1import logging
2logger = logging.getLogger()
3logger.setLevel(logging.INFO)
4
5logging.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
继续问题

  1. 是什么让 logging.basicConfig() 不再生效呢？
  2. 如何定制 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
 1logging.Formatter.converter = time.gmtime
 2logger = logging.getLogger()
 3logger_handler = LambdaLoggerHandler(log_sink)
 4logger_handler.setFormatter(
 5    logging.Formatter(
 6        "[%(levelname)s]\t%(asctime)s.%(msecs)dZ\t%(aws_request_id)s\t%(message)s",
 7        "%Y-%m-%dT%H:%M:%S",
 8    )
 9)
10logger_handler.addFilter(LambdaLoggerFilter())
11logger.addHandler(logger_handler)
12...
13request_handler = _get_handler(handler)
14...
15while True:
16    ...
17    handle_event_request(
18        lambda_runtime_client,
19        request_handler,
20....

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

test.py
 1handler = logging.StreamHandler()
 2formatter = logging.Formatter('<DEMO> %(asctime)s - %(name)s - %(levelname)s - %(message)s')
 3handler.setFormatter(formatter)
 4
 5logger = logging.getLogger()
 6logger.setLevel(logging.DEBUG)
 7logger.addHandler(handler)
 8
 9logger.debug('debug message - 1')
10logging.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 的影响。

再做个测试
1logging.basicConfig(level=logging.INFO, format='<DEMO> %(asctime)s - %(name)s - %(levelname)s - %(message)s')
2
3logger = logging.getLogger('abc')
4
5logger.info('info message - 1')
6logging.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
 1import json
 2import logging
 3
 4logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
 5logger = logging.getLogger()
 6if logger.handlers:  # for AWS Lambda
 7    logger.handlers[0].setFormatter(logging.Formatter(logging_format))
 8    logger.setLevel(logging.INFO)
 9
10
11def lambda_handler(event, context):
12    logging.info('hello world')
13    
14    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 又能再次用上
 1import json
 2import logging
 3
 4logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
 5logger = logging.getLogger()
 6for handler in logger.handlers:  # for AWS Lambda
 7    logger.removeHandler(handler)
 8    
 9logging.basicConfig(level=logging.INFO, format=logging_format)
10
11
12def lambda_handler(event, context):
13    logging.info('hello world')
14    
15    return 'Hello from Lambda!'

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

针对性的解决办法

本最后采取的是一种更保守的方式，由于自己的包被 ECS 和 Lambda  共用，所以在包的  __init__.py 文件中加上了
 1import logging
 2
 3
 4def init_logging():
 5    logging_format = '%(asctime)s - %(levelname)s - %(module)s(%(funcName)s:%(lineno)d) - %(message)s'
 6    logger = logging.getLogger()
 7    if logger.handlers:  # for AWS Lambda
 8        logger.handlers[0].setFormatter(logging.Formatter(logging_format))
 9        logger.setLevel(logging.INFO)
10    else:
11        logging.basicConfig(level=logging.INFO, format=logging_format)
12
13
14init_logging()

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

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

这是继对 Python logging 更深入研究 Python logging 使用笔记 之后找到的更简单方法, 做法是
1import logging
2from logging import StreamHandler
3
4stdout_handler = StreamHandler()
5logging.basicConfig(level=logging.INFO, force=True, handlers=[stdout_handler])

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

关于 Logger Name

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

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

链接：

  1. Using python Logging with AWS Lambda
  2. change_lambda_logger_format.py
  3. AWS Lambda Python Logging: A Quick Guide
永久链接 https://yanbin.blog/config-aws-lambda-python-logging/, 来自 隔叶黄莺 Yanbin's Blog
[版权声明] 本文采用 署名-非商业性使用-相同方式共享 4.0 国际 (CC BY-NC-SA 4.0) 进行许可。