CLOVER🍀

That was when it all began.

Fluentdで複数行のログを読む

これは、なにをしたくて書いたもの?

以前、Fluent Bitで複数行(Multiline)のログファイルを読むエントリを書きました。

Fluent Bitで、複数行のログファイルを読む - CLOVER🍀

今回は、これをFluentdで行ってみます。

FluentdとMultiline

Fluentdを使って複数行のログを読むには、2つの方法があるようです。

Fluentd単体だと、Parser Pluginのmultilineを使います。

multiline - Fluentd

サードパーティ製のプラグインを使う場合は、fluentd-plugin-concatを使います。

GitHub - fluent-plugins-nursery/fluent-plugin-concat: Fluentd Filter plugin to concatenate multiline log separated in multiple events.

今回、これらを使って複数行のログを読んでみたいと思います。

ログを出力するサンプルアプリケーションは、Fluent Bitの時と同じもの(Spring Bootのバージョンだけ上げます)を使います。

Fluent Bitで、複数行のログファイルを読む - CLOVER🍀

以下、それぞれの方法の概要を。

Parser Plugin / multiline

まずは、multiline Parser Pluginを使う方法から。

multiline - Fluentd

他のParser Pluginと異なり、Tail Pluginと組み合わせて使うことが想定されています。

Unlike other parser plugins, this plugin needs special code in input plugin e.g. handle format_firstline. So, currently, in_tail plugin works with multiline but other input plugins do not work with it.

パラメーターは2種類で、format_firstlineとformatN(Nは数字)です。

少なくとも、format1は必須になります。1以降のformatNは、複数行で構成された各ログをより細かくパターンマッチさせる時に
使います。

Railsのログの例が、その活用例になっています。

multiline / Rails Log

format_firstlineは、複数行の開始を表す正規表現パターンを指定します。デフォルトはnilで、指定した場合はこのパターンに
マッチしない行をバッファに溜めていくようになります。

再度format_firstlineにマッチする行が来たら、その直前までがひとつのログレコードとして扱われることになります、と。

Javaのスタックトレースの例が、format_firstlineとformat1だけを指定してひとつにまとめる例としてはわかりやすいですね。
これがドキュメントに記載されています。

multiline / Java Stacktrace Log

ソースコードで見ると、確かにTail Pluginがmultilineを完全意識した構成になっていますね。

https://github.com/fluent/fluentd/blob/v1.11.2/lib/fluent/plugin/in_tail.rb#L519-L556

また、Multiline Pluginのパース処理そのものにはformat_firstlineの方は出てこないようです。format_firstlineを意識しているのは、
あくまでTail Pluginのようですね。

https://github.com/fluent/fluentd/blob/v1.11.2/lib/fluent/plugin/parser_multiline.rb#L76-L100

つまり、formatNのみを使った場合は複数行ログの行数が想定できることになります、と。

fluent-plugin-concat

続いて、fluent-plugin-concatです。こちらはFilter Pluginとして使う、複数のイベントに分割されたログを結合するためのものです。

GitHub - fluent-plugins-nursery/fluent-plugin-concat: Fluentd Filter plugin to concatenate multiline log separated in multiple events.

複数行の指定方法はいくつかあり、n_lines、multiline_start_regexp、multiline_end_regexp、continuous_line_regexpが
あります。n_linesと他の設定には、排他の関係があります。

それぞれ意味はわかりそうですが、n_linesが複数行がどれだけ続くか、他は複数行の開始、終了、継続を表す正規表現を
指定するといった感じですね。

使い方も書かれていますが、特にDockerとKubernetesがとてもしっかり書かれています。これらでよく使われるんでしょうね…。

Usage

このFilter Pluginが複数のタグにマッチする場合、ログが混ざったりするのでは?と思ったのですが、デフォルトでタグごとに
ストリームの管理が分かれているようです。

https://github.com/fluent-plugins-nursery/fluent-plugin-concat/blob/v2.4.0/lib/fluent/plugin/filter_concat.rb#L177-L188

さらに細かくストリームの単位を指定したい場合は、stream_identity_keyでレコード内でどのキーをストリームの単位として
扱うかを指定します。

説明はこれくらいにして、実際に使ってみましょう。

環境

今回の環境は、こちらです。

$ td-agent --version
td-agent 1.11.2


$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 20.04.1 LTS
Release:    20.04
Codename:   focal


$ uname -srvmpio
Linux 5.4.0-65-generic #73-Ubuntu SMP Mon Jan 18 17:25:17 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux

サンプルアプリケーション

まずは、ログを読み込む対象となるサンプルアプリケーションを用意します。Spring Bootで、簡単に作成。

JavaとMavenのバージョン。

