テレメトリ

テレメトリは、性質の異なる二つの問いに答えます。ログは個々の判断や失敗を説明し、 トレースは一つのリクエストが処理と時間をどう通過したかを示します。Popcorn Web は両者を 関連付けつつ、開発環境と本番環境に同じ出力先を強制しません。

テレメトリのモデル

アプリケーションコードは pw.Logger(r) から構造化 レコードを書きます。コンテキストは 実行中のトレース識別子を持つため、スパン内で出したレコードには trace_id、span_id、 trace_flags が自動的に入ります。フレームワークの診断も同じロガーを使います。メッセージは 人が読み、型を保った属性はクエリに使います。

package handlers

import (
    "net/http"

    "github.com/shibukawa/popcornweb/pw"
)

func showAccount(w http.ResponseWriter, r *http.Request) {
    accountID := r.PathValue("id")
    pw.Logger(r).Info(
        "account requested",
        pw.String("account_id", accountID),
        pw.Bool("cached", false),
    )
    w.WriteHeader(http.StatusNoContent)
}

レベルは trace から error まであり、設定上の下限には off も使えます。値を メッセージへ埋め込まず、pw.String、pw.Int、pw.Bool などのスカラー用 コンストラクタを使います。timestamp、severity、message、service_name、 trace_id、span_id、trace_flags は出力パイプラインの予約名であり、 アプリケーション属性から置き換えられません。

生成されたデータベース呼び出しは、クエリ診断を通して ステートメントと実行時間を記録できます。bind値のログは独立した機密性の高い設定で、 トレースとの関連付けに必要なものではありません。

パスワード、トークン、セッション値、不要な個人情報をメッセージや属性に入れないでください。 構造化保存は、誤って入れた秘密を安全にするのではなく、検索しやすくします。

リクエストトレースを読む

所要時間はリクエストが遅かったことを示し、スパンの木はどこで待ったかを示します。 フレームワークがリクエスト、レンダー、境界、生成済みDB呼び出しのスパンを開くため、 通常の経路へアプリケーション独自のタイマーを足す必要はありません。

GET /orders                                      842ms
└─ render stream                                 838ms
   ├─ render initial                              41ms
   │  └─ SELECT                                   33ms
   ├─ render boundary  (tb-1)                    797ms
   └─ render boundary  (tb-2)                    120ms

この例ではシェルは速く、tb-1 が1秒近くフォールバックを表示しています。開発 テレメトリビューアはこの木を自動で表示します。それ以外では、OTLPエンドポイントを 設定すると既定の auto 方針が有効になります。

[observability.trace]
enabled = "auto"   # トレースを送出するときは on、それ以外は off
render = true
boundary = true
database = true
statement = true

enabled はこれらのスパンを開くかどうかを決めます。そのうち何本が残るかは別の問いで、 下のどのトレースを残すかが答えます。 アプリケーションが独自のトレーサープロバイダを持つなら enabled = "on"、ホットな経路で スパンのコストを実測して避けたいなら "off" にします。小さな領域や頻繁な配信が多い ページで最初に落とす詳細は boundary = false です。statement = false はDBの時間を残して SQL本文を外します。bind値がスパンへ載ることはありません。

レンダーの分岐

レンダースパンの名前がレスポンスの経路を示します。

名前	レスポンスの経路
render buffered	最初の1バイトより前に完成したドキュメント
render stream	非同期レンダリングしたドキュメント
render live	live配信ストリーム
render navigate	ナビゲーション差分
render redraw	ひとつのコンポーネント自身による応答
render fragment	外部swapライブラリ向けのフラグメント

スパンはレスポンス圧縮前の pw.render.bytes と pw.render.boundaries を持ちます。 レンダリングキャッシュへ問い合わせたレスポンスには pw.render.cache_hits と pw.render.cache_misses も入ります。

ストリームするドキュメントでは、render initial はシェルとフォールバックをコミットする flushで終わります。各境界スパンはそこからフラグメントを書き終えるまでなので、その長さは html.async_concurrency の後ろで待った時間を含め、訪問者がフォールバックを見た時間です。 処理内で独自の pw.StartSpan を開けば、順番待ちと 実行時間を分けられます。

