Spring Boot Web 输出 Tomcat 的访问日志到控制台

Oct 26, 2022 --- · 5 min read · AWS EC2 AccessLog ECS ·

Share on:

当我们直接使用 Tomcat 时，访问日志的配置在 $TOMCAT_HOME/conf/server.xml 中

<Valve className="org.apache.catalina.valves.AccessLogValve" directory="logs"
prefix="localhost_access_log" suffix=".txt"
pattern="%h %l %u %t "%r" %s %b" />

产生的日志文件在 $TOMCAT_HOME/logs 目录中，生成以日期戳进行区分的滚动日志文件，如 localhost_access_log.2022-10-25.txt 等

而在我们使用 Spring Boot Web 时, 默认的嵌入式 Web 应用服务器是 Tomcat，我们可以在 Spring 属性文件中配置是否启用 Tomcat 访问日志(默认不启用)。属性文件中的配置针对的是如何输出访问日志到文件，而我们有时候需要输出访问日志到控制台而不非文件，比如 AWS 上的 ECS 应用，控制台的输出可直接发送到 CloudWatch，这样便于分析日志。

在 Spring Web 中可以用 Interceptor 或 Filter 来记录访问日志，但在请求出错时无法准确显示出响应时间和状态码，毕竟 Tomcat 的访问日志在代码的外层，进出 Controller 方法的输入输出信息也就掌握的更清楚。

本文的任务是探索输出 Spring Boot Web 嵌入式 Tomcat 的访问日志到控制台。有两种方式

配置特殊输出设备文件 /dev/stdout 引导 Tomcat 输出访问日志到控制台
定制 Tomcat 的 AccessLogValve，获取到访问日志记录，然后自己控制输出，直接 Sytem.out.println 或由通用日志框架(slf4 等) 输出

关于访问日志的配置可在 Spring 属性文件(application.properties 或 yaml 文件) 中定制，属性名为 server.tomcat.accesslog.* 等一系列配置中。在 Spring Common Application Properties 页面中搜索 server.tomcat.accesslog. 下面列出相关的属性, 说明及默认值，按大概的关注度由强及弱排列

server.tomcat.accesslog.enabled: 是否开启访问日志，默认为 false
server.tomcat.accesslog.directory: 访问日志目录，可用绝对或相对目录(相对于 Tomcat Base 目录)，默认为 logs
server.tomcat.accesslog.prefix: 日志文件名前缀，默认为 access_log
server.tomcat.accesslog.suffix: 日志文件名后缀，默认为 .log
server.tomcat.accesslog.pattern: 日志记录行输出格式，默认为 common, 即 %h %l %u %t "%r" %s %b
server.tomcat.accesslog.file-date-format: 插入到日志文件名中的日期格式，默认为 .yyyy-MM-dd, 所以结合 prefix, suffix, 最后的文件名就像 localhost_access_log.2022-10-25.log
server.tomcat.accesslog.condition-if: 如果设置了值为 "needLog", 那么只有请求的 ServletRequest.getAttribute("needLog") 不为 null 时才记录; 默认为空，即所有的访问都被记录
server.tomcat.accesslog.condition-unless: 如果设置了值为 "excludeLog" 的话，只有 ServletRequest.getAttribute("excludeLog") 为 null 时才记录; 默认为空，即所有访问都被记录
server.tomcat.accesslog.rotate: 是否滚动访问日志文件，默认是 true
server.tomcat.accesslog.rename-on-rotate: 日志文件名是否含有时间戳，直到被滚动时才加上时间戳。默认为 false，表示当前日志文件名含有时间戳
server.tomcat.accesslog.max-day: 访问日志保留的最大天数，默认为 -1, 表示永远
server.tomcat.accesslog.buffered: 在输出日志内容到文件前是否缓存, 缓存中的内容被定期刷到文件中，默认为 true。缓存到减少日志输出对正常业务代码的性能影响
server.tomcat.accesslog.check-exists: 是否检查日志文件是否存在，比如在外部重命名了日志文件后会重新创建，默认为 false
server.tomcat.accesslog.encoding: 日志文件的字符集，默认为系统默认字符集
server.tomcat.accesslog.locale: 产生时间戳所用的区域(Locale)，默认为 Java 的默认 local
server.tomcat.accesslog.request-attributes-enabled: 是否把 IP 地址，Hostname, 协议，端口号附加到 Request 中去，默认为 false
server.tomcat.accesslog.ipv6-canonical: 是否使用 IPv6 的规范格式，默认为 false

