いにしえのバックエンド入門

# 12.05 MB の写真を送ったときの、アプリのログ（全部）
10:52:56.867 INFO  [4a5dcd45] access               POST /api/v12/claims/EXP-2026-5020/receipts 413 51 ms user=arai
# 送った側
  ERR BrokenPipeError  (1070.3 ms)

ログは1行だけ、しかも「413 を返した」と書いてありました。サーバーは断りの返事を書いたつもりですが、利用者には届いていません（前回の Tomcat の読み捨ての上限です）。ログは、サーバーから見えたことしか書かない。利用者の画面で起きたことは、別の手段で知るしかありません。

• ない URL ── /favicon.ico 1回で 500 と 59 行のログ（実測）
• 量 ── 開発のままの設定では、GET 1件で 5 行・533 バイト（実測）
• 出してはいけないもの ── ハッシュ、申請の値、ファイル名がログに（実測）
• 番号・数・健康診断 ── 1件の行を集める、数で見る、DB が止まると 30 秒（実測）

アプリには Spring Boot Actuator と、数を Prometheus の形で出す Micrometer を足しました。ログの設定は、本番向けに次のように変えています。

# 本番向けの application.properties（第13回で変えたところ）
logging.pattern.console=%d{HH:mm:ss.SSS} %-5level [%X{reqId:--}] %-20.20logger{0} %msg%n
management.server.port=8081
management.endpoints.web.exposure.include=health,metrics,prometheus
management.endpoint.health.show-details=always
spring.servlet.multipart.max-file-size=10MB
spring.servlet.multipart.max-request-size=10MB

ブラウザは、頼まなくても /favicon.ico（タブの小さな絵）を取りに来ます。それを1回開いたときのログです。