生成された .pw.sql 呼び出しは、実行中のレンダーまたはアプリケーションスパンの下に 現れます。パラメータ化された文と標準DB属性を持ちますが、bind値は持ちません。遅い文には pw.db.slow が付き、関連するクエリ診断から同じ トレース識別子で値、plan、再実行用スニペットを読めます。

サービスをまたぐトレース

ひとつのプロセスの中では、関連付けはコンテキストがすでに運んでいる識別子の組です。 サービスの境界を越えると共有されたコンテキストは存在しないので、識別子は代わりに ワイヤに載ります。W3C Trace Context の traceparent と tracestate フィールドです。

読む側は自動です。traceparent を持って届いたリクエストは、新しいトレースを始めずに 呼び出し元のトレースを続けます。これはどちらの HTTP バックエンドでも同じで、木の根に なるのはリクエストが最初に入ったサービスです。書く側には計装済みのクライアントが要ります。 ヘッダーを作るのはクライアントスパンを開いた当人でなければならないからです——呼ばれた側 が親として採用するのはヘッダーが名指したスパンで、別の場所で書けば呼ばれた側の仕事は 間違った親にぶら下がります。

import "github.com/shibukawa/popcornweb/contrib/otel/otelhttp"

client := otelhttp.NewClient(http.DefaultClient)
request, err := http.NewRequestWithContext(ctx, http.MethodGet, endpoint, nil)
if err != nil {
    return err
}
response, err := client.Do(request)

リクエストのコンテキストを渡してください。context.Background() に置き換えると親子関係が 切れます。独自クライアントには otelhttp.NewTransport を使え、渡したtransport自体は 変更しません。

ローカルの JSONL レコードに載った trace_id をコレクタまで持っていく価値があるのは、 これがあるからです。下にあるトレース1本のクエリが返すのは このサービスが 書いた レコードで、同じ ID をコレクタに投げれば、同じリクエストについて他のサービスが記録した スパンが返ってきます。

ひとつだけ意図的に除外されるクライアントがあります。OTLP エクスポータが POST に使うものです。 エクスポートをトレースすると、エクスポートがスパンを開き、そのエクスポートがまたスパンを 開くので、エクスポータは渡されたクライアントから計装を外します。

フレームワークのスパンが覆うのはフレームワークの処理までです。キャッシュ呼び出しなど ハンドラ固有の処理は pw.StartSpan で囲みます。 セッション、認証、マイグレーションのために内部で発行する文は、クエリ診断から除外されるのと 同じくDBスパンを作りません。

どのトレースを残すか

1リクエストは1スパンではありません。上の木はリクエストのルート、レンダー、初期ビルド、 確定した境界ごと、実行された文ごとにスパンを開くので、3つの領域を待って6つのクエリを 走らせるページは十数個を生みます。この倍率になると、問いは「トレースを取る価値があるか」 ではなく「どのトレースを残す価値があるか」に変わります。

答えは、プロセスとバックエンドのあいだに何がいるかで変わります。前段にコレクタがいるなら、 このプロセスは全部記録してコレクタに決めさせればいい。「失敗したトレースを残す」という 規則を適用できるのはそこだけです——完成したトレースだけが、それが失敗したかどうかを 知っているからです。バックエンドへ直接送る構成は、その段を取り除きます。プロセスが スパンを断れる最後の場所になり、断らなかったスパンはそのまま課金対象になります。

そのため既定値はひとつではなく、環境で決まります。APP_ENV=dev は全トレースを記録し、 それ以外の値は——このフレームワークが知らない名前も含めて——10本に1本を残します。

[observability.trace]
sampler = "parentbased_traceidratio"
sampler_arg = "0.05"

開発だけが例外なのは、いま出したリクエストを見る手段がテレメトリビューアしかないからです。 サンプリングされた開発ループは、たったいま見たページが欠けているループになります。向きも 意味を持ちます。見慣れない環境名は誰かがトラフィックのために足したものなので、記録側では なくサンプリング側に倒れます。

