AWS Java Lambda 使用 Logback 记录日志

calendar Mar 18, 2017 · 7 min read · lambda  ·
Share on: linkedin copy
直接一句话：去掉 Log4J 的依赖，把  Slf4J, Logback, 和 log4j-over-slf4j 依赖加进来就行了，配置文件换成 logback.xml，这就完了，不要往下看了，都是些废话。

当我们用 Serverless 命令 sls create -t aws-java-maven -p hello-lambda 创建的示例项目中直接用的是 Log4J 日志组件，而且也没用像  Slf4j, 或 Apache Common Logging 更上一层的通用日志框架。查看了几个 AWS 本身的组件 S3, SNS, 和 Kinesis 的 SDK, 它们内部是用的 Apache Common Logging 声明的日志变量
import org.apache.commons.logging.LogFactory;
import org.apache.commons.logging.Logger;

private static final Log log = LogFactory.getLog(AmazonKinesis.class)
而我们自己的组件中通用日志组件是 Slf4j, 底层实现为 Logback, 所以我们希望在 Lambda 中使用 Logback 来写日志。
选用一个通用日志框架总是明智之举，因为一个项目经常杂糅了多种日志实现，使用 Slf4J 或 Apache Common Logging 可以把它们(Log4J, Logback, 或更多)输出到共同的目的地，并且有统一的日志输出接口。而我们认为通用日志框架还是 Slf4J 要先进些，所以我们在 Java Lambda 中的日志方案是 Slf4J + Logback，还需要把 Log4J 的日志桥接到 Slf4J 上来，再经由 Logback 输出。

回到前面创建的 hello-lambda 项目，看其中怎么用的 Log4J，先瞧瞧 pom.xml 文件怎么引入的 Log4J, 它是间接通过一个 AWS 定义的 Log4J Appender 引入的
1<dependency>
2    <groupId>com.amazonaws</groupId>
3    <artifactId>aws-lambda-java-log4j</artifactId>
4    <version>1.0.0</version>
5</dependency>
这个 AWS 定义的 Appender 是怎么用的呢？看 log4j.properties 文件的内容
1log = .
2log4j.rootLogger = DEBUG, LAMBDA
3log4j.appender.LAMBDA=com.amazonaws.services.lambda.runtime.log4j.LambdaAppender
4log4j.appender.LAMBDA.layout=org.apache.log4j.PatternLayout
5log4j.appender.LAMBDA.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss} <%X{AWSRequestId}> %-5p %c:%L - %m%n
看到这个 Log4J 的配置文件我最感兴趣的要数 <%X{AWSRequestId}>, 它能指示出触发 Lambda 的请求 ID, 在后面的 Logback 我也想要它。

看一下 hello-lambda 的日志输出吧，最简单的 handler
 1package cc.unmi;
 2import java.util.Map;
 3import org.apache.log4j.Logger;
 4import com.amazonaws.services.lambda.runtime.Context;
 5import com.amazonaws.services.lambda.runtime.RequestHandler;
 6public class Handler implements RequestHandler<Map<String, Object>, String> {
 7    
 8    private static final Logger LOG = Logger.getLogger(Handler.class);
 9    @Override
10    public String handleRequest(Map<String, Object> input, Context context) {
11        LOG.info("received: " + input);
12        return context.getFunctionName();
13    }
14}
Serverless  的项目可以用命令 mvn package; sls deploy 打包并部署到 AWS 上去, 简单测试，上面的 LOG.info() 的输出如下
2017-03-18 05:10:19 <2e65ba82-0b99-11e7-a827-454505660a82> INFO  cc.unmi.Handler:16 - received: {key1=value1}
在 %X{AWSRequestId} 处输出了当前请求 ID 信息，这在 Lambda 并发时很容易区别不同请求的日志信息。

再看下它是怎么输出 AWS 自家组件中的日志信息的，尝试读一下 S3 Object。这里 Log4J 的日志级别是 DEBUG; 项目中要用到 aws-java-sdk-s3, 引入方式不多解释。在 handleRequest(...) 方法中相应代码如下
AmazonS3 amazonS3 = AmazonS3ClientBuilder.defaultClient();
amazonS3.getObject("test-bucket", "test-file.txt");  //可建立相应的 S3 bucket 和相应的文件，没也可以看日志
这个获得 S3 Object 的信息很详细，还没触及文件内容，否则每一行的文件内容都能看到，为了不占太大篇幅，用一个滚动的 TextArea 来显示, 请滚动过目