如果在 Spring Boot 中引入的不是 Tomcat，比如 undertow, 那么相应的访问日志配置属性就是 server.undertow.accesslog.*。

上面的属性对应到 org.springframework.boot.autoconfigure.web.ServerProperties.Tomcat.Accesslog, org.apache.catalina.values.AccessLogValve 和 org.apache.catalina.values.AbstractAccessLogValve 中的属性。

输出访问日志到 /dev/stdout(标准输出)

在进行实质性配置之前看一下只是单单启用 server.tomcat.accesslog.enabled=true ，其他属性全保持默认值时的访问日志在哪里。为此我们先在 application.properties 中加上一行

1server.tomcat.accesslog.enabled=true

根据其他属性的默认值，我们可此访问日志文件将会是 logs/access_log.2022-10-26.log (写作时的日期), 这是一个相对路径，相对目录是 System.getProperty("catalina.home"), 比如在 Mac OS X 下在一次 Spring Boot Web 应用启动后输出的值为

/private/var/folders/hz/h515j94x4ls272nvxf3pqt800000gq/T/tomcat.8080.17520809821230678569

访问了一次 /test 后，产生的日志文件可见如下

$ ~ ls /private/var/folders/hz/h515j94x4ls272nvxf3pqt800000gq/T/tomcat.8080.17520809821230678569
logs work
$ ~ ls /private/var/folders/hz/h515j94x4ls272nvxf3pqt800000gq/T/tomcat.8080.17520809821230678569/logs
access_log.2022-10-26.log
$ ~ cat /private/var/folders/hz/h515j94x4ls272nvxf3pqt800000gq/T/tomcat.8080.17520809821230678569/logs/access_log.2022-10-26.log
0:0:0:0:0:0:0:1 - - [26/Oct/2022:10:08:53 -0500] "GET /test HTTP/1.1" 200 12

创建文件输出流来输出内容到控制台可用下面的方式

1FileOutputStream out = new FileOutputStream("/dev/stdout");
2out.write("hello".getBytes());

执行后控制台输出为

hello

由此，我们可以让 Tomcat 认为输出文件是 /dev/stdout 这一绝对文件路径，为达到此目的，我们必须原本访问日志文件的中，后缀置空掉，最后的 Spring 属性配置如下

1server.tomcat.accesslog.enabled=true
2server.tomcat.accesslog.directory=/dev
3server.tomcat.accesslog.prefix=stdout
4server.tomcat.accesslog.buffered=false
5server.tomcat.accesslog.suffix=
6server.tomcat.accesslog.file-date-format=

这样 Tomcat 就会乖乖的输出访问日志到 /dev/stdout，关闭缓存的目的是要立即看到访问日志输出。