判定はルートで一度だけ行われ、あとは前節の traceparent に載って運ばれます。子スパンが 判定し直すことはありません。継承するからこそトレースは1本になるのであって、各スパンが めいめいサイコロを振ったらそれは束にすぎません。parentbased_ の接頭辞はこれをサービス間へ 広げます。記録すると決めた呼び出し元が下流の比率で切られることはなく、記録しないと決めた 呼び出し元が下流に覆されることもありません。

変更する理由は2つあります。前段にコレクタがいるならここは always_on にして、トレース 全体が見える向こう側でサンプリングする。直接送っていて比率が見合わないなら、トレースを 止めるのではなく sampler_arg を下げる。50本に1本でもリクエストの形は見えますが、ゼロ本 からは何も見えません。

サンプリングされなかったリクエストは、トレースされていないリクエストではありません。スパン 識別子は本物なので、ログレコードには trace_id が載り続け、送出する traceparent は決定内容を 呼び出し先へ伝え、クエリ診断も文ごとのレコードを書きます。 出ないのはスパンだけで、それこそ比率を選んだ目的です。

解釈できない sampler の引数は、全記録へ黙って戻るのではなく起動時にプロセスを止めます。 起動サマリも、解決された sampler とその出どころを報告します。 どちらも理由は同じです。1000本に1本しか残さないプロセスと、トレーサーが壊れたプロセスは、 外から見ると区別がつきません。

サンプラーを触るのは、トレースのコストが問題のときです。知りたいのがレートやパーセンタイル、 ヒット率なら、どんな比率も答えにはなりません。

メトリクス

サンプリングは、トレースからは答えられない問いを作ります。比率を生き延びたトレースから 計算したパーセンタイルは生存者のパーセンタイルですし、「何リクエスト処理したか」に至っては 標本から復元できません。メトリクスがそれを引き受けます。そしてここには一切サンプリングが 掛かりません。サンプラーが何を残したかによらず、計器はすべてのリクエストを数えます。2つの シグナルが並んで存在するのは、片方がもう片方の安価版だからではなく、この違いのためです。

送り先はトレースと同じエンドポイントで、/v1/traces の隣に /v1/metrics が足されるだけです。 すでに送出しているデプロイに追加の設定は要りません。届くものは2層に分かれます。

1層目は、ゼロコードのOpenTelemetryエージェントが入れるのと同じ集合です。メソッド・ ステータス・ルートで引ける http.server.request.duration、外向き呼び出しの http.client.request.duration、ドライバと文のキーワードごとの db.client.operation.duration、 コネクションプールの状態、そして go.* のメモリ・goroutine・GC。名前も単位も属性も仕様の ままです。ダッシュボードもアラートも、そして運用者の前職も、すでにその名前を知っています。

2層目は、外部のエージェントには見えない半分です。pw.render.duration と pw.render.bytes は レンダーモードを持つので、非同期レンダリングが リクエストごとに選んだ分岐が、1レスポンスずつではなく分布として見えます。 pw.boundary.settle.duration はフォールバックが画面を占めていた時間、 pw.live.delivery.duration はlive領域が実際に入れ替わった間隔、 pw.live.subscriptions.active はリクエスト単位の記録には決して現れない同時接続数です。 キャッシュは結果属性を持つカウンタとして届きます。

-- ヒット率は、メトリクスを読む側が計算する
sum(pw_render_cache_operations{pw_cache_result="hit"})
  / sum(pw_render_cache_operations)

フレームワークは項を出し、商は出しません。分母のないヒット率では、効いているキャッシュと そもそも対象がなかったキャッシュを区別できないからです。同じ規則が、あるはずと思う計器を いくつか消しています。リクエスト数のカウンタはありません——所要時間ヒストグラムのcountが その数で、同じ数の2つ目の名前はいずれ食い違います。平均所要時間のゲージもありません （sumをcountで割ればいい）。秒間リクエスト数の系列もありません。区間あたりのレートは読む側が 計算するもので、あらかじめ窓を切った数は、このプロセスが窓を推測して作ったものになります。

