🙆‍♀️

rails/rspec/rakeコマンドが使えなくなった（不完全解決）

2023/01/25に公開

Rails

RSpec

rake

tech

TL;DR

railsコマンドやrspecコマンドを使おうとすると、ctrl+Cでストップできないスリープ状態になってしまう
- ps auxすると、STATがD+(Uninterruptible sleep)になっていた
gitやbootsnapのキャッシュ周りが読み込めないみたいだったので、再度リポジトリをcloneし直したり、bootsnapを使わないように設定することで一旦解決

実行環境

macos :Ventura 13.1
docker : Docker for Mac (Engine v20.10.6)
ruby : 2.6.2p47
rails : 5.2.4.6

経緯と調査録

今ではもう何が原因か定かではないですが、macosのアップデートを久しぶりに行ったあと、docker下のrailsコマンドやrspecコマンド、rakeコマンドを用いると、プロセスが固まってしまうようになってしまいました。
ctrl+Cでterminateできずさすがにおかしいと思い、ps auxをすると、該当プロセスのSTATのところがD+になっていました。

...この辺りあまり詳しくなかったので調べてみると、DはUninterruptible sleepを意味しており、主にIO周りでスタックしているということがわかりました。

IO周りがおかしいといっても、プロセスはエラーも吐かず、何のメッセージも返していないので困ったなとなっていたら、どうやらstraceコマンドを用いることで、プロセスの処理内容を追うことができるとのことでした。

参考 : strace でプログラムの動きを追ってみよう

strace は、特定プロセスのシステムコールレベルでの処理をトレースできるツールです。

straceコマンドはaptであれば、以下のコマンドでインストールできます。

apt install strace

実際にstraceコマンドを用いてみます。（-fオブションでサブプロセスもトレースできるみたいです）

