当 Logback-Access 遇见 SpringBoot ！

Posted 2021-04-25 蜗牛小鼓

使用 logback 来收集一个 springboot 应用的运行日志，这个网上很常见而且资料也非常多了，今天要说的是 logback 提供的另一个 logback-access 的模块，可以用它来收集应用的访问日志，这个是怎么回事，一起来看看吧。

---

前言

logback-access 的官方文档上介绍了如何来收集 tomcat 的日志：

这里的方式是通过服务器的配置文件来实现的，我们知道 springboot 使用了内置的 web 容器，tomcat 也是嵌入式的，这一点官网并没有给出更多的资料。

标题既然说了是 logback 收集 springboot 的访问日志，那么不用担心，咱们肯定是有招的，不妨接着往下看吧。

原来，早已经有老外也遇到了这个问题，而且他们也自己实现了一个 logback-access-spring-boot-starter ，有了它我们也可以在 springboot 里边收集访问日志了。

这个 starter 实现了 tomcat、jetty、undertow 三个web容器与 springboot 的整合，我们以 tomcat 为 web 容器，logstash 为日志输出目的，来实现收集访问日志的功能。

可以先看下最终在 logstash 中输出的日志片段:

{
        "httpStatus" => "200",
    "requestMapping" => "/foo/bar",
     "requestParams" => "{\"name\":\"test\",\"age\":18}",
              "type" => "AccessLog",
       "requestHost" => "localhost:52271",
              "port" => 52267,
        "requestURI" => "/foo/bar",
          "@version" => "1",
     "executionTime" => "140",
                "ip" => "127.0.0.1",
        "createTime" => "2020-09-29 11:47:08",
              "host" => "localhost",
        "@timestamp" => 2020-09-29T03:47:08.820Z,
               "pid" => "42358",
        "httpMethod" => "POST"
}
{
        "httpStatus" => "200",
    "requestMapping" => "/foo/person/{name}",
              "type" => "AccessLog",
       "requestHost" => "localhost:52271",
              "port" => 52267,
        "requestURI" => "/foo/person/zhangsan",
          "@version" => "1",
     "executionTime" => "46",
                "ip" => "127.0.0.1",
        "createTime" => "2020-09-29 11:47:08",
              "host" => "localhost",
        "@timestamp" => 2020-09-29T03:47:08.891Z,
               "pid" => "42358",
        "httpMethod" => "GET"
}

可以看到收集到了接口的 requestMapping、请求参数、响应的httpStatus，可以说是非常实用了。

原理

它的请求日志都是 tomcat 在处理完请求后，

会判断下是否有适配了 AccessLogAdapter 的类，

如果有则会去记录访问日志。

正是 logback-access-spring-boot-starter 帮我们干了这个事情，它不仅仅实现了AccessLogAdapter，而且也创建了包含整个请求 request 和 response 的 AccessEvent 对象，AccessEvent 对象与 logback-access 完美的衔接在了一起。

这样我们的工作重点就变成了了解 AccessEvent 中都存储了哪些内容，然后想方设法，把它里边的内容组装到我们要往 logstash 写入的 json 中即可。

这是 AccessEvent 的一部分代码截图：

可以看到最终往 logstash 中写入的内容，大部分这里都能获取到。

实施

jar包引入

先从 https://start.spring.io/ 初始化一个springboot2.0的项目，引入logstash-logback-encoder、logback-access-spring-boot-starter jar包。

dependencies {
 implementation 'org.springframework.boot:spring-boot-starter'
 implementation('net.logstash.logback:logstash-logback-encoder:5.2')
 implementation('net.rakugakibox.spring.boot:logback-access-spring-boot-starter:2.7.1')
}

创建logback-access.xml

不管是是否是内嵌的 tomcat，通过 logback 来收集访问日志，都设置 logback-access.xml 文件。这个文件中几个重要的标签：

• Apperder 日志输出到控制台、logstash、文件等目标中
• Filter 对要收集的日志来进行过滤
• Encoder 格式化日志 最终可以是字符串、json

Appender

使用 LogstashAccessTcpSocketAppender 通过 tcp 方式连接 logstash

Filter

使用自己实现的 UrlPrefixesFilter，通过配置需要记录访问日志的接口前缀，来达到控制的目的。

UrlPrefixesFilter.java：

public class UrlPrefixesFilter extends AbstractMatcherFilter<IAccessEvent> {

    private String prefixes;

    @Override
    public FilterReply decide(IAccessEvent event) {
        if (!isStarted()) {
            return FilterReply.NEUTRAL;
        }
        for (String prefix : prefixes.split(",")) {
            if (event.getRequestURI().toLowerCase().startsWith(prefix)) {
                return onMatch;
            }
        }
        return onMismatch;
    }

    public String getPrefixes() {
        return prefixes;
    }

    public void setPrefixes(String prefixes) {
        this.prefixes = prefixes;
    }

    @Override
    public void start() {
        if (this.prefixes != null) {
            super.start();
        }
    }

}

