`mise`が固まった。原因は plugin 内の再帰実行だった¶

mise は、プロジェクトごとにツールの版や環境変数を切り替える CLI だ。Nix のパッケージを mise から扱う nix plugin（mise-nix）を使っていたところ、ある日mise configが返ってこなくなった。この記事では、straceのない環境で/procだけを手がかりに待ち先をたどり、plugin 内の再帰実行によるデッドロックへ行き着くまでを順に示す。

症状と最初の切り分け¶

mise と mise-nix の検証時のバージョンは記録していない。ここで扱うのは、ログに残るプロセスの待機状態と、plugin 内の再帰呼び出しを止めると解消した事例だ。

次のようにtimeoutを付けて実行すると、設定ファイルやenv.shの読み込みログまでは出るが、その先に進まない。

timeout 3s mise config -v

最初はenv.shを疑った。中に次のような処理があったためだ。

export GIT_ORIGIN_DIR=$(git origin-dir)

そこでmiseと同じ条件で、env.shを直接 source してみた。

time timeout 3s /usr/bin/bash --noprofile -c '
  . "/home/my-user/dev/repo-path/ops/env.sh"
  . "/home/my-user/dev/repo-path/.worktrees/review-duckdb/ops/env.sh"
  export -p >/dev/null
'

こちらはすぐにstatus=0で終わったので、env.shは原因ではなさそうだった。

`/proc`で待ち先を調べる¶

straceが入っていなかったので、/procを見ることにした。まず、止まっているmiseがカーネルのどこで待っているか（wchan）を確認する。

mise config -v &
pid=$!

sleep 1
ps -o pid,stat,wchan:32,cmd -p "$pid"

wchanの列には次の値が出た。

1	`locks_lock_inode_wait`

kernel stack も確認する。

sudo cat /proc/"$pid"/stack

locks_lock_inode_wait
__do_sys_flock
__x64_sys_flock
...

miseはflock(2)の解放待ちで止まっていた。

lock holder を追う¶

/proc/locksを見ると、同じ lock に複数のプロセスが並んでいた。先頭の PID 390834が lock を保持している holder で、->の付いた行はその解放を待つプロセスだ。

1
2
3

FLOCK ADVISORY WRITE 390834 08:50:1959 0 EOF
-> FLOCK ADVISORY WRITE 390879 08:50:1959 0 EOF
 -> FLOCK ADVISORY WRITE ...

holder の fd をたどると、lock の対象は次の mise の cache lock だった。

1	`/home/my-user/.cache/mise/lockfiles/628ccf5e6073db31`

では、holder はなぜ lock を解放しないのか。holder 自身の待ち先を見る。

ps -o pid,stat,wchan:32,cmd -p 390834

1	`390834 Sl anon_pipe_read mise ls --current --installed --json`

holder 自身は pipe の read 待ちだった。/proc/390834/syscallと fd を調べると読んでいたのは fd 11 の pipe で、その write 側を持つプロセスを探すと次の 2 つが見つかった。

1 2	`pid=390834 fd=11 cmd=mise ls --current --installed --json pid=390879 fd=1 cmd=mise ls --current --installed --json`

つまりmise lsの実行中に、もうひとつmise lsが起動しており、外側（390834）は内側（390879）の stdout を読もうとしていた。さらに PID 390879のwchanを見ると、次のとおり lock 待ちで止まっていた。

1	`locks_lock_inode_wait`

内側が待っているのは、外側のmiseが保持しているのと同じ lock だった。構造を図にすると次のようになる。

outer mise
  ├─ cache lock を保持
  └─ inner mise の stdout を待つ

inner mise
  └─ outer mise が持つ cache lock を待つ

外側は内側の終了を待ち、内側は外側の lock 解放を待つ。互いに相手を待っているので、どちらも先へ進めないデッドロックだった。

再帰実行の出所¶

mise ls --current --installed --jsonを検索すると、nix plugin の次のファイルに見つかった。

1	`~/.local/share/mise/plugins/nix/lib/nix_env.lua`

該当箇所はcollect_man_paths()の次の呼び出しだ。

local ok, tool_json = pcall(
  cmd.exec,
  "mise ls --current --installed --json 2>/dev/null"
)

nix plugin は、active な Nix tools のMANPATHを集めるために、plugin の処理中からmise CLI 自身を呼んでいた。今回の実行経路では、外側のmiseが cache lock を保持した状態でここに入り、内側のmiseが同じ lock を取りに行って停止していた。

pcall()で囲んであっても、このデッドロックは防げない。pcall()が捕まえるのはエラーであり、cmd.exec()が返ってこなければpcall()も返ってこないためだ。

再帰呼び出しを止めると直った¶

確認のため、該当処理を一時的に無効化した。

local ok, tool_json = false, nil

さらに既存の cache の影響を避けるため、空の cache directory で試した。

tmp=$(mktemp -d)

MISE_CACHE_DIR="$tmp" timeout 5s \
  mise ls --current --installed --json

echo "status=$?"

結果は次のとおりで、timeoutの制限時間内に終わった。

1	`status=0`

mise hook-envも同様にstatus=0になった。これで、nix plugin 内の再帰的なmise lsが原因だと確認できた。

まとめ¶

今回のデッドロックは、次の流れで発生していた。

outer mise が cache lock を保持
↓
nix plugin の collect_man_paths() が mise ls を再帰実行
↓
inner mise が同じ lock を待つ
↓
outer mise は inner mise の終了を待つ

最初はmise configやenv.shが怪しく見えた。しかし実際には、別のmise lsがすでにデッドロックしており、後続のmiseは同じ lock の後ろに詰まっていただけだった。

straceがなくても、次の/procまわりのコマンドだけで原因まで追えた。

ps -o pid,stat,wchan:32,cmd -p <pid>
cat /proc/locks
ls -l /proc/<pid>/fd
cat /proc/<pid>/fdinfo/<fd>
sudo cat /proc/<pid>/stack
sudo cat /proc/<pid>/syscall

たどった順序は次のとおりだ。

flock 待ち
↓
lock holder を特定
↓
holder は pipe 待ち
↓
pipe の相手を特定
↓
相手が同じ lock 待ち

プロセスが理由もなく固まったように見えるときは、「何が怪しいか」より先に「今、何を待っているか」を調べる。今回は、その順序で調べたことで、疑っていたenv.shではなく plugin 内の再帰実行へたどり着けた。

参考¶

mise 今回デッドロックした CLI 本体。mise lsやmise hook-envの挙動はここで確認できる。
mise-nix 今回の原因になった nix plugin。mise lsを呼んでいるcollect_man_paths()は、lib/nix_env.luaで確認できる。

miseが固まった。原因は plugin 内の再帰実行だった¶