これは、なにをしたくて書いたもの?
以前、Fluent Bitで複数行(Multiline)のログファイルを読むエントリを書きました。
Fluent Bitで、複数行のログファイルを読む - CLOVER🍀
今回は、これをFluentdで行ってみます。
FluentdとMultiline
Fluentdを使って複数行のログを読むには、2つの方法があるようです。
Fluentd単体だと、Parser Pluginのmultilineを使います。
サードパーティ製のプラグインを使う場合は、fluentd-plugin-concatを使います。
今回、これらを使って複数行のログを読んでみたいと思います。
ログを出力するサンプルアプリケーションは、Fluent Bitの時と同じもの(Spring Bootのバージョンだけ上げます)を使います。
Fluent Bitで、複数行のログファイルを読む - CLOVER🍀
以下、それぞれの方法の概要を。
Parser Plugin / multiline
まずは、multiline Parser Pluginを使う方法から。
他の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のログの例が、その活用例になっています。
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として使う、複数のイベントに分割されたログを結合するためのものです。
複数行の指定方法はいくつかあり、n_lines
、multiline_start_regexp
、multiline_end_regexp
、continuous_line_regexp
が
あります。n_lines
と他の設定には、排他の関係があります。
それぞれ意味はわかりそうですが、n_lines
が複数行がどれだけ続くか、他は複数行の開始、終了、継続を表す正規表現を
指定するといった感じですね。
使い方も書かれていますが、特にDockerとKubernetesがとてもしっかり書かれています。これらでよく使われるんでしょうね…。
このFilter Pluginが複数のタグにマッチする場合、ログが混ざったりするのでは?と思ったのですが、デフォルトでタグごとに
ストリームの管理が分かれているようです。
さらに細かくストリームの単位を指定したい場合は、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 --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を使うパターンです。
設定は、こんな感じで行いました。
/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を使います。
こちらはサードパーティ製のプラグインになるので、インストールが必要です。こちらのドキュメントに記載されている
プラグインのインストールコマンドを確認したら
インストールします。
$ 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回試した後に時間が空くとすぐ忘れてしまうのですが…こうやってメモしておくのが良いのでしょう…。
きっと、また思い出すために見ることになるでしょう。