投稿日：
2019年4月30日
最終更新日：
【SpringBoot2】UUIDを自動採番してX-Request-Idとしてlogbackのログに埋め込む方法【MDC】
YouTubeも見てね♪
Anker PowerCor
旅行には必須の大容量モバイルバッテリー！
[ノースフェイス] THE NORTH FACE メンズ アウター マウンテンライトジャケット
防水暴風で耐久性抜群なので旅行で大活躍です！
レッドブル エナジードリンク 250ml×24本
翼を授けよう！
ドラゴンクエスト メタリックモンスターズギャラリー メタルキング
みんな大好き経験値の塊をデスクに常備しておこう！
Bauhutte ( バウヒュッテ ) 昇降式 L字デスク ブラック BHD-670H-BK
メインデスクの横に置くのにぴったりなおしゃれな可動式ラック！
BANDAI SPIRITS ULTIMAGEAR 遊戯王 千年パズル 1/1スケール
もう一人の僕を呼び覚ませ！！
サンディスク microSD 128GB
スマホからSwitchまで使える大容量MicroSDカード！
目次
サーバーログを漁りやすくしよう
リクエストを特定するIDは重要
APIシステムやWebシステムを開発していると、システム障害や調査のためにログを漁ることは頻繁にあると思います。
その際に、同一リクエスト内のログを絞りこむための情報をあらかじめログのパターンに仕込んでおかないと、他のリクエストのログと混合してしまい厳密な調査が出来ません。
しかし、SpringBootとLogbackを使っていれば、ライブラリを追加する事無くMDCと言う機能を使って簡単にログに独自の値を埋め込む事が可能です。
MDCとは？
MDCとは、Mapped Diagnostic Contextsという機能の事を指し、ログ情報に対して独自の情報を付与して出力する事が可能になります。
実際には、SLF4jの機能ですが、Logback自体もSLF4jの作者が作ったライブラリなので同様の機能が搭載されています。
今回は、Filterで自動採番したUUIDをMDCとしてログパターンに埋め込む方法をご紹介致します♪
手順
Filterの準備
まずは、MDCにUUIDを追加するFilterクラスを用意しましょう。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
|
package tech.blogenist.service.account.api.infrastructure.filter.x_request_id;
import java.io.IOException;
import java.util.UUID;
import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import org.slf4j.MDC;
public class MdcXRequestIdFilter implements Filter
{
public static final String KEY = "x-request-id"; //logback内から取得する際のキー
@Override
public void doFilter( ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain )
throws IOException, ServletException
{
UUID uuid = UUID.randomUUID();//UUIDの発行
try
{
MDC.put( KEY, uuid.toString() );// MDCに追加
filterChain.doFilter( servletRequest, servletResponse );
}finally
{
MDC.remove( KEY );
}
}
}
|
Configクラスの実装
次に、上記のクラスを@Configurationで適用させましょう。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
|
package tech.blogenist.service.account.api.infrastructure.filter.x_request_id;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
@Configuration
public class XRequestIdFilterConfig
{
@Bean
public MdcXRequestIdFilter mdcXRequestIdFilter()
{
MdcXRequestIdFilter filter = new MdcXRequestIdFilter();
return filter;
}
}
|
logbackのパターンを修正
では、実際にlogbackのパターンにFilterクラスで追加したx-request-idを埋め込んでみましょう。
|
1
2
3
4
|
...
<!-- %X{x-request-id}を追加 -->
<property name="FORMAT" value="[%-5level] [%X{x-request-id}] [%d{yyyy-MM-dd HH:mm:ss.SSS}] [%logger{36}] - %msg%n" />
...
|
確認
では、実際にサーバーを起動してリクエストを投げてみましょう。
ちなみに、FilterにてMDCを追加しているので、起動ログは以下のように空白となりますので気をつけてください。
[INFO ] [] [2019-04-30 20:11:40.848] [t.b.s.account.AccountApplication] - Started AccountApplication in 2.575 seconds (JVM running for 23.541)
リクエストを投げると以下のようなログが出力されると思います。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
|
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.005] [o.h.q.c.internal.CriteriaQueryImpl] - Rendered criteria query -> select generatedAlias0 from CurrentAccountInfomationsTableEntity as generatedAlias0 where generatedAlias0.accountId=:param0
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.005] [org.hibernate.SQL] - select currentacc0_.account_id as account_1_2_, currentacc0_.account_infomation_id as account_4_2_, currentacc0_.created_at as created_2_2_, currentacc0_.updated_at as updated_3_2_ from account.current_account_infomations currentacc0_ where currentacc0_.account_id=?
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.010] [org.hibernate.loader.Loader] - Result set row: 0
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.010] [org.hibernate.loader.Loader] - Result row: EntityKey[tech.blogenist.service.account.entity.db.account.CurrentAccountInfomationsTableEntity#component[value]{value=10001}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.011] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.CurrentAccountInfomationsTableEntity#component[value]{value=10001}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.011] [org.hibernate.SQL] - select accountinf0_.id as id1_0_0_, accountinf0_.account_id as account_7_0_0_, accountinf0_.age as age2_0_0_, accountinf0_.created_at as created_3_0_0_, accountinf0_.display_name as display_4_0_0_, accountinf0_.name as name5_0_0_, accountinf0_.sex_type as sex_type8_0_0_, accountinf0_.updated_at as updated_6_0_0_, accountsta1_.id as id1_1_1_, accountsta1_.created_at as created_2_1_1_, accountsta1_.updated_at as updated_3_1_1_, sextypesta2_.type as type1_3_2_, sextypesta2_.name as name2_3_2_ from account.account_infomations accountinf0_ left outer join account.accounts accountsta1_ on accountinf0_.account_id=accountsta1_.id left outer join account.sex_types sextypesta2_ on accountinf0_.sex_type=sextypesta2_.type where accountinf0_.id=?
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.014] [o.h.l.p.e.p.i.ResultSetProcessorImpl] - Starting ResultSet row #0
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.014] [o.h.l.p.e.p.i.EntityReferenceInitializerImpl] - On call to EntityIdentifierReaderImpl#resolve, EntityKey was already known; should only happen on root returns with an optional identifier specified
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.015] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.AccountInfomationsTableEntity#component[value]{value=20002}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.016] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.AccountInfomationsTableEntity#component[value]{value=20002}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.016] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.AccountsTableEntity#component[value]{value=10001}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.016] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.AccountsTableEntity#component[value]{value=10001}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.017] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.SexTypesTableEntity#component[type]{type=MALE}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.017] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.SexTypesTableEntity#component[type]{type=MALE}]
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.017] [o.h.r.j.i.ResourceRegistryStandardImpl] - HHH000387: ResultSet's statement was not registered
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.018] [o.h.l.e.p.AbstractLoadPlanBasedEntityLoader] - Done entity load : tech.blogenist.service.account.entity.db.account.AccountInfomationsTableEntity#AccountInfomationIdValue(value=20002)
[DEBUG] [f31e75fa-e295-4318-b395-8daf9dc9ed3e] [2019-04-30 20:19:34.018] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.CurrentAccountInfomationsTableEntity#component[value]{value=10001}]
|
念のため、もう一度同じリクエストを投げてみましょう。
|
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
|
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.232] [o.h.q.c.internal.CriteriaQueryImpl] - Rendered criteria query -> select generatedAlias0 from CurrentAccountInfomationsTableEntity as generatedAlias0 where generatedAlias0.accountId=:param0
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.232] [org.hibernate.SQL] - select currentacc0_.account_id as account_1_2_, currentacc0_.account_infomation_id as account_4_2_, currentacc0_.created_at as created_2_2_, currentacc0_.updated_at as updated_3_2_ from account.current_account_infomations currentacc0_ where currentacc0_.account_id=?
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.235] [org.hibernate.loader.Loader] - Result set row: 0
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.235] [org.hibernate.loader.Loader] - Result row: EntityKey[tech.blogenist.service.account.entity.db.account.CurrentAccountInfomationsTableEntity#component[value]{value=10001}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.237] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.CurrentAccountInfomationsTableEntity#component[value]{value=10001}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.237] [org.hibernate.SQL] - select accountinf0_.id as id1_0_0_, accountinf0_.account_id as account_7_0_0_, accountinf0_.age as age2_0_0_, accountinf0_.created_at as created_3_0_0_, accountinf0_.display_name as display_4_0_0_, accountinf0_.name as name5_0_0_, accountinf0_.sex_type as sex_type8_0_0_, accountinf0_.updated_at as updated_6_0_0_, accountsta1_.id as id1_1_1_, accountsta1_.created_at as created_2_1_1_, accountsta1_.updated_at as updated_3_1_1_, sextypesta2_.type as type1_3_2_, sextypesta2_.name as name2_3_2_ from account.account_infomations accountinf0_ left outer join account.accounts accountsta1_ on accountinf0_.account_id=accountsta1_.id left outer join account.sex_types sextypesta2_ on accountinf0_.sex_type=sextypesta2_.type where accountinf0_.id=?
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.241] [o.h.l.p.e.p.i.ResultSetProcessorImpl] - Starting ResultSet row #0
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.242] [o.h.l.p.e.p.i.EntityReferenceInitializerImpl] - On call to EntityIdentifierReaderImpl#resolve, EntityKey was already known; should only happen on root returns with an optional identifier specified
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.242] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.AccountInfomationsTableEntity#component[value]{value=20002}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.AccountInfomationsTableEntity#component[value]{value=20002}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.AccountsTableEntity#component[value]{value=10001}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.AccountsTableEntity#component[value]{value=10001}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.engine.internal.TwoPhaseLoad] - Resolving associations for [tech.blogenist.service.account.entity.db.account.SexTypesTableEntity#component[type]{type=MALE}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.SexTypesTableEntity#component[type]{type=MALE}]
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.r.j.i.ResourceRegistryStandardImpl] - HHH000387: ResultSet's statement was not registered
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.l.e.p.AbstractLoadPlanBasedEntityLoader] - Done entity load : tech.blogenist.service.account.entity.db.account.AccountInfomationsTableEntity#AccountInfomationIdValue(value=20002)
[DEBUG] [5b6faa3d-17e4-4401-86cc-2663f2dccc96] [2019-04-30 20:20:29.243] [o.h.engine.internal.TwoPhaseLoad] - Done materializing entity [tech.blogenist.service.account.entity.db.account.CurrentAccountInfomationsTableEntity#component[value]{value=10001}]
|
正しくUUIDが採番されていますね♪
終わりに
以上のように、少ない実装で簡単にログにX-Request-IDを埋め込む事が出来ました。
Logbackを導入する事でログ周りのカスマイズがとても簡単になるので、皆さんも是非試してみてください。