cronで連続される

ことの発端はボードの温度の異常上昇でした。

午前４時の間に気温の変動がない状態でボードの温度だけ上昇しています。これにはSoftEatherが入っているので外部からのハッキングを一番に考えました。そんなわけで昨日の更新を行ったわけですが…。

問題点として、ログの容量が溢れていてその時点のログを見れなかったという。正直最悪です。原因は先月lircをapt installしたときに設定は行っていなかったのですが、サービスが起動されていて、エラーログのためにログ領域を食いつぶしていたという形でした。

ログがまともに見れないので、とりあえず現状のsyslogだけでも退避させ再起動を行いました。そして念のためにまずはremove lircを行いました。

温度ロガーは記録されているのでその記録を見てみると、どうも跳ね上がった時間の最後に同じ時間に連続して実行されているようでした。

すこし検索して見てみましたがcronで変な動作をしたような話はなさそうでした。

SoftEather側のログをみると、ちょうどそのタイミングでサービスが起動されている形になってログが記録されていました。気になるのは終了された記録がなかったこと。さらにそのタイミングの前にSoftEatherへのアクセスが無いようだったので、もし仮にハッキングされていた場合はログも改竄されていることになるので、結構厄介なことになっていることになります。

そうなっていないことを祈りつつ、とりあえずSoftEatherの更新は行いました。

記録として残っている温度ログの中を見てみることに。

とりあえず他にも同じような状態に陥ったことが無いか確認してみることに。

pi@rasp3bprs:~ $ sqlite3
SQLite version 3.16.2 2017-01-06 16:32:41
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
sqlite> .open /var/logger/logging.db
sqlite> select * from (select timestamp, count(*) "cnt" from temperatures group by timestamp) where cnt > 1;
2020-09-01 05:04|11
2020-09-14 04:39|11

どうやら9/1にも同じような状態に陥ってそうです。

タイムスタンプの様子を見てみると、9/14の場合は連続実行のまえから実行される時間が数分遅れ気味になっていましたが、9/1の場合は連続実行前後に異変はなく、綺麗に実行されていました。

ここで、再度cronについて検索をかけてみると、異変があったという記録を見つけることができました。

cron の意外な落とし穴！ https://moro-archive.hatenablog.com/entry/2015/03/17/011823

このブログの中で、cronの動作をソースから追っかけて調べている様子が書かれていました。要約すると、cronはシステム時間とcron内部の想定時間がズレた場合、それなりに起動を行う。１分単位の処理は未処理分は考慮されず、それ以外は未処理分の処理を順次処理していこうとするが、その補正方法は差異時間により３パターンあるということ。

一般論としてcronの現状の実装で問題が発生することはほぼ無いが、システム系で再投入や起動タイミングによって異常が発生するとダメな処理がある場合はキックをcronに任せたとしても独自にちゃんと実装しないとダメですね。容易に考えられるのは会計系の月次が絡んでる処理とか、プラントの制御管理系とか。

少し話がズレてしまいましたが、温度ログは5分間隔でロギングしているので、未処理分がまとめて連続処理されることはありそうです。なので問題の日の個数をカウントしてみます。（遊んでいるので数がズレていることはありますがｗ）

sqlite> select timestamp, count(*) "cnt" from temperatures where substr(timestamp, 1, 10) = "2020-09-01";
2020-09-01 23:55|288
sqlite> select timestamp, count(*) "cnt" from temperatures where substr(timestamp, 1, 10) = "2020-09-02";
2020-09-02 23:55|288

一時間当たりの個数 × 24時間 = (60/5) * 24 = 12 * 24 = 288
 1日当たりの個数は変わらないので、連続実行は見事に後追いで実行されているものと思われます。

タイムスタンプを列挙して問題のある前後をふくめて切り抜いてみると、

2020-09-01 03:40
2020-09-01 03:45
2020-09-01 03:50
2020-09-01 03:55
2020-09-01 04:00
2020-09-01 04:05
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:04
2020-09-01 05:05
2020-09-01 05:10
2020-09-01 05:15
2020-09-01 05:20
2020-09-01 05:25
2020-09-01 05:30

04:10～05:00の分が 4:04に実行されている形になっていました。14日の方はブレは多いいですがほぼ同様にまとめて処理されている形でした。

温度変化も気になったので、過去日のグラフを表示できるようにして9/1の温度を見てみると、

4時から5時にかけて温度がおかしくなっていました。SoftEatherのログを見ると、やはりこの5時時過ぎに起動ログが残っていました。

まとめると、どちらも温度異常があったのち、vpnが起動しているという結果が認められました。

連続実行されている直接的原因はcronが1時間ほど止まった状態になった後、サービスの起動が行われてそのタイミングで連続実行されているという感じです。

 

すこしスッキリしましたが、根本的な原因が分かりません。

ほかのRaspberry piの温度ログを見てみても連続実行されたものはありませんでした。もう一台同じスペックの3B+にSoftEatherを入れてあるのですが、そちらもこのような現象は発生していませんでした。

1時間というスパンを前提に、操作上の原因として考えられそうなのは…システムアップデートぐらいでしょうか？
残っているものと言えば、あとはteratermのログぐらいなので、これを見てみることに。残念なことに該当時間に接続している記録はありませんでした。正直apt upgradeでインストール時にサービスが強制的に止められて再起動させられたと考えていたのですが、どうやら違っていたようです。

現象的にWindowsUpdateのような感じなので、少し見方を変えてaptが動いているかもしれないと思い、自動起動について検索して見ると、どうやらapt関連で動作しているらしい記述を発見。パッケージリストの更新を行っているようですが、１時間もかかるっていうのが納得いきません。関連処理を見てみると/usr/lib/apt/apt.systemd.dailyが実行されているようなのでスクリプトを見てみることに。

ざっくり見ると、aptで使用したキャッシュやらアーカイブやらをごにょごにょしてるっぽいです。こんな処理を裏で動かす必要があるのかどうか…

topで見る限りmotionとvpnserverぐらいしか動いていないので基本的にはスカスカのはずなんですが、ログを溢れさせて放置していたという致命的なことをやらかしていたので、もう少し様子を見るしかないということでしょうかね。