はじめに
現在の職場において、勤怠管理の都合で業務端末の起動停止時刻がチェックされており、打刻システムに記録された時刻とそれに著しい差異があった場合労務部門からツッコミが入ることになっている。
起動停止時刻はいわゆるスパイウェア情報漏洩リスク対策や資産管理のためにデバイスにインストールする系のソリューションでログを取得の上、管理部門で一元管理されている。しかしそのログが何とも信憑性にかける感じであり、絶対シャットダウンしたのに遅い時刻が記録されていたりなんだりで毎月の勤怠締めのタイミングで不毛なやりとりが発生しがちだった。
指摘を受ける側として対策を考えるにあたり、いや絶対シャットダウンしましたよ、と定性的な回答を繰り返すのは技術者の姿勢として望ましくない。
そのため自分でも何らかエビデンスとなり得る情報を残したいと思って行動した記録を以下に記します。
確認した環境
ちょっと前のMacBook Pro
macOS 10.15.7
検証
ググったところ、pmsetコマンドでそれらしき情報を取得できることが分かった。pmsetは電源管理まわりを操作するコマンド。
❯ pmset -g log
と実行すると電源管理系のイベント履歴が表示される。
それをざっと眺めてみると、 ShutdownCause というイベントが見つかった。
❯ pmset -g log | grep ShutdownCause
2021-02-01 08:50:55 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
2021-02-02 08:51:15 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
2021-02-03 08:54:48 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
2021-02-04 08:53:23 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
2021-02-04 17:20:16 +0900 ShutdownCause SMC shutdown cause: 0: Battery disconnected
2021-02-05 08:54:56 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
しかしなぜかタイムスタンプが電源ONした日時のように見受けられる。
適当にgrepしてみた感じ、このログは/var/log/powermanagement/配下に保存されている模様だった。
おそらくこのイベントはOSがシャットダウンした後に発生しており、次回OS起動時にSMCから読み込まれるためこういうタイムスタンプになるのではないだろうか（勘）。
ということはこの1つ前のイベントが、OSが検知できる電源OFF直前の電源系イベントと言えるのではないだろうか。
1行前も出してみる。
❯ pmset -g log | grep -B 1 ShutdownCause
2021-01-30 18:47:40 +0900 Assertions PID 17327(fsck_apfs) Released PreventUserIdleDisplaySleep "Running FSCK" 00:00:00 id:0x0x500009b1a [System: DeclUser IntPrevDisp kDisp]
2021-02-01 08:50:55 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
--
2021-02-01 19:51:43 +0900 Assertions PID 50104(fsck_apfs) Released PreventUserIdleDisplaySleep "Running FSCK" 00:00:00 id:0x0x500009ae2 [System: DeclUser IntPrevDisp kDisp]
2021-02-02 08:51:15 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
--
2021-02-02 18:24:59 +0900 Assertions PID 81520(fsck_apfs) Released PreventUserIdleDisplaySleep "Running FSCK" 00:00:00 id:0x0x5000093ce [System: PrevIdle DeclUser IntPrevDisp kDisp]
2021-02-03 08:54:48 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
--
2021-02-03 20:30:21 +0900 Assertions PID 68211(fsck_apfs) Released PreventUserIdleDisplaySleep "Running FSCK" 00:00:00 id:0x0x500009cac [System: DeclUser IntPrevDisp kDisp]
2021-02-04 08:53:23 +0900 ShutdownCause SMC shutdown cause: 5: Software initiated shutdown
--
2021-02-04 17:17:46 +0900 Assertions PID 206(hidd) Summary UserIsActive "com.apple.iohideventsystem.queue.tickle serviceID:10000037d name:NULL product:Apple Internal Keyb eventType:11" 00:00:04 id:0x0x90000887c [System: PrevIdle PrevDisp DeclUser kDisp]
2021-02-04 17:20:16 +0900 ShutdownCause SMC shutdown cause: 0: Battery disconnected
はたして、限りなく私が業務終了したっぽい日時となった。
シェル芸でそれっぽく加工してみる。
❯ pmset -g log | grep -B 1 ShutdownCause | awk -F' ' '!/--/ { if( $4 == "ShutdownCause" ){ $4 = "PowerOn" } else { $4 = "PowerOff" }; print $1,$2,$3,$4}'
2021-01-30 18:47:40 +0900 PowerOff
2021-02-01 08:50:55 +0900 PowerOn
2021-02-01 19:51:43 +0900 PowerOff
2021-02-02 08:51:15 +0900 PowerOn
2021-02-02 19:24:59 +0900 PowerOff
2021-02-03 08:54:48 +0900 PowerOn
2021-02-03 20:30:21 +0900 PowerOff
2021-02-04 08:53:23 +0900 PowerOn
2021-02-04 17:17:46 +0900 PowerOff
2021-02-04 17:20:16 +0900 PowerOn
この結果を何らかの方法で定期的に出力して月末に集計すれば、それなりに実情に即した記録が取れるのではないかと思う。
Automatorでアプリ化しログイン項目に登録するのがよいかも。
真面目にエビデンスとして残すなら変に加工せず pmset -g log をそのまま残しておいてもいいかもしれない。というか /var/log/powermanagement/ を定期的にバックアップしてもいいかもしれない。
おことわり
ここまでの内容を裏づけるドキュメントを軽く探してみたが見つからなかった。
一次情報にあたる資料をご存知の方がいたら教えてください。また間違いがあればご指摘いただけると嬉しいです。
間違ってもこの情報をそのまま鵜呑みにして従業員の勤怠管理や内部統制云々で使ったりすることのなきよう。