$ java --version
openjdk 11.0.9.1 2020-11-04
OpenJDK Runtime Environment (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04)
OpenJDK 64-Bit Server VM (build 11.0.9.1+1-Ubuntu-0ubuntu1.20.04, mixed mode, sharing)


$ mvn --version
Apache Maven 3.6.3 (cecedd343002696d0abb50b32b541b8a6ba2883f)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 11.0.9.1, vendor: Ubuntu, runtime: /usr/lib/jvm/java-11-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "5.4.0-64-generic", arch: "amd64", family: "unix"

`pom.xml

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>org.littlewings</groupId>
    <artifactId>simple-logging-web-app</artifactId>
    <version>0.0.1-SNAPSHOT</version>

    <properties>
        <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
        <project.reporting.outputEncoding>UTF-8</project.reporting.outputEncoding>
        <maven.compiler.source>11</maven.compiler.source>
        <maven.compiler.target>11</maven.compiler.target>
    </properties>

    <dependencyManagement>
        <dependencies>
            <dependency>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-dependencies</artifactId>
                <version>2.4.2</version>
                <type>pom</type>
                <scope>import</scope>
            </dependency>
        </dependencies>
    </dependencyManagement>

    <dependencies>
        <dependency>
            <groupId>org.springframework.boot</groupId>
            <artifactId>spring-boot-starter-web</artifactId>
        </dependency>
    </dependencies>

    <build>
        <finalName>${project.artifactId}</finalName>
        <plugins>
            <plugin>
                <groupId>org.springframework.boot</groupId>
                <artifactId>spring-boot-maven-plugin</artifactId>
                <version>2.4.2</version>
                <executions>
                  <execution>
                    <goals>
                      <goal>repackage</goal>
                    </goals>
                  </execution>
                </executions>
            </plugin>
        </plugins>
    </build>
</project>

ログを出力するだけの、@RestController。

src/main/java/org/littlewings/spring/example/App.java

package org.littlewings.spring.example;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
@RequestMapping("app")
public class App {
    Logger logger = LoggerFactory.getLogger(App.class);

    public static void main(String... args) {
        SpringApplication.run(App.class, args);
    }

    @GetMapping("info")
    public String info() {
        logger.info("{}, info logging", "hello");

        return "info logging";
    }

    @GetMapping("warn")
    public String warn() {
        logger.warn("{}, warn logging", "world");

        return "warn logging";
    }

    @GetMapping("error")
    public String error() {
        logger.error("{}, error logging", "oops!!");

        return "error logging";
    }

    @GetMapping("exception")
    public String exception() {
        Exception e = new RuntimeException("Oops!!");

        logger.error("exception occurred, {}", "why?", e);

        return "exception logging";
    }
}

パッケージングして

$ mvn package

起動。これで、/tmp/spring.logにログが出力されます。

$ java -Dlogging.file.path=/tmp -jar target/simple-logging-web-app.jar

確認。

$ curl localhost:8080/app/info
info logging


$ curl localhost:8080/app/error
error logging


$ curl localhost:8080/app/exception
exception logging

ログはこんな感じに出力されます。

2021-01-27 14:28:14.969  INFO 1263 --- [http-nio-8080-exec-1] org.littlewings.spring.example.App       : hello, info logging
2021-01-27 14:28:16.503 ERROR 1263 --- [http-nio-8080-exec-3] org.littlewings.spring.example.App       : oops!!, error logging
2021-01-27 14:28:17.895 ERROR 1263 --- [http-nio-8080-exec-2] org.littlewings.spring.example.App       : exception occurred, why?

java.lang.RuntimeException: Oops!!
    at org.littlewings.spring.example.App.exception(App.java:44) ~[classes!/:na]
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
    at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
    at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
    at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:962) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:626) ~[tomcat-embed-core-9.0.41.jar!/:4.0.FR]
    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.3.jar!/:5.3.3]
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:733) ~[tomcat-embed-core-9.0.41.jar!/:4.0.FR]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]
    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]
    at java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]

これで、準備完了です。では、Fluentdの設定を行っていきましょう。

Parser Plugin / multilineで複数行のログファイルを読む

まずは、multilineを使うパターンです。

multiline - Fluentd

設定は、こんな感じで行いました。

/etc/td-agent/td-agent.conf

<source>
  @type tail
  @id app_log_tail

  <parse>
    @type multiline
    format_firstline /^\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}/
    format1 /^(?<log>(?<time>\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}).+)/
  </parse>

  path /tmp/spring.log
  pos_file /var/log/td-agent/app.log.pos
  tag app.log
</source>

<match app.**>
  @type stdout
  @id output_stdout
</match>

Tail Pluginで、ログファイルを読み続けます。この時に、Parser Pluginとしてmultilineを指定します。

  <parse>
    @type multiline
    format_firstline /^\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}/
    format1 /^(?<log>(?<time>\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}).+)/
  </parse>

アプリケーションログの日時の部分を開始行として定義しておきます。

また、timeをパターンとして指定していますが、time_keyのデフォルトはtimeらしいので、こちらに合わせておきました。

Config: Parse Section / Parse Parameters

それ以上のパースは今回は行いません。

出力先は、Stdout Plugin…つまり、Fluentd自身のログファイルにします。

<match app.**>
  @type stdout
  @id output_stdout
</match>

設定したら、Fluentdを再起動。

$ sudo systemctl restart td-agent

では、アプリケーションにアクセスしてみます。
※正確には、このあともう1回アクセスしないと最後のリクエストのログは書き出されませんが

$ curl localhost:8080/app/info
$ curl localhost:8080/app/error
$ curl localhost:8080/app/exception
$ curl localhost:8080/app/warn

Fluentdのログを見ます。

/var/log/td-agent/td-agent.log

2021-01-27 14:39:43.891000000 +0000 app.log: {"log":"2021-01-27 14:39:43.891  INFO 1263 --- [http-nio-8080-exec-5] org.littlewings.spring.example.App       : hello, info logging"}
2021-01-27 14:39:46.925000000 +0000 app.log: {"log":"2021-01-27 14:39:46.925 ERROR 1263 --- [http-nio-8080-exec-6] org.littlewings.spring.example.App       : oops!!, error logging"}
2021-01-27 14:40:14.398000000 +0000 app.log: {"log":"2021-01-27 14:40:14.398 ERROR 1263 --- [http-nio-8080-exec-7] org.littlewings.spring.example.App       : exception occurred, why?\n\njava.lang.RuntimeException: Oops!!\n\tat org.littlewings.spring.example.App.exception(App.java:44) ~[classes!/:na]\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]\n\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]\n\tat java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]\n\tat org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:962) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:626) ~[tomcat-embed-core-9.0.41.jar!/:4.0.FR]\n\tat org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:733) ~[tomcat-embed-core-9.0.41.jar!/:4.0.FR]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]\n"}
2021-01-27 14:40:20.487000000 +0000 app.log: {"log":"2021-01-27 14:40:20.487  WARN 1263 --- [http-nio-8080-exec-8] org.littlewings.spring.example.App       : world, warn logging"}

スタックトレースもまとまった行になっていることがわかりますね。

ちなみに、time_keyで指定されているフィールド(今回はデフォルトのtime)を残すには、keep_time_keyをtrueに
設定します。

  <parse>
    @type multiline
    format_firstline /^\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}/
    format1 /^(?<log>(?<time>\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}).+)/

    keep_time_key true
  </parse>

確認。

2021-01-27 14:45:26.306000000 +0000 app.log: {"log":"2021-01-27 14:45:26.306  INFO 1263 --- [http-nio-8080-exec-10] org.littlewings.spring.example.App       : hello, info logging","time":"2021-01-27 14:45:26.306"}

fluent-plugin-concat

次は、fluent-plugin-concatを使います。

GitHub - fluent-plugins-nursery/fluent-plugin-concat: Fluentd Filter plugin to concatenate multiline log separated in multiple events.

こちらはサードパーティ製のプラグインになるので、インストールが必要です。こちらのドキュメントに記載されている
プラグインのインストールコマンドを確認したら

Plugin Management - Fluentd

インストールします。

$ sudo td-agent-gem install fluent-plugin-concat
Fetching fluent-plugin-concat-2.4.0.gem
Successfully installed fluent-plugin-concat-2.4.0
Parsing documentation for fluent-plugin-concat-2.4.0
Installing ri documentation for fluent-plugin-concat-2.4.0
Done installing documentation for fluent-plugin-concat after 0 seconds
1 gem installed

今回は2.4.0がインストールされました。

インストールされた場所は、こちら。

$ ll /opt/td-agent/lib/ruby/gems/2.7.0/gems/fluent-plugin-concat-2.4.0
total 56
drwxr-xr-x   4 root root 4096 Jan 25 15:13 ./
drwxr-xr-x 131 root root 4096 Jan 25 15:13 ../
-rw-r--r--   1 root root    0 Jan 25 15:13 Appraisals
-rw-r--r--   1 root root 1047 Jan 25 15:13 fluent-plugin-concat.gemspec
-rw-r--r--   1 root root  105 Jan 25 15:13 Gemfile
drwxr-xr-x   2 root root 4096 Jan 25 15:13 .github/
-rw-r--r--   1 root root   53 Jan 25 15:13 .gitignore
drwxr-xr-x   3 root root 4096 Jan 25 15:13 lib/
-rw-r--r--   1 root root 1072 Jan 25 15:13 LICENSE.txt
-rw-r--r--   1 root root  762 Jan 25 15:13 NEWS.md
-rw-r--r--   1 root root  219 Jan 25 15:13 Rakefile
-rw-r--r--   1 root root 4718 Jan 25 15:13 README.md
-rw-r--r--   1 root root 1153 Jan 25 15:13 .rubocop.yml
-rw-r--r--   1 root root  970 Jan 25 15:13 .travis.yml

では、設定します。

/etc/td-agent/td-agent.conf

<source>
  @type tail
  @id app_log_tail

  <parse>
    @type regexp
    expression /(?<log>.*)/
  </parse>


  path /tmp/spring.log
  pos_file /var/log/td-agent/app.log.pos
  tag app.log
</source>

<filter app.**>
  @type concat
  key log
  multiline_start_regexp /^\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}/
</filter>

<filter app.**>
  @type parser
  key_name log

  <parse>
    @type regexp
    expression /^(?<log>(?<time>\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}).+)/m

    keep_time_key true
  </parse>
</filter>


<match app.**>
  @type stdout
  @id output_stdout
</match>

複数行のログファイルはfluent-plugin-concatで結合させるので、Tail Pluginはなにも考えずに1行ずつログレコードとして
読み取るように設定します。

<source>
  @type tail
  @id app_log_tail

  <parse>
    @type regexp
    expression /(?<log>.*)/
  </parse>


  path /tmp/spring.log
  pos_file /var/log/td-agent/app.log.pos
  tag app.log
</source>

Tail Pluginで読み取ったログは、fluent-plugin-concatで結合させます。先ほどのmultilineの時と同様に、日時のパターンを
ログの開始パターンとして定義しました。

<filter app.**>
  @type concat
  key log
  multiline_start_regexp /^\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}/
</filter>

あとはオマケで、time_key(timeフィールド)を抜き出すために、regex Parser Pluginを付けています。
今回は最初からkeep_time_keyはtrueにしています。

<filter app.**>
  @type parser
  key_name log

  <parse>
    @type regexp
    expression /^(?<log>(?<time>\d{4}-\d\d-\d\d \d\d:\d\d:\d\d.\d{3}).+)/m

    keep_time_key true
  </parse>
</filter>

設定したら、Fluentdを再起動して

$ sudo systemctl restart td-agent

アプリケーションにアクセスしてみます。
※やっぱり、このあとにもう1回リクエストをつけています

$ curl localhost:8080/app/info
$ curl localhost:8080/app/error
$ curl localhost:8080/app/exception
$ curl localhost:8080/app/warn

Fluentdのログを確認。

/var/log/td-agent/td-agent.log

2021-01-27 14:59:28.464000000 +0000 app.log: {"log":"2021-01-27 14:59:28.464  INFO 1263 --- [http-nio-8080-exec-4] org.littlewings.spring.example.App       : hello, info logging","time":"2021-01-27 14:59:28.464"}
2021-01-27 14:59:30.036000000 +0000 app.log: {"log":"2021-01-27 14:59:30.036 ERROR 1263 --- [http-nio-8080-exec-2] org.littlewings.spring.example.App       : oops!!, error logging","time":"2021-01-27 14:59:30.036"}
2021-01-27 14:59:34.503000000 +0000 app.log: {"log":"2021-01-27 14:59:34.503 ERROR 1263 --- [http-nio-8080-exec-6] org.littlewings.spring.example.App       : exception occurred, why?\n\njava.lang.RuntimeException: Oops!!\n\tat org.littlewings.spring.example.App.exception(App.java:44) ~[classes!/:na]\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]\n\tat java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]\n\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]\n\tat java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]\n\tat org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:197) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:141) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1060) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:962) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:626) ~[tomcat-embed-core-9.0.41.jar!/:4.0.FR]\n\tat org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883) ~[spring-webmvc-5.3.3.jar!/:5.3.3]\n\tat javax.servlet.http.HttpServlet.service(HttpServlet.java:733) ~[tomcat-embed-core-9.0.41.jar!/:4.0.FR]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119) ~[spring-web-5.3.3.jar!/:5.3.3]\n\tat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]\n\tat java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]\n\tat org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.41.jar!/:9.0.41]\n\tat java.base/java.lang.Thread.run(Thread.java:834) ~[na:na]\n","time":"2021-01-27 14:59:34.503"}
2021-01-27 14:59:36.987000000 +0000 app.log: {"log":"2021-01-27 14:59:36.987  WARN 1263 --- [http-nio-8080-exec-7] org.littlewings.spring.example.App       : world, warn logging","time":"2021-01-27 14:59:36.987"}

スタックトレースを含んだログも結合されていますし、OKですね。

まとめ

Fluentdを使って、複数行のログを読む方法を2つ試してみました。

multilineの設定って、1回試した後に時間が空くとすぐ忘れてしまうのですが…こうやってメモしておくのが良いのでしょう…。

きっと、また思い出すために見ることになるでしょう。