JsonEncoder

使用最灵活的 AccessEventCompositeJsonEncoder，它里边可以自由的配置 providers。

1. 通过 、 添加时间戳和版本号，
2. 通过表达式来获取 request 和 response 中的内容。比如 "httpMethod": "%m","httpStatus": "%s"分别获取了 请求方法和 响应状态

   关于 requestMapping: "requestMapping" => "/foo/person/{name}"springMvc 在找到处理请求的 requestMapping 后会把命中的接口的 requestMapping 以 key 为 org.springframework.web.servlet.HandlerMapping.bestMatchingPattern 的形式设置到 request 的属性中，这样我们得来全不费功夫，一个  "requestMapping": "%reqAttribute{org.springframework.web.servlet.HandlerMapping.bestMatchingPattern}"，便取到了处理请求的真正的方法上的 requestMapping，结合这个 requestMapping 与 httpMethod 两个值简单分个组就能统计出这个应用中各个接口的访问次数。

3. 通过自定义的 jsonprovider 来获 pid、请求参数等内容 自定义 PidJsonProvider.java:

public class PidJsonProvider extends AbstractFieldJsonProvider<ILoggingEvent> implements FieldNamesAware<LogstashFieldNames> {

    private static final String FIELD_PID = "pid";

    public PidJsonProvider() {
        setFieldName(FIELD_PID);
    }

    @Override
    public void writeTo(JsonGenerator generator, ILoggingEvent event) throws IOException {
        String name = ManagementFactory.getRuntimeMXBean().getName();
        String pid = name.split("@")[0];
        JsonWritingUtils.writeStringField(generator, getFieldName(), pid);
    }

    @Override
    public void setFieldNames(LogstashFieldNames fieldNames) {
        setFieldName(FIELD_PID);
    }

}

这是我的完整的 logback-access.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>

    <!-- logstash tcp  -->
    <appender name="LOGSTASH" class="net.logstash.logback.appender.LogstashAccessTcpSocketAppender">
        <!-- url prefixes filter split by , -->
        <filter class="com.snaildrum.demo.filter.access.UrlPrefixesFilter">
            <prefixes>/foo</prefixes>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <param name="Encoding" value="UTF-8"/>
        <destination>localhost:4560</destination>
        <keepAliveDuration>5 minutes</keepAliveDuration>
        <reconnectionDelay>1 second</reconnectionDelay>
        <writeBufferSize>16384</writeBufferSize>
        <encoder class="net.logstash.logback.encoder.AccessEventCompositeJsonEncoder">
            <providers>
                <timestamp/>
                <version/>
                <pattern>
                    <!-- https://logback.qos.ch/manual/layouts.html#logback-access -->
                    <pattern>
                        {
                            "type": "AccessLog",
                            "executionTime": "%D",
                            "ip": "%a",
                            "httpMethod": "%m",
                            "requestHost": "%i{host}",
                            "requestMapping": "%reqAttribute{org.springframework.web.servlet.HandlerMapping.bestMatchingPattern}",
                            "createTime": "%date{yyyy-MM-dd HH:mm:ss}",
                            "requestURI": "%U",
                            "httpStatus": "%s"
                        }
                    </pattern>
                </pattern>
                <provider class="com.snaildrum.demo.provider.access.PidJsonProvider" />
                <provider class="com.snaildrum.demo.provider.access.RequestParamsJsonProvider" />
            </providers>
        </encoder>
    </appender>

<!--
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%fullRequest%n%n%fullResponse</pattern>
        </encoder>
    </appender>
-->


    <appender-ref ref="LOGSTASH"/>
<!--    <appender-ref ref="CONSOLE" />-->
</configuration>

请求头是 application/json 时获取请求的参数

当发送 json 请求时，springBoot 中是通过 @RequestBody 接收的，这种情况，在 AccessEvent 中并没有地方可以获取，想要获取 RequestBody 中的 json 串如何处理呢？

logback-access 官方的包里给了一个 TeeFliter 的类，该类实现了 HttpServletRequestWarper 和 HttpServletResponseWarper，读取了 reqeuest 和 response 里的流中数据，不过与此同时同事官方也给出了警告⚠️：

它曾经无缘无故使得线上的环境宕机。

尴尬了，那怎么弄了？

不要慌，可以参考 TeeFilter 实现一个自己的 Filter，当请求头是 application/json 再读取里边的内容，然后将读取到的内容设置到 request 的属性中，在 logback-access 的自定义 JsonProvider 中取出。

MyFilter.java：

public class MyFilter implements Filter {

    @Override
    public void init(FilterConfig filterConfig) {
        // doing something
    }

