Home Design SylFS Aura Setup TechNote TODO Walkthrough API (rustdoc) Graphs

ログ規約

発端（2026-08-02）

性能調査で足した診断ログが多すぎたので整理した。 そのとき [TLS][READEND] TIMEOUT という失敗ログまで一緒に消した。 結果、「失敗・エラーしているのにログが出ない」状態を作った。

冗長な情報ログと失敗ログを同列に扱ったのが誤り。

規約

L-1: 失敗は必ずログに残す（例外なし）

以下は常にログを出す。整理・削除の対象にしない。

失敗ログには判断に必要な値を必ず添える （経過時間、上限値、対象のホスト／パス、件数など）。 「失敗しました」だけでは次の一手が決められない。

L-2: エラーを握り潰さない

以下は禁止。どうしても続行する場合はログを出してから続行する。

let _ = fs.save_file(...);        // ← 失敗が消える
result.ok();                      // ← 同上
result.unwrap_or_default();       // ← 失敗と「空」が区別できない

過去に let _ = fs.save_file(...) でキャッシュ保存の失敗が 握り潰され、「非同期取得は完了しているのにキャッシュが効かない」 原因の特定に時間を要した（spec/resource_loading.md）。

L-3: 成功時の毎回ログは出さない

毎フレーム・毎ノード・毎リクエストで出るログは、

成功パスは黙る。必要なら集計して節目で 1 回出す。

L-4: 診断ログには期限と目的を書く

一時的な切り分けログには、いつ・何のために足したかを書く。

// 【2026-08-01計測】paint の 53% がどのプリミティブにも計上されない。
// 原因が判明したら消す。

目的が達成されたら消す。ただし L-1 に該当するものは消さない。

L-5: 整理するときは分類してから消す

一括で消さない。1 件ずつ次を判定する。

種別 扱い
失敗・エラー 残す（L-1）
上限到達・異常な状態 残す
正常終了の記録（EOF 等） 頻度次第。毎回出るなら消す
成功時の値の記録 消す
一時的な計測 消す（L-4）

grep でまとめて消す前に、フォーマット文字列を目で見て分類する。

【2026-08-05】不安定な試験は「賭け」をやめる

事例: test_tcp_socket_table_exhaustion_and_reuse

確かめたい性質は 「テーブルが満杯なら tcp_connect_real が Err("tcp socket table full") を返す」。

ところが試験は 40 本の OS スレッドを一斉に起動し、 「SYN タイムアウト（6 秒）で先行分が抜ける前に全員が揃う」ことに賭けていた。 ホスト負荷が高いと起動が遅れて満杯を観測できず、偽陰性で落ちる。 過去に 5 回「フレーキー解消」の修正が入っており（リトライ 3 回化など）、 どれも賭けの勝率を上げただけで賭け自体は残っていた。

直し方

賭けの部分を状態の直接構築に置き換える。

let occupied = tcp_fill_socket_table_for_test();   // スレッド 0 本
assert_eq!(tcp_connect_real(...), Err("tcp socket table full"));
tcp_clear_socket_table_for_test();

#[cfg(test)] の試験用ヘルパを 2 本足しただけ。

判断規準

T-1: 試験が「AがBより先に起きる」ことに依存していたら、 その順序は検証対象か？ 違うなら状態を直接作る。

T-2: 同じ試験に「フレーキー解消」の注釈が 2 回以上付いていたら、 賭け率の調整ではなく構造を疑う。

T-3: 純粋モジュール側で決定論的に検証済みの性質を、 実機側で重ねて確かめない。実機側は 「その戻り値が呼び出し元まで伝わるか」だけに絞る。

結果: 偽陰性が消え、試験時間も 22.1 秒 → 15.1 秒。

【2026-08-05】ログ行の混線を潰す（L-6）

症状

シリアルログの行が混ざり、機械的に読めなくなっていた。

