CLOVER🍀

That was when it all began.

Sentry JavaのLogbackインテグレーションを試す

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

Sentryには、各種言語向けのライブラリがあります。

Platforms - Docs

Java用のライブラリもあり、

Integrations - Docs

この中にLogback用のライブラリが提供されているので、こちらを使って遊んでみることにしました。

Logback

他には、Android、GAE、j.u.Logging、Log4j 1 & 2、Springなどがあります。

SentryとException tracking pattern

Sentryとは、オープンソースのエラートラッキングシステムです。以前に環境構築をしたことがあります。

オープンソースのエラートラッキングシステム、Sentryをローカルで動かしてみる - CLOVER🍀

書籍「Microservices Pattens」では「Exception tracking pattern」というパターンで、サービスとしてはHoneybadgerが紹介されています。

Microservices Patterns: With examples in Java

Microservices Patterns: With examples in Java

「Exception tracking pattern」とは、エラー時の情報(例外など)をREST APIなどでException tracking serviceに送ってアラートやその解決の
管理をしようというパターンです。

Sentry JavaとLogback

Sentry Javaは、SentryのJava向けのクライアントライブラリです。その中に、Logback用のインテグレーションがあります。

Logback

GitHub - getsentry/sentry-java: A Sentry SDK for Java and other JVM languages.

https://github.com/getsentry/sentry-java/blob/v1.7.27/sentry-logback/src/main/java/io/sentry/logback/SentryAppender.java

Logbackとの統合機能としてはAppenderがあるのみで、主な処理はほとんどコア部分に入っています。

Java - Docs

Configuration - Docs

Manual Usage - Docs

https://github.com/getsentry/sentry-java/tree/v1.7.27/sentry

このあたりの情報を見つつ、試していってみましょう。

環境

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

$ java -version
openjdk version "11.0.4" 2019-07-16
OpenJDK Runtime Environment (build 11.0.4+11-post-Ubuntu-1ubuntu218.04.3)
OpenJDK 64-Bit Server VM (build 11.0.4+11-post-Ubuntu-1ubuntu218.04.3, mixed mode, sharing)


$ mvn -version
Apache Maven 3.6.1 (d66c9c0b3152b2e69ee9bac180bb8fcc8e6af555; 2019-04-05T04:00:29+09:00)
Maven home: $HOME/.sdkman/candidates/maven/current
Java version: 11.0.4, vendor: Ubuntu, runtime: /usr/lib/jvm/java-11-openjdk-amd64
Default locale: ja_JP, platform encoding: UTF-8
OS name: "linux", version: "4.15.0-58-generic", arch: "amd64", family: "unix"

Sentryは、オンプレミス版(Docker)を使用します。バージョンは、9.1.2。

Installation with Docker - Docs

GitHub - getsentry/onpremise: Sentry On-Premise setup

インストール時に作成するアカウントは、「test@example.com / password」としました。

お題

シンプルに、LogbackからSentryにログを送信し、Sentry上で確認できることを目標にします。

また、今回はアラートまわりについては扱いません。

準備

アプリケーションの、Maven依存関係はこちら。

        <dependency>
            <groupId>io.sentry</groupId>
            <artifactId>sentry-logback</artifactId>
            <version>1.7.27</version>
        </dependency>

「sentry-logback」を依存関係に追加すると、推移的に「slf4j-api」も引き込まれます。

Sentryにログインして、プロジェクトを作成します。Javaを選択。

f:id:Kazuhira:20190823001546p:plain

プロジェクトの「Settings」から、「DSN」を確認。

f:id:Kazuhira:20190823001617p:plain

このDSNを覚えておきます。

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

ドキュメントを見ていると、スタックトレースがそれなりの深さがあるものを用意した方が良さそうだったので、今回は
簡単なHTTPサーバーを書くことにしました。

JDKに組み込まれている、HttpServerを利用して作成。
src/main/java/org/littlewings/sentry/logback/Server.java

package org.littlewings.sentry.logback;

import java.io.IOException;
import java.net.InetSocketAddress;
import java.nio.charset.StandardCharsets;

import com.sun.net.httpserver.HttpServer;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.slf4j.MDC;