    @Override
    public void doFilter(ServletRequest req, ServletResponse resp, FilterChain chain) throws IOException, ServletException {
        HttpServletRequest request = (HttpServletRequest) req;
        String contentType = request.getContentType();
        if (contentType != null && contentType.startsWith("application/json")) {
            MyHttpServletRequest myHttpServletRequest = new MyHttpServletRequest(request);
            ServletInputStream inputStream = myHttpServletRequest.getInputStream();
            BufferedReader in = new BufferedReader(new InputStreamReader(inputStream));
            StringBuilder builder = new StringBuilder();
            String line;
            while ((line = in.readLine()) != null){
                builder.append(line);
            }
            String jsonStr = builder.toString();
            System.out.println(jsonStr);
            if (!"".equals(jsonStr)) {
                myHttpServletRequest.setAttribute("jsonStr", jsonStr);
            }
            chain.doFilter(myHttpServletRequest, resp);
        } else {
            chain.doFilter(request, resp);
        }
    }

    @Override
    public void destroy() {
        // doing something
    }
}

MyHttpServletRequest.java:

public class MyHttpServletRequest extends HttpServletRequestWrapper {

    private byte[] body;

    public MyHttpServletRequest(HttpServletRequest request) {
        super(request);
        try {
            body = toByteArray(request.getInputStream());
        } catch (IOException ex) {
            body = new byte[0];
        }
    }

    @Override
    public ServletInputStream getInputStream() throws IOException {
        return new DelegatingServletInputStream(new ByteArrayInputStream(body));
    }


    public static byte[] toByteArray(InputStream input) throws IOException {
        ByteArrayOutputStream output = new ByteArrayOutputStream();
        byte[] buffer = new byte[4096];
        int n;
        while (-1 != (n = input.read(buffer))) {
            output.write(buffer, 0, n);
        }
        return output.toByteArray();
    }

}

DelegatingServletInputStream.java

public class DelegatingServletInputStream extends ServletInputStream {

    private final InputStream sourceStream;

    private boolean finished = false;


    /**
     * Create a DelegatingServletInputStream for the given source stream.
     *
     * @param sourceStream the source stream (never {@code null})
     */
    public DelegatingServletInputStream(InputStream sourceStream) {
        this.sourceStream = sourceStream;
    }

    /**
     * Return the underlying source stream (never {@code null}).
     */
    public final InputStream getSourceStream() {
        return this.sourceStream;
    }


    @Override
    public int read() throws IOException {
        int data = this.sourceStream.read();
        if (data == -1) {
            this.finished = true;
        }
        return data;
    }

    @Override
    public int available() throws IOException {
        return this.sourceStream.available();
    }

    @Override
    public void close() throws IOException {
        super.close();
        this.sourceStream.close();
    }

    @Override
    public boolean isFinished() {
        return this.finished;
    }

    @Override
    public boolean isReady() {
        return true;
    }

    @Override
    public void setReadListener(ReadListener readListener) {
        throw new UnsupportedOperationException();
    }

}

自定义的 RequestParamsJsonProvider.java:

public class RequestParamsJsonProvider extends AbstractFieldJsonProvider<IAccessEvent> implements FieldNamesAware<LogstashAccessFieldNames> {

    private static final String FIELD_REQUESTPARAMS = "requestParams";

    public RequestParamsJsonProvider() {
        setFieldName(FIELD_REQUESTPARAMS);
    }

    @Override
    public void writeTo(JsonGenerator generator, IAccessEvent event) throws IOException {
        // when content-type is  application/json
        String jsonStr = event.getAttribute("jsonStr");
        if (jsonStr != null && !"".equals(jsonStr) && !IAccessEvent.NA.equals(jsonStr)) {
            JsonWritingUtils.writeStringField(generator, getFieldName(), jsonStr);
            return;
        }

        // not application/json
        Map<String, String[]> requestParameterMap = event.getRequestParameterMap();
        if (requestParameterMap == null || requestParameterMap.isEmpty()) {
            return;
        }

        Set<String> requestParamKeys = requestParameterMap.keySet();

        Map<String, String> map = requestParamKeys.stream().collect(Collectors.toMap(k -> k, requestParamKey -> {
                    String[] requestParameter = requestParameterMap.get(requestParamKey);
                    if (requestParameter.length == 1) {
                        return requestParameter[0];
                    }
                    return String.join(",", requestParameter);
                },
                (oldValue, newValue) -> newValue)
        );

        ObjectMapper mapper = new ObjectMapper();
        String json = mapper.writeValueAsString(map);
        JsonWritingUtils.writeStringField(generator, getFieldName(), json);
    }

    @Override
    public void setFieldNames(LogstashAccessFieldNames fieldNames) {
        setFieldName(FIELD_REQUESTPARAMS);
    }

}

最后

• 最终的 json 中包含了请求参数，对于一些敏感字段或者大字段肯定是有脱敏及过滤需求的，可以直接设计一个表达式，针对特定的接口对特定的字段操作，最终实现一个自定义的 requestParams 就能实现。
• 如果未来要把日志通过 logstash 写入到 ES 中，那么请求参数一定要格式化为 json 字符串，如果最终进入 ES 中的 json 是多层的，那样会造成 ES 中的索引无限增多，非常危险。

查看源代码

---

      长按关注我

一起成长，共同进步

蜗牛小鼓

感觉有用，点个在看