[NET][DNSSEND]CgQ hoBnstw7HFyzSD-As=fonts.gstatic.com attempt=1
ont Awesome 7 Brands[WARN ] [NET][DNSSEND] host=fonts.gstatic.com ...

リソース取得を 4 並列にしてから頻発した。 診断の土台が壊れると、他のすべての調査が信用できなくなる。

原因は 3 つ重なっていた

# 原因 対処
1 log! が write_fmt を 3 回（レベル・本文・改行）素で呼ぶ。UART へは 1 文字ずつ書くので途中で切り替わる 行を組み立ててから 1 回で出す（emit_line）
2 print! がロックを通らず、ログ行の途中へ割り込む 同じロックを通す（emit_raw）
3 println! が本文と改行で print! を 2 回呼ぶ。1 回ずつロックしても隙間に割り込まれる format_args! の入れ子で改行まで 1 回にまとめる

待ち時間の上限は「時間」で決める

最初は回数（10 万回）でスピンを切ったが短すぎた。 115200 baud では 1 文字 ≈ 87µs、100 文字の行で ≈ 9ms かかる。 10 万回のスピンは 1ms にも満たないので、先行する行を書き終える前に 諦めて混線が残っていた。

tick 基準（20 tick ≈ 200ms）にすれば CPU 速度に依らず 「行 1 本ぶんは待つ」が保証できる。tick が進まない場合の保険として 回数の上限も併せて置く。

行の組み立てはヒープを使わない

String を組むとアロケータのロックを取る。 確保まわりの不具合を調べるためのログ自身が、その経路に依存してしまう。 スタック上の固定長バッファ（kernel/uart_line_buf.rs、512 バイト）で組む。 入り切らない分は文字境界まで戻して ... を付ける （不正な UTF-8 を UART へ流さない）。

不変条件

L-6: ログ 1 行は不可分に出力する。 出力を複数回の書き込みに分けない。分けるなら全体をロックで囲う。

実測

混線行 / 総ログ行
修正前 2 / 399
emit_line + emit_raw 後 1 / 417
println! を 1 回化した後 0 / 435

単体試験は tests/src/test_line_buf.rs に 9 件 （溢れ・UTF-8 境界・ちょうど収まる場合の off-by-one）。

【2026-08-05】自分で書いた T-1 を自分で破っていた

事象

単体試験がまれに 1 件だけ落ちる（845 passed; 1 failed）。 3 回続けて再現せず、落ちた回もテスト名を採れていなかった。

再現を待つのではなく、失敗するまで回して丸ごと保存することで捕捉した。

for i in 1 2 3 4 5 6 7 8; do
  make test > tmp/test_run.log 2>&1
  if grep -qa "test result: FAILED" tmp/test_run.log; then
    grep -a -A 12 "^failures:" tmp/test_run.log; break
  fi
done

4 回目で捕捉:

test_rule_index::state_masks::状態を使わなければゼロ
  left: None   right: Some(0)

原因

この session で私自身が追加した試験だった。 active_states_of はグローバルの ACTIVE（spin::Mutex<Option<RuleIndex>>） を見るが、試験は並列に走るので、 別の試験の clear_active() が挟まると None が返る。

同じ file の少し上に、自分で書いた教訓がある。

T-1: 試験が「AがBより先に起きる」ことに依存していたら、 その順序は検証対象か？ 違うなら状態を直接作る。

守れていなかった。

対処

問い合わせ本体を RuleIndex::states_of(&self, ..) へ移し、 active_states_of はそれに委譲するだけにした。 試験は索引を直接組んで問い合わせる。グローバルを一切使わない。

10 回連続で成功（従来は 8 回に 1 回程度落ちていた）。

追加の規準

T-4: 再現しないフレーキーは「待つ」のではなく 失敗するまで回して出力を丸ごと保存する。 15 秒で回る試験なら 10 回でも 3 分。推測より速い。

T-5: 教訓を書いても、次に自分が書くコードで破る。 新しい試験を足したら、その場で T-1〜T-3 に照らすこと。