public class Server {
    public static void main(String... args) throws IOException {
        Logger logger = LoggerFactory.getLogger(Server.class);

        HttpServer server = HttpServer.create(new InetSocketAddress(8080), 10);
        server.createContext("/", exchange -> {
            MDC.put("app", "java-app");

            String path = exchange.getRequestURI().getPath();

            logger.info("{} access", path);

            byte[] body;
            switch (path) {
                case "/info":
                    logger.info("INFOログだよ");

                    body = "OK!!".getBytes(StandardCharsets.UTF_8);
                    exchange.sendResponseHeaders(200, body.length);
                    exchange.getResponseBody().write(body);
                    break;
                case "/warn":
                    logger.warn("WARNログです");

                    body = "WARN!!".getBytes(StandardCharsets.UTF_8);
                    exchange.sendResponseHeaders(500, body.length);
                    exchange.getResponseBody().write(body);
                    break;
                case "/error":
                    logger.error("エラーですよ");

                    body = "ERROR!!".getBytes(StandardCharsets.UTF_8);
                    exchange.sendResponseHeaders(500, body.length);
                    exchange.getResponseBody().write(body);
                    break;
                case "/exception":
                    logger.error("例外だよ", new RuntimeException("Oops!!"));

                    body = "Oops!!".getBytes(StandardCharsets.UTF_8);
                    exchange.sendResponseHeaders(500, body.length);
                    exchange.getResponseBody().write(body);
                    break;
                default:
                    exchange.sendResponseHeaders(404, 0);
                    break;
            }

            MDC.clear();
        });

        server.start();
    }
}

「/info」や「/warn」などのエンドポイントに合わせたログレベルのログを出力し、「/exceptioon」の場合は例外をロギング。

次に、ドキュメントを見ながらLogbackの設定ファイルを用意します。

Logback / Usage

src/main/resources/logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] [%-5level] [%X{app}] %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="Sentry" class="io.sentry.logback.SentryAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>WARN</level>
        </filter>
    </appender>

    <root level="info">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="Sentry"/>
    </root>
</configuration>

Appenderとして、「SentryAppender」を追加します。ログレベルは、今回はドキュメント通りにWARN以上を対象にしました。

    <appender name="Sentry" class="io.sentry.logback.SentryAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>WARN</level>
        </filter>
    </appender>

また、Sentry Javaの設定ファイルも用意。
src/main/resources/sentry.properties

environment=staging
servername=myhost

mdctags=app
stacktrace.app.packages=org.littlewings.sentry.logback

設定の意味は、こちらを。

Configuration - Docs

environmentやservernameは、Optionとして定義してあります。

Options

servernameは、イベントが発生したホスト名をこちらで上書きできるようです。Optionとしてなにも指定しなかった場合は、アプリケーションを
実行しているホスト名がSentryに送信されます。

Tags、MDC Tagsというものもあり、タグを設定することができます。

Tags

MDC Tags

MDCはSLF4J由来のもので、これで指定したMDCタグは、タグとして扱われます。ここでMDC Tagsとして指定しなかった場合は、
MDCにputした内容はAdditional Dataとして扱われます。

Additional Data

「stacktrace.app.packages」で、アプリケーションとそれ以外のスタックトレースのパッケージを区別することができます。

“In Application” Stack Frames

これらの設定は、ファイルシステムまたはクラスパス上のsentry.propertiesで定義することができますが、実行時にシステムプロパティや
環境変数で上書きすることもできます。コードで静的に指定することもできます。

Configuration methods

システムプロパティや環境変数で指定する場合は、「sentry.」(SENTRY_) prefixが必要です。

あ、そうそう、Sentryへのデータ送信ですが、デフォルトでは非同期みたいですよ。

Async Connection

動作確認

と、設定の説明はこれくらいにして試してみましょう。

DSNを指定して、起動。

$ mvn compile exec:java -Dexec.mainClass=org.littlewings.sentry.logback.Server -Dsentry.dsn=http://9f72660300424abf915b9cc317ad95@localhost:9000/2

「/info」。

$ curl localhost:8080/info
OK!!


