失敗しようがない確認処理:Macの自動化の1週間で見つけた5つの偽陽性
あるひとつのルールを守っていれば、1週間のほとんどを無駄にせずに済みました。確認処理を信じる前に、対象が壊れているときに何を出力するかを考えることです。答えが「同じもの」なら、それは確認処理ではありません。OKと表示するだけの飾りです。
以下は、1週間で見つけた5つの例です。どれもmacOS上のもので、何か月も問題なく動いていた自動化の中にありました。どれも自信満々に誤った答えを出し、壊れていないものを直しに人を向かわせました。
| 確認項目 | 正常時の出力 | 異常時の出力 | 判定 |
|---|---|---|---|
| pgrep -f softwareupdate | 常駐デーモンに一致 | 常駐デーモンに一致 | 役に立たない |
| tar -xf - ; echo COPIED | COPIED | COPIED(0バイト) | 役に立たない |
| kickstartによる権限の確認 | 警告は出力されない | 何も出力されない | 役に立たない |
| stat -f %Su /dev/console | root | root | 役に立たない |
| sysadminctl -autologin set | error:22 | error:22 | 役に立たない |
1. 実行されていなかったアップデート
あるマシンが、再起動後なかなか戻ってこないように見えました。pgrep -f softwareupdateでざっと調べると一致するものがありました。そこでスクリプトはソフトウェアアップデートの実行中だと報告し、当社は待ちました。
アップデートなど行われていませんでした。softwareupdatedはどのMacにも常駐しているデーモンです。部分一致で探せば、何かが起きていてもいなくても見つかります。マシンのオーナーが素朴な質問で気づきました。「アップデートなんて走っていないはずだ。何が問題なのか?」確認処理には答えがありませんでした。最初から答えなど持っていなかったからです。
正しくは、実行中のアップデートが残す痕跡を探すことです。進行中のダウンロードや、継続的なディスクアクセスは証拠になります。常に存在するプロセス名は証拠になりません。
2. 0秒でコピーが終わったXcode
当社では、tarアーカイブをSSH経由でストリーミングして、マシン間でXcodeを複製しています。ある実行では、途中でメモリ不足になったノートPCを経由していました。送信側が落ち、受信側のtar -xf -は空のストリームを読み、何も展開せずに終了コード0で終わりました。スクリプトはXCODE_COPIEDと出力しました。
実際には1バイトも移動していませんでした。終了コードは、tarが頼まれたことについては正直でした。届いたものを展開せよ、という指示です。何も届かなかったのです。
# what we checked tar -xf - -C /Applications && echo XCODE_COPIED # what we should have checked du -sh /Applications/Xcode.app # 3.8G, or it did not happen /Applications/Xcode.app/Contents/Developer/usr/bin/xcodebuild -version
3. 付与済みと報告された権限
macOSは画面収録を、人かMDMプロファイルしか付与できない権限の後ろに置いています。Appleのkickstartツールは、その権限がないとはっきりした警告を出します。当社の確認処理はその警告を探し、見つからなければ権限は付与済みと報告していました。
ツール自体に権限がまったくないと、何も出力しません。警告も、ほかの何も出ません。警告がないことが、成功とまったく同じに見えたのです。詳しい経緯はログインはできるのに何も映らないMacに書きました。直し方は、ツールの意見を聞くのをやめて、フレームバッファから実際のピクセルを取得することでした。
4. 停止と報告されたデスクトップ
ユーザーがGUIにログインしているかを確かめるために、/dev/consoleの所有者を調べていました。新しいマシンではrootと表示されたので、誰もログインしていないと判断しました。次に、2日前からユーザーがログインしているお客様のマシンを調べました。そこでもrootと表示されました。
約10分間、有料のお客様のデスクトップが停止していると報告されていました。実際は正常でした。デバイスノードの所有者は、当社が思っていた意味を持っていなかったのです。whoは、セッションがあるときだけconsoleの行を表示します。現在のテレメトリはこれを報告しています。
5. 常に同じだったエラー
最新のmacOSメジャーバージョンを入れたマシンで、自動ログインが効きませんでした。Appleのsysadminctl -autologin setはSACSetAutoLoginPassword error:22を返しました。新しいOSに新しいエラー。結論は明らかに思えました。新しいリリースが、スクリプトによる自動ログインを壊したのだと。
そこで、1つ前のメジャーバージョンを入れた正常なマシンで同じコマンドを実行しました。そのマシンでは自動ログインが何週間も動いていました。結果は同じエラーでした。このコマンドは正常なシステムでも壊れたシステムでも同じように失敗します。つまり、どちらについても何の情報も持っていませんでした。本当の原因は、初回起動時の一時的な状態だとわかりました。自信のあった診断は間違いで、対照実験が1分もかからずそれを否定しました。
ルールと、2つの系
5つの例はどれも、最初の問いで不合格になります。これらを追いかけるのに4日かかりました。どの例でも、背後のシステムは確認処理が主張したようには壊れていませんでした。
何を変えたか
画面の確認では、フレームバッファを取得して色の数を数えます。セッションの確認にはwhoを使い、テレメトリで送ります。ログイン画面のままのマシンは、正常に見えるのではなくアラートを出します。コピーは、サイズと、コピーしたバイナリを実際に実行することで検証します。そして、正常だとわかっているマシンで同じ確認をするまでは、どんな障害にも根本原因を決めません。どれも気の利いた工夫ではありません。すべて同じ問いです。確認処理が嘘をついたあとではなく、書く前に問うのです。