【2026-08-05・続】同じグローバルに依存する試験を全部洗った

T-5（新しい試験を足したら既存の規準に照らす）に従い、 css/rule_index.rs の ACTIVE に依存する試験を全部数えた。

試験 状況
test_rule_index::state_masks（今回追加） active_states_of 経由。8 回に 1 回落ちていた → グローバルを使わない形へ修正済み
test_sugi_lab_cascade（24 件） style_tree 経由。style_tree が呼び出しの前後で ACTIVE を設定・解除する

後者は落ちてはいなかったが、2 本の style_tree が重なれば 相手の索引を上書きし合い、間違った候補ルールで照合する。 落ちれば気付けるが、たまたま通ってしまうと 「通ったのに検証できていない」状態になる方が怖い。

style_tree は本体の設計がグローバル前提なので、 こちらは呼び出しを直列化した（style_tree_serialized）。 10 回連続で成功。

production 側の位置づけ

layout は Core 0 の単一スレッドからしか走らないため、この競合は起きない。 ただしこれは get_fs() と同じ種類の「運用上の不変条件」であり、 型システムが保証するものではない。 レイアウトを並列化するときは、先に ACTIVE を引数へ移すこと （この session で get_fs() の同じ申し送りを見落として ファイルシステムを壊した。二度目は避ける）。

追加の規準

T-6: 「落ちていない」は「競合が無い」ではない。 グローバル状態に触る試験は、落ちる前に洗い出して直列化するか、 グローバルを使わない形へ直す。

【2026-08-05】「計装がブラウザを落とした」は誤診だった

最初にこう書いた（誤り）

draw() に計測用ガードを 2 つ足したらブラウザが起動しなくなり、 外したら直ったので「計装が原因」と結論して L-7/L-8 を書いた。

実際は断続的な失敗だった

コードを一切変えずに再実行したら正常に動いた（total=13 ok=13）。 ブラウザが起動しない現象は前から断続的に起きており （この session で total=3 や Loading Secure Page... のまま等、 　異なるコード状態で何度も観測している）、 私の変更とは無関係だった。

「外したら直った」は1 回の観測にすぎない。 自分で書いた R-7（見た目 1 枚で原因を決めつけない）を、 また破った。戻して直ったように見えても、それは 1 標本。

本当の問題: ハーネスが失敗を見逃していた

撮影スクリプトは [LAYOUT][SRC] load_html が出れば 「ブラウザが起動した」と判定していた。 だがブラウザは起動時に空のホームページを読むので、 目的の URL へ行っていなくてもこの印は出る。

結果、ブラウザが起動しないまま「成功」と判定して撮影し、 端末の画面を保存していた。しかも再送も走らない。

対処

目的のホストへ実際に接続したこと（[NET][DNSSEND] host=<host>）を 確かめるようにした。行っていなければ再送し、3 回で諦めて明示的に報告する。

教訓（差し替え）

L-7: 「変更を戻したら直った」は1 標本。 断続的な失敗のある環境では、戻さずにもう一度実行して 再現するかを先に確かめる。実機 1 回が数分でも、それが最短。

L-8: 判定に使う印は、目的の状態に固有でなければならない。 load_html のように「似た状況でも出る」印を使うと、 失敗を成功と誤判定する。

【2026-08-05】撮影ハーネスの判定を直した

見逃していたもの

「ブラウザが起動した」の判定に [LAYOUT][SRC] load_html を使っていた。 だがブラウザは起動時に空のホームページを読むので、 目的の URL へ行っていなくてもこの印は出る。

結果、ブラウザが起動しないまま「成功」と判定して端末の画面を保存し、 再送も走らなかった。失敗が失敗として見えていなかった。

直したが、一度作り込んだ失敗

判定を host=<host>（名前解決・接続まで）に変えたところ、 そこまで 60 秒では届かない回があり、 起動中のブラウザへもう一度キーを送ってしまった。 送ったキーはブラウザが吸うので、かえって壊れる。 3 回連続で起動失敗した。