これを現実的なコストに収めているのは、パスではなくルートを使う規則です。http.route は 登録されたパターンを持つので、/orders/{id} は注文ごとではなく1系列になります。どのルートにも マッチしなかったリクエストは、生パスではなくルート属性そのものを持ちません。生成された ページとAPIハンドラは何もしなくてもルートを報告します。自分でレスポンスを書く手書きの ハンドラは、pw.SetRoute(w, r) を一度呼びます。

グループは個別に切れますが、実際に切る意味があるのは1つだけです。

[observability.metrics]
runtime = false   # プラットフォームのエージェントが go.* を集めている

runtime は二重取得があり得る唯一のグループです。ほかにはありません——レンダーモードや コンポーネントキャッシュのヒットを外から数えられるものは存在しないので、切れば間隔ごとの コールバック1回が浮き、問いが失われます。

メトリクスは間隔ごとに収集され、既定は60秒です。だから1本の遅いリクエストには向きません ——それはトレースとクエリ診断の仕事です——そして、多数のリクエストを跨いで初めて見えるもの すべてに向いています。

開発環境の出力先

pw dev では、アプリケーションのレコードを読みやすいテキストとしてターミナルへ出し続けます。 開発テレメトリビューアが有効なら、関連付いたログとトレースも受信します。それとは独立して、 pw dev はアプリケーションログを既定でプロジェクト内の .log へ JSONL 形式で保存します。

一回の pw dev 起動につき pw-dev-*.jsonl が一つ対応します。再ビルドやアプリケーションの 再起動は同じファイルへ追記し、次の pw dev 起動では新しいファイルを使います。ディレクトリと ファイルは最初のレコードで初めて作られるため、何も出力しない実行はファイルを残しません。 既存ファイルを切り詰めたり自動削除したりせず、新しい pw init プロジェクトでは .log/ を Git の対象外にします。既存プロジェクトは自身の .gitignore に .log/ を追加してください。 ディレクトリとファイルは、OSの規則が許す範囲で所有者だけが使える権限で作られます。

[dev.logs]
enabled = true
directory = ".log"

ビューアには、独立したプロジェクト設定があります。

[dev.otel]
enabled = true

directory はプロジェクト内の相対パスでなければなりません。enabled = false にすると、 ターミナルと設定済みの OTLP 出力を維持したままローカルファイルだけを止めます。ファイル システムのエラーはローカル保存だけを無効化し、一度診断を出します。アプリケーションは停止しません。

各 JSON 行には安定した timestamp、severity、message、service_name があります。 関連付いたレコードには trace_id、span_id、数値の trace_flags も入ります。 アプリケーション属性は型を保ったトップレベルフィールドなので、数値や真偽値をクエリに使えます。

DuckDBでJSONLをクエリする

DuckDB は任意で導入する外部ツールであり、pw は同梱、インストール、実行のいずれも行いません。 データベースへ取り込まずに複数回の実行を横断して検索できます。プロジェクトルートで 実行するか、glob を設定済みディレクトリへ合わせてください。Popcorn Web のエージェントSkillも このスキーマを知っているため、「直近1時間で繰り返したエラーを見せて」のような質問からクエリを 作れます。

FROM read_ndjson_auto('.log/*.jsonl', union_by_name = true)
ORDER BY timestamp DESC
LIMIT 100;

union_by_name = true により、ファイルごとに任意のアプリケーション属性が異なっていても 読み取れます。未知のフィールドを絞り込む前に、推論された型を確認します。

DESCRIBE SELECT *
FROM read_ndjson_auto('.log/*.jsonl', union_by_name = true);

最近の警告とエラーを調べるクエリです。

SELECT timestamp, severity, service_name, message, trace_id
FROM read_ndjson_auto('.log/*.jsonl', union_by_name = true)
WHERE lower(severity) IN ('warn', 'error')
  AND timestamp >= now() - INTERVAL '1 hour'
ORDER BY timestamp DESC
LIMIT 100;

繰り返し発生しているイベントを数えます。