有些调试信息对我们使用 AWS 的资源还是很有帮助的。

到此，可以设定我们的目标了

  1. 使用 Slf4J 通用日志组件，底层实现用 Logback 替换掉 Log4J
  2. 把 AWS 自家组件中 Log4J 的日志信息通过 Slf4J -> Logback 输出
  3. 在 Logback 的每一条日志中也要能输出 AWSRequestId 信息

使用 Slf4J + Logback

去掉 Log4J 依赖，加上 Slf4J + Logback 依赖

在 pom.xml 中把 com.amazonaws:aws-lambda-java-log4j 依赖删掉便 Log4J 也没啦，接着加上 Logback 的依赖
1<dependency>
2    <groupId>ch.qos.logback</groupId>
3    <artifactId>logback-classic</artifactId>
4    <version>1.1.7</version>
5</dependency>
因为 Logback 不爱单独行事，默认使用 Slf4J 作为它的上层通用日志框架，所以上面也把 org.slf4j:slf4j-api 依赖传递进来了。

logback.xml 配置文件

在 resources 目录中创建 logback.xml 文件，内容可如下
 1<?xml version="1.0" encoding="UTF-8"?>
 2<configuration scan="false" debug="false">
 3    <statusListener class="ch.qos.logback.core.status.NopStatusListener"/><br/>
 4    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
 5        <encoder>
 6            <pattern>
 7                %d{yyyy-MM-dd HH:mm:ss} [%thread] %-5level %logger{36} - %msg%n
 8            </pattern>
 9        </encoder>
10    </appender><br/>
11    <root level="DEBUG">
12        <appender-ref ref="STDOUT"/>
13    </root><br/><br/>
14</configuration>
我们也设定了日志级别为 DEBUG.

使用 Slf4J 日志接口

把之前的 Log4J 日志代码改成 Slf4J 通用日志代码，完整的一个 Lambda Handler 如下
 1package cc.unmi;
 2import java.util.Map;
 3import com.amazonaws.services.lambda.runtime.Context;
 4import com.amazonaws.services.lambda.runtime.RequestHandler;
 5import org.slf4j.Logger;
 6import org.slf4j.LoggerFactory;
 7public class Handler implements RequestHandler<Map<String, Object>, String> {
 8    private static final Logger logger = LoggerFactory.getLogger(Handler.class);
 9    @Override
10    public String handleRequest(Map<String, Object> input, Context context) {
11        logger.info("received: " + input);
12        return context.getFunctionName();
13    }
14}
部署到 AWS 上进行测试，查看日志输出如下
2017-03-18 05:52:48 [main] INFO  cc.unmi.Handler - received: {key1=value1}
得到我们想要的输出，这个目标很简单

Log4J 的日志桥接到 Slf4J, 再用 Logback 输出


再来测试一下前面那段 S3 Object 的获取代码，加下两行到 handleRequest(...) 方法中去
1AmazonS3 amazonS3 = AmazonS3ClientBuilder.defaultClient();
2amazonS3.getObject("test-bucket", "text-file.txt");
部署再测试，我们发现在 Logback 已是 DEBUG 级别的情况下，只有一行日志输出

2017-03-18 06:00:08 [main] INFO  cc.unmi.Handler - received: {key1=value1}
没有处理 S3 getObject(...) 的详细日志输出，也就是原本在 AWS 自家组件中用 Log4J 打印的里层我们不会跑到 Logback 上来。原因是我们缺少 log4j-over-slf4j, 所以 Log4J 的日志输出在拿掉了 Log4J 依赖后不知道往何处去。

加上 log4j-over-slf4j 依赖

在 pom.xml 文件中加上
1<dependency>
2    <groupId>org.slf4j</groupId>
3    <artifactId>log4j-over-slf4j</artifactId>
4    <version>1.7.21</version>
5</dependency>
部署再触发执行，现在可以看到前面那个文本框中一样详细的调试信息输出了，一个获取 S3 Object  的细节信息一览无余。现在还差最后一个问题了。

要注意的是 log4j-over-slf4j.jar 与 slf4j-log4j12.jar 是不能共存的，应用启动时就会有冲突报出来。 参见  Bridging legacy APIs

在 Logback 日志中输出 AWSRequestId


其实这个才是重点，前面还真完全是些废话，简单就是一句话：去掉 Log4J 的依赖，把  Slf4J, Logback, 和 log4j-over-slf4j 依赖加进来就行了，配置文件换成 logback.xml。

既然这个是关键就应该单飞了，继续研究, 草稿中 ......