% strace -f bundle exec rails -v
（中略）
[pid  2511] lstat(".git/refs/heads/master", {st_mode=S_IFREG|0644, st_size=41, ...}) = 0
[pid  2511] open(".git/refs/heads/master", O_RDONLY) = 3
[pid  2511] read(3, "3057cdcf25cd95ba7c1dd56b6119bf83"..., 256) = 41
[pid  2511] read(3, "", 215)            = 0
[pid  2511] close(3)                    = 0
[pid  2511] lstat(".git/refs/HEAD", 0x7ffd740477d0) = -1 ENOENT (No such file or directory)
[pid  2511] open(".git/packed-refs", O_RDONLY) = 3
[pid  2511] fstat(3, {st_mode=S_IFREG|0644, st_size=220008, ...}) = 0
[pid  2511] fstat(3, {st_mode=S_IFREG|0644, st_size=220008, ...}) = 0
[pid  2511] read(3,

ここでストップしました。
むむ...どうやらgit関係のファイルのreadで止まっているっぽいです。たしかにIO周りで何か発生してそう。
消していいものなのかちょっと判断が難しいので、同じプロジェクトのgitリポジトリを別フォルダにクローンして再度ビルドしてみることにしました。

（30分後）

さて、再度ビルドし終えたので、コマンドを叩いてみます。

% bundle exec rails -v
>

また止まってるが...。

straceコマンドを併用してみます。

% strace -f bundle exec rails -v
（中略）
lstat("/usr/local/bundle/gems", {st_mode=S_IFDIR|S_ISGID|0755, st_size=12288, ...}) = 0
lstat("/usr/local/bundle/gems/bootsnap-1.4.4", {st_mode=S_IFDIR|S_ISGID|0755, st_size=4096, ...}) = 0
lstat("/usr/local/bundle/gems/bootsnap-1.4.4/lib", {st_mode=S_IFDIR|S_ISGID|0755, st_size=4096, ...}) = 0
lstat("/usr/local/bundle/gems/bootsnap-1.4.4/lib/bootsnap", {st_mode=S_IFDIR|S_ISGID|0755, st_size=4096, ...}) = 0
lstat("/usr/local/bundle/gems/bootsnap-1.4.4/lib/bootsnap/compile_cache.rb", {st_mode=S_IFREG|0644, st_size=1324, ...}) = 0
open("/app/tmp/cache/bootsnap-load-path-cache", O_RDONLY|O_CLOEXEC) = 5
ioctl(5, TCGETS, 0x7fff935a5830)        = -1 ENOTTY (Inappropriate ioctl for device)
fstat(5, {st_mode=S_IFREG|0644, st_size=462385, ...}) = 0
lseek(5, 0, SEEK_CUR)                   = 0
mmap(NULL, 462848, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f6edbeea000

どうも別のファイルで止まっているっぽいですね...。
調べてみるとbootsnap-load-path-cacheはbootsnapのキャッシュみたいです。
一旦rails側でbootsnapを読み込まないようにしてみます。

# require 'bootsnap/setup'

コメントアウトしました。

実行してみます。

% bundle exec rails -v
Rails 5.2.4.6

通りました！

bootsnapを使えるようにしたい（未解決）

やったーと言いたいところですが、bootsnapを使わないのはちょっとだけ気持ち悪いので使える方法がないか調査してみます。
（ここからは章タイトルにあるように未解決です。申し訳ございません）

色々調べていると、bootsnap-load-path-cacheやbootsnap-compile-cacheを削除する
のがいいとのことでした。/app/tmp/cache/以下を消してみます。

% rm -rf /app/tmp/cache
rm: cannot remove '/app/tmp/cache/.nfs0000000011de3dfa00000003': Device or resource busy
rm: cannot remove '/app/tmp/cache/.nfs0000000011de5efb00000006': Device or resource busy
rm: cannot remove '/app/tmp/cache/.nfs0000000011cf14c100000002': Device or resource busy
rm: cannot remove '/app/tmp/cache/bootsnap-compile-cache/b3/.nfs0000000011cf0a0d00000005': Device or resource busy

何か消せないファイルあるけど...。
nfs?そういえばうちのプロジェクトではdocker for macでのVolumeのマウントが遅いので、nfsを用いたマウントを行っていたなあということを思い出しました。（参考 : https://qiita.com/kunit/items/36d9e5fa710ad26f8010）
たぶん何かしらのプロセスがファイルディスクリプタを掴んだまま死んでいるか何かなのかな〜と思いました。

まあ一旦bootsnapの設定を戻して、コマンド実行してみます。

% bundle exec rails c
Loading development environment (Rails 5.2.4.6)
[1] pry(main)>

お、通った。
キャッシュが効くかもう一回実行してみます。

% strace -f bundle exec rails c
（中略）
lstat("/usr/local/bundle/gems/bootsnap-1.4.4", {st_mode=S_IFDIR|S_ISGID|0755, st_size=4096, ...}) = 0
lstat("/usr/local/bundle/gems/bootsnap-1.4.4/lib", {st_mode=S_IFDIR|S_ISGID|0755, st_size=4096, ...}) = 0
lstat("/usr/local/bundle/gems/bootsnap-1.4.4/lib/bootsnap", {st_mode=S_IFDIR|S_ISGID|0755, st_size=4096, ...}) = 0
lstat("/usr/local/bundle/gems/bootsnap-1.4.4/lib/bootsnap/compile_cache.rb", {st_mode=S_IFREG|0644, st_size=1324, ...}) = 0
open("/app/tmp/cache/bootsnap-load-path-cache", O_RDONLY|O_CLOEXEC) = 5
ioctl(5, TCGETS, 0x7ffea073af40)        = -1 ENOTTY (Inappropriate ioctl for device)
fstat(5, {st_mode=S_IFREG|0644, st_size=462441, ...}) = 0
lseek(5, 0, SEEK_CUR)                   = 0
mmap(NULL, 462848, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe717592000
read(5, 1

やっぱりダメみたいですね...。
bootsnap-load-path-cacheは消してもまた生成されてエラーが出るし、fuserコマンドでファイルを使用しているプロセスを特定しようとしましたが、Permission deniedが出て特定できませんでした...（何故...）

% apt install psmisc
% fuser bootsnap-load-path-cache
Cannot stat file /proc/36/fd/0: Permission denied
Cannot stat file /proc/36/fd/1: Permission denied
Cannot stat file /proc/36/fd/2: Permission denied
Cannot stat file /proc/36/fd/3: Permission denied
Cannot stat file /proc/36/fd/4: Permission denied
Cannot stat file /proc/36/fd/5: Permission denied
Cannot stat file /proc/36/fd/6: Permission denied
Cannot stat file /proc/36/fd/7: Permission denied
Cannot stat file /proc/36/fd/8: Permission denied
Cannot stat file /proc/36/fd/9: Permission denied
Cannot stat file /proc/39/fd/0: Permission denied
Cannot stat file /proc/39/fd/1: Permission denied
Cannot stat file /proc/39/fd/2: Permission denied
Cannot stat file /proc/39/fd/3: Permission denied
Cannot stat file /proc/39/fd/4: Permission denied
Cannot stat file /proc/39/fd/5: Permission denied
Cannot stat file /proc/39/fd/6: Permission denied
Cannot stat file /proc/39/fd/7: Permission denied
Cannot stat file /proc/39/fd/8: Permission denied
Cannot stat file /proc/39/fd/9: Permission denied
Cannot stat file /proc/39/fd/10: Permission denied
Cannot stat file /proc/39/fd/11: Permission denied
Cannot stat file /proc/39/fd/12: Permission denied
Cannot stat file /proc/39/fd/13: Permission denied
Cannot stat file /proc/39/fd/14: Permission denied
Cannot stat file /proc/39/fd/15: Permission denied
Cannot stat file /proc/39/fd/16: Permission denied
Cannot stat file /proc/39/fd/17: Permission denied

ここから色々調べてみましたが、残念ながらこの件に関しては解決できませんでした。

bootsnapはrails周りの立ち上げを早めてくれるらしいのですが、別にこの状態でもそこまで遅くなく、困らないと思ったため、このままbootsnapは使わない運用で行こうと最終的に判断しました（敗北）。
いかがでしたか？な記事になってしまって大変申し訳無いですが、何かわかる方はコメントなどで教えていただけると助かります...。

TL;DR

実行環境

経緯と調査録

bootsnapを使えるようにしたい（未解決）

Discussion