ログ#

Log.info("起動しました");
Log.warn("設定が足りません: %s".formatted(key));
Log.debug("見つかりませんでした");
Log.error(cause, "保存できませんでした: id=%d".formatted(id));

[2026-09-07 13:12:19]-[main] error 保存できませんでした / java.lang.IllegalStateException: 書けません

ロガーの名前#

どのログにも必ず入るもの#

SQL の本数と時間がどのログにも入るのが要点です。 N+1 は「ログを見れば分かる」ようにしてあります（要件 NF-O-02）。

アクセスログ#

1リクエストに1行、リクエストの終わりに出ます。ルートに当たらなくても出ます（404 も残る）。

{"logger_name":"access","level":"INFO","message":"GET /users/42 200",
 "request_id":"m1abcd-xyz-1","sql_execute_count":2,"sql_execute_time":4.0,
 "method":"GET","path":"/users/42","query":"","status":200,"elapsed":12.34,
 "matched":true,"bot":false}

ボットを分ける#

server.bot_access_log（既定 true）が有効なら、ボットの行は access.bot に出ます。 判定は User-Agent の一覧（crawler-user-agents）との照合です。

切る#

server.access_log = false で、1行も出さなくなります。

server {
	access_log = false
}

1リクエストの中でいちばん大きいのがここです（割り当ての約4割。約 3,400 byte）。 切ると、行を組み立てる仕事も、ボット判定（User-Agent の照合）も止まります。 秒あたりの本数は1割ほど変わります（10 コアの Mac・8接続で 52,537 → 57,030 rps）。 台によって違うので、切る前に自分の台で測ってください （jimble-load/load.sh が、出す版と出さない版を並べて測ります）。

**メトリクスとトレースは残ります。**切って消えるのはアクセスログだけです。

実行 ID#

36進の時刻-乱数-連番 で、リクエスト（や WebSocket のメッセージ、バッチ）ごとに1つ採番されます。 持ち回りは ScopedValue で、MDC は使っていません。

先頭が時刻なので、ID を並べ替えると時系列になります。

SQL のログ#

SQL の本数と時間は自動で数えます（上の表）。

log.db = true にすると、アプリが DBLog.save(db, data) で書いたものが db_log テーブルに入ります。SQL を自動で記録する機能ではありません。

logback の設定#

jimble は logback とエンコーダを持っていますが、設定ファイルはアプリのものです。 jimble new の雛形は conf/logback.xml を作ります（conf/ は jar に入ります）。

<configuration>

	<!-- 人が読む形 -->
	<appender name="console" class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>%d{HH:mm:ss.SSS} %-5level %logger{20} - %msg%n</pattern>
			<charset>UTF-8</charset>
		</encoder>
	</appender>

	<!-- 例外。スタックトレースを字下げして出す（jimble 同梱） -->
	<appender name="error" class="ch.qos.logback.core.ConsoleAppender">
		<target>System.err</target>
		<encoder class="io.jimble.util.log.encoder.LogbackErrorEncoder"/>
	</appender>

	<!-- 機械が読む形。1行に1つの JSON（jimble 同梱） -->
	<appender name="json" class="ch.qos.logback.core.ConsoleAppender">
		<encoder class="io.jimble.util.log.encoder.LogbackJsonEncoder"/>
	</appender>

	<logger name="access" level="INFO" additivity="false">
		<appender-ref ref="json"/>
	</logger>

	<logger name="access.bot" level="INFO" additivity="false">
		<appender-ref ref="json"/>
	</logger>

	<logger name="error" level="ERROR" additivity="false">
		<appender-ref ref="error"/>
	</logger>

	<root level="INFO">
		<appender-ref ref="console"/>
	</root>

</configuration>

環境で分けたいときは、logback.xml の代わりに -Dlogback.configurationFile=conf/logback.prod.xml を渡してください。

テストで拾う#