### 出力されたログ
2019-08-24 00:34:20.089 [HTTP-Dispatcher] [INFO ] [java-app] org.littlewings.sentry.logback.App - /info access
2019-08-24 00:34:20.091 [HTTP-Dispatcher] [INFO ] [java-app] org.littlewings.sentry.logback.App - INFOログだよ

「/warn」。

$ curl localhost:8080/warn
WARN!!


2019-08-24 00:34:47.319 [HTTP-Dispatcher] [INFO ] [java-app] org.littlewings.sentry.logback.App - /warn access
2019-08-24 00:34:47.319 [HTTP-Dispatcher] [WARN ] [java-app] org.littlewings.sentry.logback.App - WARNログです

「/error」。

$ curl localhost:8080/error
ERROR!!


2019-08-24 00:35:08.984 [HTTP-Dispatcher] [INFO ] [java-app] org.littlewings.sentry.logback.App - /error access
2019-08-24 00:35:08.985 [HTTP-Dispatcher] [ERROR] [java-app] org.littlewings.sentry.logback.App - エラーですよ

「/exception」。

$ curl localhost:8080/exception
Oops!!


2019-08-24 00:35:40.262 [HTTP-Dispatcher] [INFO ] [java-app] org.littlewings.sentry.logback.App - /exception access
2019-08-24 00:35:40.264 [HTTP-Dispatcher] [ERROR] [java-app] org.littlewings.sentry.logback.App - 例外だよ
java.lang.RuntimeException: Oops!!
    at org.littlewings.sentry.logback.Server.lambda$main$0(Server.java:48)
    at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
    at jdk.httpserver/sun.net.httpserver.AuthFilter.doFilter(AuthFilter.java:82)
    at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:80)
    at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange$LinkHandler.handle(ServerImpl.java:692)
    at jdk.httpserver/com.sun.net.httpserver.Filter$Chain.doFilter(Filter.java:77)
    at jdk.httpserver/sun.net.httpserver.ServerImpl$Exchange.run(ServerImpl.java:664)
    at jdk.httpserver/sun.net.httpserver.ServerImpl$DefaultExecutor.execute(ServerImpl.java:159)
    at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.handle(ServerImpl.java:442)
    at jdk.httpserver/sun.net.httpserver.ServerImpl$Dispatcher.run(ServerImpl.java:408)
    at java.base/java.lang.Thread.run(Thread.java:834)

さて、Sentryの方を見てみましょう。

見た目としては2つ、イベントとしては3つ来ています。

f:id:Kazuhira:20190824003743p:plain

2つイベントが来ていたレコードを見てみます。

f:id:Kazuhira:20190824003836p:plain

WARNとERRORがまとまっています…。

WARNの方を見てみましょう。これだけの情報が届いています。

f:id:Kazuhira:20190824003936p:plain

f:id:Kazuhira:20190824003958p:plain

なぜかスタックトレースも届いており、デフォルトで表示されているのは「stacktrace.app.packages」で指定したアプリケーションの
パッケージのものだけなので、「Full」を指定するとこれを展開することができます。

f:id:Kazuhira:20190824004106p:plain

「Raw」で、見慣れた感じにすることもできます。

f:id:Kazuhira:20190824004142p:plain

タグ。ホスト名や、environmentで指定した内容などが入っています。

f:id:Kazuhira:20190824004339p:plain

MDCで指定した内容が、ここに入っていますね。

            MDC.put("app", "java-app");

MDC Tagsとして指定しなかった場合は、Additional Dataに入ります。今回は、スレッド名のみしか入っていません。

f:id:Kazuhira:20190824004439p:plain

ERRORの方は、レベルが異なる以外、大して差がなかったので割愛。

Exceptionを含むERROR。

f:id:Kazuhira:20190824004628p:plain

こちらも、あんまり変わりなく。

とにかく、ログを送信した時点でその時のスタックトレースが含まれるようなので、ロギング時に例外を含むかどうかは関係なく
記録されるみたいですね。

それなりに重そう…ですが、デフォルトで非同期送信なのでまだ良い?

とりあえず、動作確認はできました、と。

まとめ

Sentry JavaのLogbackインテグレーションを使って、ロギング時にSentryにデータを送ってみました。

まずは、ログを送信してSentryで見るところまでできたので、次はアラートの送信、管理などをやってみるとしましょう。