最終形: 2 段階に分ける

目的 印 失敗時
コマンドが届いたか [LAYOUT][SRC] load_html（速い） 再送する（最大 3 回）
目的地へ着いたか host=<host>（遅い） 再送しない。警告を出すだけ

再送してよいのは「そもそも届いていない」ときだけ。 着いたかどうかは、再送では直らない。

教訓

L-9: 再送の判定と、成否の判定は別の印を使う。 遅い印で再送を決めると、処理中の相手に追い打ちをかける。

L-10: 「失敗を検出できるようにする」変更は、 それ自体が新しい失敗を作りうる。 検出を足したら、正常系が壊れていないかを必ず確かめる。

【2026-08-05】撮影ハーネスの不安定さはログの読み方が原因だった

症状

ブラウザが起動しない回が頻発（一時は 4 回連続）。 端末にはコマンドのエコーすら出ず、シリアルログはログイン直後で止まる。 OS 側のコードを戻しても直らず、環境要因かと思われた。

原因

待ちループが Get-Content -Raw でログ全体を 500ms ごとに読み直していた。

待ちを増やした（host=<host> の確認を足した）ときに悪化したのは、 読み直しの回数がそのぶん増えたため。計測のための待ちが、 計測対象を止めていた。

対処

結果

2 回連続で成功（total=13 ok=13 / total=10 ok=10）。

教訓

L-11: 観測が対象を止めていないか疑う。 ログを読む頻度・量も負荷であり、 シリアルのように詰まると相手が止まる経路では致命的になる。

L-12: 「環境要因だろう」で片付けない。 今回それで 4 回の失敗を見送りかけたが、原因は自分のスクリプトにあった。

【2026-08-05】計装を外したら受信待ちが半減した

役目を終えた計装を撤去した（L-4）。

撤去 呼ばれ方
受信ループの recv呼出 / 受信sleep 1 パケットごと（実測 8118 / 4758 回）
USB 送信の TX成功 / TX失敗 1 フレームごと（実測 40068 回）

効果

撤去前: 受信待ち=11647/25416
撤去後: 受信待ち= 5473/25057   ← 呼び出し回数はほぼ同じ

受信待ちが半減。 計装が受信ループの半分を占めていた。

perf::add は「アトミック 1 回だけ」のつもりだったが、 実際は get_ticks() を2 回（start と add）呼ぶ。 1 パケットごとに 4 回のタイマ読みは、 1 秒あたり数千回の経路では効く。

規準

L-13: 計装は呼ばれる頻度で分類する。 - 節目（1 ページに数回）… 常設してよい - 1 パケット・1 フレーム・1 要素ごと … 調査中だけ。 目的を果たしたら必ず外し、外した状態で測り直す

perf.rs の冒頭に「熱経路に置いても影響が小さい」と書いていたが、 これは誤りだった。訂正済み。

描画側の計装撤去は速度に効かなかった

同じ考えで draw_helpers と kernel/draw.rs の 1 呼び出しごとの計測（TickTimer / AccTimer / Guard、17 行）も外した。

撤去前: total=17461 relayout=6650 frames=70 → 描画部 154 tick/frame
撤去後: total=17601 relayout=6741 frames=72 → 描画部 151 tick/frame

有意差なし。

受信側と何が違ったか

呼ばれる回数 撤去の効果
受信ループ 1 パケットごと（約 13000 回） 受信待ちが半減
描画の原始操作 矩形塗り=11 tick と元々軽い 差なし

「1 呼び出しごと」でも、呼ばれる回数が桁違いだと結論が変わる。 L-13 は「頻度で分類する」だが、 その頻度は推測ではなく実測の回数で判断すること。

撤去自体は正しい後始末（役目を終えた計測を残さない）。 ただし速くなると期待して外すなら、回数を先に見る。