@BeforeEach
void captureLog () {

	Log.sink((loggerName, level, message, data, throwable) ->
		logs.add(new Entry(loggerName, level, message, data)));

}

@AfterEach
void restoreLog () {

	Log.resetSink();

	// 設定を触るテストがあるので、必ず戻す（残すと後ろのテストが理由なく落ちる）
	Conf.reload();

}

Log.sink(...) は全体を差し替えます。@AfterEach で Log.resetSink() を忘れないでください。

メトリクス#

Metrics.snapshot() が、いまの値をまとめて返します。

get("/metrics", context -> context.response().json(Metrics.snapshot()));

返る形はこうです。

{
  "counter": { "http.request": 1234, "http.status.2xx": 1230, "http.status.5xx": 4 },
  "latency": {
    "http.GET /posts/{id}": {
      "count": 1200, "sum_ms": 4321.0, "max_ms": 812.3,
      "p50_ms": 10, "p95_ms": 100, "p99_ms": 500,
      "bucket": { "1": 300, "5": 700, "10": 150, "50": 40, "100": 8, "500": 1, "1000": 1, "5000": 0, "over": 0 }
    }
  },
  "gauge": { "db.pool.main.active": 3, "db.pool.main.idle": 5 }
}

何が勝手に入っているか#

自分で入れる#

Metrics.count("posts.created");
Metrics.record("search.elapsed", elapsedNanos);
Metrics.gauge("cache.size", () -> cache.size());

Metrics.gauge("mq.notice.pending", () -> noticeQueue.pendingCount());

トレース#

サービスをまたいだ1本の流れを見る（要件 NF-O-05）。使うときだけ依存が増えます。

// build.gradle.kts
implementation("io.jimble:jimble-otel:0.2.1")

public static void main (String[] args) {

    JimbleOtel.install("my-app", "http://localhost:4318");

    new JimbleServer(...).start();

}

これだけで、次のものに自動で区間が付きます。

アプリの中を細かく見たいところは自分で足せます。

try (Span span = Tracing.start("画像の変換", SpanKind.internal)) {
    span.attribute("file", name);
    convert(file);
}

サービスをまたぐ#

入ってきた traceparent（W3C Trace Context）は自動で引き継ぎます。 jimble の HTTP クライアントから出るときも自動で付きます。

// 相手側のトレースが、こちらの続きとして繋がる
new HttpGetExecutor("https://api.example.com/users").execute();

MQ も繋がります。積んだリクエストと、何分もあとに別のプロセスで動いた処理が1本になります。 そのために traceparent をキューの行に持っています（data には入れません）。

それ以外の経路で外へ渡すときは自分で入れてください。

String traceparent = Tracing.traceparent();   // トレースが無効なら null

ログと突き合わせる#

トレースが有効なとき、すべてのログに trace_id と span_id が入ります。 実行 ID（request_id）はそのままなので、いままでの集計は壊れません。

{"request_id":"mttvgm93-10676dj-1","trace_id":"4bf92f35...","span_id":"00f067aa...", ...}

全部は拾わない#

流量が多いと送る先が持ちません。割合を渡してください。

JimbleOtel.install("my-app", "http://localhost:4318", 0.1);   // 10 本に1本

送り先#

OTLP の HTTP（/v1/traces）へ protobuf で送ります。OpenTelemetry Collector でも、 Jaeger でも、Grafana Tempo でも、OTLP を受けるものなら何でも構いません。

自分で出す先を書く#

Tracer は 2 メソッドの interface です。標準出力に出す、社内の仕組みへ送る、 テストで中身を見る、といったときは自分で書けます。テスト用の RecordingTracer は jimble-core に入っています。

RecordingTracer tracer = new RecordingTracer();
Tracing.use(tracer);

// ... テストしたい処理 ...

assertEquals("GET /posts/{id}", tracer.spans().get(0).name());

設定キー#

日本語が化けるときは -Dstdout.encoding=UTF-8 -Dstderr.encoding=UTF-8 を付けてください （本番で動かす）。