SELECT service_name, severity, message, count(*) AS occurrences
FROM read_ndjson_auto('.log/*.jsonl', union_by_name = true)
GROUP BY ALL
ORDER BY occurrences DESC
LIMIT 50;

一つのトレースを発生順に並べます。

SELECT timestamp, severity, message, span_id
FROM read_ndjson_auto('.log/*.jsonl', union_by_name = true)
WHERE trace_id = 'REPLACE_WITH_TRACE_ID'
ORDER BY timestamp;

一回の起動だけに絞る場合、JSONリーダーの filename オプションに対応した DuckDB では、 入力元パスを仮想列として取り出せます。

SELECT filename, timestamp, severity, message
FROM read_ndjson_auto(
    '.log/*.jsonl',
    union_by_name = true,
    filename = true
)
WHERE filename = '.log/REPLACE_WITH_RUN_FILE.jsonl'
ORDER BY timestamp;

探索的な分析は読み取り専用にしてください。利用者が渡した値はSQL文字列へ連結せず、bindするか 慎重に引用します。実行中のアプリケーションが走査中に追記することがあります。最新レコードが 一時的に不完全なら、もう一度実行してください。

本番環境の出力先

pw dev 以外で Popcorn Web がローカルログファイルを作ることはありません。本番ログは プラットフォームのログ収集器に向けた標準出力上の構造化 JSON となり、OTLP は設定済みの エンドポイントへ送られます。ファイルの所有、ローテーション、保持期間、アクセス制御、削除は、 アプリケーションコンテナではなくデプロイ先のプラットフォームが管理します。

そのエンドポイントは2種類のどちらかであり、この選択はアドレス以上のものを決めます。前段の コレクタ——サイドカー、ノードエージェント、ゲートウェイ——は、リトライとバッファリングを プロセスの寿命の外に置き、リソース属性を下流で足し、バックエンドの資格情報を1か所に集め、 テイルサンプリングを選択肢に残します。収集基盤へ直接送る構成は、運用するコンポーネントを 1つ減らし、開発ループとデプロイの違いをURLだけにします。その代償が、いま挙げた全部です。 プロセス内で使い切ったリトライは、先送りではなくレコードの喪失になります。資格情報は全 インスタンスの otel.headers に置かれます。そしてヘッドサンプリングが唯一の段になります。

すでにコレクタを運用しているか、いずれ運用する見込みがあるならコレクタ経由を選んでください。 小規模なデプロイなら直接送出でよく、その場合は sampler を意図して設定してください。 あなたのトラフィックを知らないまま選ばれた既定値のままにはしないことです。

レベル、stdout_format、サービス識別子、リソース属性、OTLPのendpoint/headersは、TOML または対応する OTEL_* 環境変数から アプリケーション設定一覧で設定します。ローカル保存の スイッチは、デプロイ済みアプリケーションではなく開発プロセスを制御するため、 popcornweb.toml に属します。

OTLP は、リクエスト処理がコレクタを待たないよう上限付きキューを使い、満杯ならレコードを 破棄します。設定された間隔で未充足のバッチも送り、終了時には期限付きの最終flushを行います。 キュー、バッチ、リクエストのtimeout、終了時timeoutの各設定は同じ設定リファレンスにあります。

ローカル保存を使わない場面

.log をデプロイ先のストレージ、監査証跡、コレクタの代替として使わないでください。 ローテーション、保持期間の強制、転送、アクセス制御のワークフローを持たないためです。また、 知りたいことがリクエスト内の所要時間だけなら、開始・終了ログを増やすのではなくトレースを使います。

運用チェックリスト

• 安定したイベント名と型付き属性を記録し、データをメッセージへ埋め込まない。
• リクエストのコンテキストを pw.Logger へ渡し、トレースとの関連を保つ。
• .log/ をコミットせず、ローカル方針に沿って古いファイルを削除し、本番ストレージにしない。
• 機密フィールドを含み得る生ファイルではなく、クエリと要約を共有する。
• リクエストの形と時間はテレメトリビューア、複数レコードや実行を横断する問いは DuckDB で調べる。

開発ループ全体は pw dev、対話的なトレース画面は 開発テレメトリビューアを参照してください。