# /favicon.ico を1回開いたときのログ（直す前）
10:51:57.108 ERROR [9734d104] ApiErrors            問い合わせ番号 ERR-9734d104
org.springframework.web.servlet.resource.NoResourceFoundException: No static resource favicon.ico for request '/favico…
	at org.springframework.web.servlet.resource.ResourceHttpRequestHandler.handleRequest(ResourceHttpRequestHandler.java:…
  …（ここから at の行が 56 行。全部で 59 行）
# 返事
  500  処理できませんでしたerrorId=ERR-9734d104

第7回で作った「それ以外は 500」の係が、「ない URL」まで 500 にして、スタックトレースを 59 行書いていました。ブラウザやロボットがあちこちの URL を叩くたびに、ERROR が積み上がります。これでは本物の 500 が埋もれます。「ない URL」は 404 にして、スタックトレースも書かないように直しました。

第7回からずっと、この 500 はありました。ログを読む習慣がなければ、気づかないということです。

この連載では、SQL を見るために DEBUG のログを足してきました。そのままの設定（開発のまま）と、本番向けの設定で、同じ GET を 500 回送りました。

# 同じ GET を 500 回（ログインした新井さん、2回ずつ）
  設定時間行数バイト1件あたり
  開発のまま2655 ms   2500    266,514   5 行 / 533 B
  本番向け1820 ms   500     52,001    1 行 / 104 B
  開発のまま2091 ms   2500    266,502   5 行 / 533 B
  本番向け2052 ms   500     52,002    1 行 / 104 B
# 開発のままの設定で、GET 1件が書いた行
10:53:08.968 DEBUG [c415eb98] DataSourceUtils      Fetching JDBC Connection from DataSource
10:53:08.969 DEBUG [c415eb98] findVisible          ==>  Preparing: select id, applicant, item, amount, status, version…
10:53:08.969 DEBUG [c415eb98] findVisible          ==> Parameters: EXP-2026-5001(String), 新井(String)
10:53:08.971 DEBUG [c415eb98] findVisible          <==      Total: 1
10:53:08.972 INFO  [c415eb98] access               GET /api/v11/claims/EXP-2026-5001 200 5 ms user=arai

開発のままだと、GET 1件で 5 行・533 バイト。本番向けは受付簿の 1 行・104 バイトです。1日 10 万件なら、53 MB と 10 MB のちがいになります（計算）。この実験では時間の差ははっきりしませんでしたが、ログは書くほどディスクと、読む人の時間を使います。

第11回で、MyBatis の DEBUG ログに bcrypt のハッシュが出ているのに気づきました。利用者を入れなおし、ログイン・領収書・承認をしてから、ログを数えました。

# ログイン・領収書・承認をして、ログを数える（利用者を入れなおしてから）
  bcrypt のハッシュ開発のまま 3本番向け 0
  パスワード開発のまま 0本番向け 0
  クッキー開発のまま 0本番向け 0
  SQL の値（Parameters:）開発のまま 13本番向け 0
  ファイル名開発のまま 1本番向け 0
# 開発のままの設定で出ていた行（一部）
10:53:55.442 DEBUG [-] save                 ==> Parameters: arai(String), {bcrypt}$2a$10$B0GlrG… 新井(String), APPLICANT(String)
10:54:04.956 DEBUG [c128d0d7] insert               ==> Parameters: d43b4ac3-fa09-4449-9b0f-cd2e4464b185(String), EXP-2026-5020(String), 領収書（新幹線）.jpg(S…

パスワードそのものとクッキーは、どちらの設定でも出ていませんでした（この実験では、Spring Security も Tomcat も書いていません）。でも開発のままの設定では、SQL の値としてハッシュや領収書のファイル名が出ていました。前の章の GET の例でも、受付番号と申請者の名前が SQL の値として出ていました。ログは、DB よりずっと多くの人が見る場所です。

本番向けの設定では、SQL の値の行はなくなりました。ログに書くのは、番号と結果までにします。「何の申請か」は受付番号で分かれば十分で、中身は DB にあります。

サーバーは、何人もの頼みごとを同時にこなします。ログの行は、いろいろな人のものが混ざって並びます。そこで、頼みごとが届いたら番号を付け、その番号をログのすべての行に入れます。番号は返事のヘッダー（X-Request-Id）でも返します。

# 頼みごとの番号を付ける係（RequestIdFilter.java）
@Override
protected void doFilterInternal(HttpServletRequest req, HttpServletResponse res, FilterChain chain)
        throws ServletException, IOException {
    String id = HexFormat.of().toHexDigits(ThreadLocalRandom.current().nextInt());
    MDC.put("reqId", id);
    res.setHeader("X-Request-Id", id);  // 画面にも返す。問い合わせのときに使う
    long t = System.nanoTime();
    try {
        chain.doFilter(req, res);
    } finally {
        Object user = req.getAttribute("loginUser");  // UserMdcFilter が入れたもの
        access.info("{} {} {} {} ms user={}", req.getMethod(), req.getRequestURI(), res.getStatus(),
                (System.nanoTime() - t) / 1_000_000, user == null ? "-" : user);
        MDC.clear();
    }
}

番号は SLF4J の MDC（その頼みごとの間だけ持ち歩く入れ物）に入れ、ログの形に %X{reqId} と書いておくと、どの行にも番号が付きます。第7回の問い合わせ番号も、この番号にそろえました。

# 問い合わせ番号を、頼みごとの番号にそろえる（ApiErrors.java）
@ExceptionHandler(Exception.class)  // それ以外 → 500。中身は見せず、番号で結ぶ
ProblemDetail unexpected(Exception e) {
    String reqId = MDC.get("reqId");  // 第13回：問い合わせ番号は、頼みごとの番号と同じにする
    String no = "ERR-" + (reqId != null ? reqId : HexFormat.of().toHexDigits(ThreadLocalRandom.current().nextInt()));
    log.error("問い合わせ番号 {}", no, e);
    ProblemDetail p = problem(HttpStatus.INTERNAL_SERVER_ERROR, "unexpected", "処理できませんでした", "時間をおいてもう一度お試しください。続くときは問い合わせ番号をお知らせください");
    p.setProperty("errorId", no);
    return p;
}

# 名前が 150 文字の領収書で 500 を起こし、番号でログを引く
  HTTP 500   X-Request-Id: 23c165c8   errorId: ERR-23c165c8
$ grep 23c165c8 app.log
10:54:31.882 ERROR [23c165c8] ApiErrors            問い合わせ番号 ERR-23c165c8
10:54:31.927 INFO  [23c165c8] access               POST /api/v12/claims/EXP-2026-5020/receipts 500 245 ms user=arai
  （同じ時間の、番号が付いていない行: 182 行。スタックトレースの続きの行）
# 同じことを、構造化ログ（ECS の JSON）で
  ERROR reqId=6be6d7be  問い合わせ番号 ERR-6be6d7beerror.stack_trace: 182 行
  INFO  reqId=6be6d7be  POST /api/v12/claims/EXP-2026-5020/receipts 500 264 ms user=…
  （番号の付いていない行: 0 行）

利用者が「ERR-23c165c8 と出ました」と言ってくれれば、その番号で grep するだけで、その頼みごとの行が出てきます。ただし、スタックトレースの続きの行（at …）には番号が付きません。ここを解くのが、次の構造化ログです。

Spring Boot は、設定1行でログを JSON（ECS などの決まった形）で書けます。1つの出来事が、必ず1行になります。

# logging.structured.format.console=ecs のときの1行（見やすく改行）
{
  "@timestamp": "2026-10-31T01:54:41.576648739Z",
  "log": {
    "level": "INFO",
    "logger": "access"
  },
  "process": {
    "pid": 1766,
    "thread": {
      "name": "http-nio-8080-exec-6"
    }
  },
  "service": {
    "name": "expenses",
    "version": "0.0.1-SNAPSHOT",
    "node": {}
  },
  "message": "GET /api/v11/claims/EXP-2026-5001 200 58 ms user=arai",
  "user": "arai",
  "reqId": "465dac40",
  "ecs": {
    "version": "8.11"
  }
}

MDC に入れた番号（reqId）と利用者（user）が、そのまま項目になりました。さきほどの 500 を JSON で書かせると、スタックトレースは error.stack_trace の中に入り、番号の付いていない行は 0 行になりました。人の目では読みにくくなりますが、ログを集める道具（検索やグラフ）には、こちらが向いています。

ログは「1件ずつの話」です。「いま全体がどうなっているか」は、数で見ます。Actuator は、窓口ごと・返事ごとの回数と時間を、何も書かなくても数えています。

# 200 を 50 回、ほかの人の申請で 404 を 10 回、ログインなしで 5 回、/favicon.ico を 5 回
  http_server_requests_seconds_count{method="GET",status="401",uri="UNKNOWN"} 5
  http_server_requests_seconds_count{method="GET",status="404",uri="/**"} 5
  http_server_requests_seconds_count{method="GET",status="404",uri="/api/v11/claims/{id}"} 10
  http_server_requests_seconds_count{method="GET",status="200",uri="/api/v11/claims/{id}"} 50
  http_server_requests_seconds_count{method="POST",status="200",uri="UNKNOWN"} 1
# GET /actuator/metrics/http.server.requests?tag=uri:/api/v11/claims/{id}&tag=status:200
  COUNT 50   TOTAL_TIME 0.312 s   MAX 0.060 s

URL は {id} のまとまりで数えられるので、受付番号ごとにばらばらになりません。ログインなしの 401 は門番が止めたので uri が UNKNOWN、ない URL の 404 は /** になりました。直す前なら、ここに 500 が並んでいたはずです。

数は、時間の流れでも見られます。第9回の「トランザクションの中で1秒待つ」を 12 件同時に送り、接続の池を 0.25 秒ごとに見ました。

# 第9回の「中で待つ」を 12 件同時に。接続の池を 0.25 秒ごとに見る（秒・使用中・待ち）
   0.11  0 0    0.37  0 0    0.63  0 0    0.90 10 2    1.16 10 2
   1.43 10 2    1.70 10 2    1.96 10 1    2.22 10 1    2.48 10 1
   2.74 10 1    3.00 10 0    3.26 10 0    3.52 10 0    3.78 10 0
   4.04  9 0    4.30  9 0    4.56  9 0    4.82  9 0    5.08  7 0
   5.35  7 0    5.61  7 0    5.87  7 0    6.13  6 0    6.39  6 0
   6.65  6 0    6.90  6 0    7.16  5 0    7.42  5 0    7.68  5 0
   7.94  5 0    8.20  4 0    8.46  4 0    8.72  4 0    8.97  4 0
   9.24  3 0    9.49  3 0    9.75  3 0   10.01  3 0   10.26  2 0
  10.52  2 0   10.78  2 0   11.04  2 0   11.30  1 0   11.56  1 0
  11.81  1 0   12.07  1 0

使用中はすぐに上限の 10 本に張りつき、2件が接続を待ちました。第9回では「12 件目は 12 秒」という結果から推し量りましたが、数を見れば、その場で分かります。Actuator の窓口は、業務の窓口とは別の番号（8081）で開き、見せるものも health・metrics・prometheus だけにしました。

最後に、練習用の DB を止めてみました。申請を開いてから、健康診断（/actuator/health）を見ます。

# DB を止める前・止めている間・動かしたあと（申請を開いてから、健康診断）
  止める前GET claim 200     90 ms                health 200 UP       74 ms
  止めている間GET claim 500  30178 ms ERR-d8bb10ab   health 503 DOWN  30024 ms
  動かしたあとGET claim 200   2793 ms                health 200 UP       13 ms
# 止めている間の GET 1件で増えたログ
  全部で 678 行（ERROR 1 行、at の行 631 行、WARN 14 行）
  Caused by: java.sql.SQLTransientConnectionException: HikariPool-1 - Connection is not available, request timed out after 30001ms (total=0, a…

申請を開くだけの GET が、30 秒待ってから 500 でした。接続の池が、新しい接続を作れないまま、HikariCP の connectionTimeout（既定 30 秒）まで待ったからです。健康診断も同じく 30 秒かかって DOWN。そして、この1件のために、ログは 678 行増えました。

利用者を 30 秒待たせるより、早くあきらめて「いま使えません」と返すほうが親切です。spring.datasource.hikari.connection-timeout を短くする、健康診断に時間の上限を付ける、といった調整をします。DB を動かしたあとは、最初の GET がつなぎなおしで 2.8 秒、健康診断は 13 ms で UP に戻りました。

まずは自分のアプリのログを、1日分そのまま読んでみてください。ERROR が何件あり、そのうち本当に手を打つべきものが何件か。それだけで、この回の半分は終わります。