如果我们对它进行追根溯源的话，可以找到线索

 1ServletWebServerApplicationContext.createWebServer()
 2        getWebServerFactory()
 3             WebServerFactoryCustomizerBeanPostProcessor.postProcessBeforeInitialization(WebServerFactory webServerFactory)
 4                    beanFactory.getBeansOfType(WebServerFactoryCustomizer.class)
 5                           webServerFactoryCustomizer.customize(webServerFactory)
 6                                TomcatWebServerFactoryCustomizer.customize(webServerFactory)
 7                                    propertyMapper.from(tomcatProperties::getAccesslog).when(ServerPropperties.Tomcat.Accesslog::isEnabled)
 8                                                                  .to(enabled -> customizeAccessLog(configurableTomcatWebServerFactory)
 9                                          AccessLogValve valve = new AccessLogValve();
10                                          Accesslog accessLogConfig = tomcatProperties.getAccesslog();
11                                          map.from(accessLogConfig.getPattern()).to(valve::setPattern);
12                                          map.from(accessLogConfig.getDirectory()).to(valve::setDirectory);
13                                          map.from(accessLogConfig.getPrefix()).to(valve::setPrefix);
14                                          ......
15                                          factory.addEngineValues(value)
16
17AccessLogValve.open()
18    getLogFile(boolean useDateStamp)
19        new File(dir.getAbsoluteFile(), prefix + useDateStamp? dateStamp: "" + suffix)

因为 AccessLogValve 最终是用 new File() 来创建访问日志文件的，也就是为什么我们指定输出到 /dev/stdout 便是标准输出控制台了。

从上可知，我们以 Hack 的方式用 /dev/stdout 欺骗了 Spring Boot 使得访问日志输出到了控制台，同时也为我们指明了另一个方向，那就是

用 WebServerFactoryCustomizer 定制 AccessLogValue

从前面的源代码可知 Spring 发现有 WebServerFactoryCustomizer 实例便会调用它的 customize() 方法，所以我们只要声明一个这样的 Bean 就能定制 Tomcat 的 AccessLogValue

创建类 AccessValveConfig

 1package yanbin.blog;
 2
 3import org.apache.catalina.valves.AbstractAccessLogValve;
 4import org.slf4j.Logger;
 5import org.slf4j.LoggerFactory;
 6import org.springframework.boot.web.embedded.tomcat.TomcatServletWebServerFactory;
 7import org.springframework.boot.web.server.WebServerFactoryCustomizer;
 8import org.springframework.context.annotation.Configuration;
 9import org.springframework.stereotype.Component;
10
11import java.io.CharArrayWriter;
12import java.util.List;
13
14@Configuration
15public class AccessValveConfig implements WebServerFactoryCustomizer<TomcatServletWebServerFactory> {
16    private static final Logger logger = LoggerFactory.getLogger(AccessValveConfig.class);
17    private final CustomAccessLogValve customAccessLogValve;
18
19    public AccessValveConfig(CustomAccessLogValve customAccessLogValve){
20        this.customAccessLogValve = customAccessLogValve;
21    }
22
23    @Override
24    public void customize(TomcatServletWebServerFactory factory) {
25        factory.setEngineValues(List.of(customAccessLogValve));
26    }
27
28    @Component
29    public static class CustomAccessLogValve extends AbstractAccessLogValve {
30
31        private static final String pattern = "remote_host=%h, request=%r, status_code=%s, execute_time=%D," +
32                "  bytes_received=%{Content-Length}i, bytes_sent=%b, user_agent=%{User-Agent}i";
33
34        public CustomAccessLogValve(){
35            setConditionUnless("ignore-access-log");   // request.setAttribute("ignore-access-log", "") 的请求不被记录，比如被频繁访问的 health-check
36            setPattern(pattern);
37        }
38
39        @Override
40        protected void log(CharArrayWriter message) {
41            logger.info("TomcatAccessLog: {}", message.toString());
42        }
43    }
44}

现在测试一下，在控制台上会输出

2022-10-26 11:52:35.301 INFO 34986 --- [nio-8080-exec-1] yanbin.blog.AccessValveConfig : remote_host=0:0:0:0:0:0:0:1, request=GET /test HTTP/1.1, status_code=200, execute_time=56, bytes_received=-, bytes_sent=12, user_agent=curl/7.64.1

日志是通过 SLFJ 输出来的，timestamp, 线程信息由 SLFJ 负责

有关于访问日志的 pattern 及定制

当我们在定制 pattern 时，了解它是如何获取各种信息的很重要。前面提到过内置的可用字段可以在 org.apache.catalina.values.AbstractAccessLogValve 中找到，如 %a, %A, %r 等，以及用 ${xxx}i, %{xxx}o, %{xxx}c, %{xxx}r, %{xxx}s 可分别从请求头(i), 响应头(o), cookie(c), Request attribute(r), Session attribute(s) 中提取属性值。它们的实现在 org.apache.Catalina.values.AccessLogElement 子类中，如 ResponseHeaderElement。

假如我们有自己需求的话，比如我们部署在 ECS Container 中应用希望能获得所在 EC2 的 IP 地址，而不是容器的 IP 地址，就可以实现一个 EC2AttributeElement，之后在 pattern 中配置 %{ip}E，为此我们需下面几步

在 Pattern 中加上 %{ip}E

在 CustomAccessLogValve 中覆盖 createAccessLogElement(String name, char pattern) 方法，并在 CustomAccessLogValve 中(因为 AccessLogElement 是一个 protected 类) 创建 Ec2AttributeElement类，相关的代码如下

 1@Component
 2public static class CustomAccessLogValve extends AbstractAccessLogValve {
 3
 4    private static final String pattern = "remote_host=%h, local_host=%{ip}E, request=%r, status_code=%s, execute_time=%D," +
 5            "  bytes_received=%{Content-Length}i, bytes_sent=%b, user_agent=%{User-Agent}i";
 6
 7    public CustomAccessLogValve(){
 8        setConditionUnless("ignore-access-log");
 9        setPattern(pattern);
10    }
11
12    @Override
13    protected AccessLogElement createAccessLogElement(String name, char pattern) {
14        if(pattern == 'E') {
15           return new EC2AttributeElement(name);
16        }
17        return super.createAccessLogElement(name, pattern);
18    }
19
20    private static class EC2AttributeElement implements AccessLogElement {
21
22        private final String attrName;
23
24        public EC2AttributeElement(String attrName) {
25            this.attrName = attrName;
26        }
27
28        @Override
29        public void addElement(CharArrayWriter buf, Date date, Request request, Response response, long time) {
30            // curl http://169.254.169.254/latest/meta-data/local-ipv4
31            if("ip".equals(attrName)) {
32                String ipUrl = "http://169.254.169.254/latest/meta-data/local-ipv4";
33                try(InputStream is = (InputStream) new URL(ipUrl).getContent()){
34                    String ip = new Scanner(is).next();
35                    buf.append(ip);
36                } catch (IOException e) {
37                    buf.append("??");
38                }
39            } else {
40                buf.append("-");
41            }
42        }
43    }
44
45    
46    @Override
47    protected void log(CharArrayWriter message) {
48        logger.info(message.toString());
49    }
50}

在 ECS 容器中可通过 curl http://169.254.169.254/latest/meta-data/local-ipv4 获得所在 EC2 实例的 IP 地址, 前面的代码还应把第一次成功解析出来的 IP 地址缓存起来，后续直接使用。

最后，部署到 EC2 的 Docker 容器中的 Spring Boot Web 的访问日志就会像

2022-10-26 12:43:51.253 INFO 36843 --- [nio-8080-exec-1] yanbin.blog.AccessValveConfig : remote_host=0:0:0:0:0:0:0:1, local_host=192.168.86.23, request=GET /test HTTP/1.1, status_code=200, execute_time=56, bytes_received=-, bytes_sent=12, user_agent=curl/7.64.1

备注：

无法是在 EC2 还是在 EC2 上运行的 ECS 容器中都可以通过 http://169.254.169.254/latest/meta-data/ 获得相应的 EC2 实例的信息，如

[root@xyz-01234567 ~]# curl http://169.254.169.254/latest/meta-data/
ami-id
ami-launch-index
ami-manifest-path
autoscaling/
block-device-mapping/
events/
hostname
iam/
identity-credentials/
instance-action
instance-id
instance-life-cycle
instance-type
local-hostname
local-ipv4
mac
metrics/
network/
placement/
profile
reservation-id
security-groups
services/
[root@xyz-01234567 ~]# curl http://169.254.169.254/latest/meta-data/hostname
ip-192-168-86-23.ec2.internal
[root@lin-01234567 ~]# curl http://169.254.169.254/latest/meta-data/instance-type
t3.small

其他的信息以相同的方式获得

参考：

永久链接 https://yanbin.blog/spring-boot-web-tomcat-access-logs-to-console/, 来自隔叶黄莺 Yanbin's Blog
[版权声明]

本文采用署名-非商业性使用-相同方式共享 4.0 国际 (CC BY-NC-SA 4.0) 进行许可。