Raspberry PIでNTPの同期が取れてからアプリケーションのサービスを起動するようにした
Raspberry PIにはRTC（リアルタイムクロック）が搭載されていないので、ボード上に日時を保存しておいてOSのシステム時計に反映する方法はデフォルトではない。
ただ、昨今のRaspbianはsystemd-timesyncdによって、ファイルシステムに最後の日時を保存しておいてそこから復元し、その後NTPで同期するみたいな動きになっている。なので、OSを起動すると毎回とりあえず1970年から開始…みたいな感じにはならない。
systemd-timesyncd はネットワークを介してシステム時刻を同期させるために追加されたデーモンです。 Raspberry Pi や組み込みデバイスなどの RTC を載せてないシステムのために、新しい NTP の同期が取得される度にディスクに現在の時刻を保存し、それを使って起動時にシステム時刻を修正することができ、時刻が常に正しいわけではないときでも、それらのシステムで時刻がモノトニックに進むことを保証します。
ただし、これだと自分で作ったアプリケーションをいつ起動するのかによってシステム時刻の正確な日時が取れるタイミングが微妙な感じになる。
サンプルアプリケーションで検証してみる
たとえば、次のようなアプリケーションを用意する。起動すると1秒おきに現在時刻をログファイルに記録する仕様になっている。
from datetime import datetime from logging import getLogger, basicConfig, DEBUG import time logger = getLogger(__name__) basicConfig(level=DEBUG, format='%(asctime)s %(name)-12s %(levelname)-8s %(message)s', filename='./app.log') try: while True: logger.info("current:%s" % datetime.now().strftime("%Y-%m-%d %H:%M:%S")) time.sleep(1) except KeyboardInterrupt: pass
これを起動順は指定せずに、単純にsystemdにサービスとして登録する。systemd用の設定ファイルを/etc/systemd/system/myapp.serviceとして次のように用意する。
[Unit] Description = My Application [Service] ExecStart = /home/pi/app/venv/bin/python app.py WorkingDirectory = /home/pi/app User=pi Restart=always Type=simple [Install] WantedBy = multi-user.target
これをsystemctlで有効化する。
$ sudo systemctl enable myapp.service
OSを起動してアプリケーションが起動すると次のようなログができあがる。
2019-08-14 11:25:04,274 __main__ INFO current:2019-08-14 11:25:04 2019-08-14 11:25:05,278 __main__ INFO current:2019-08-14 11:25:05 2019-08-14 11:25:06,282 __main__ INFO current:2019-08-14 11:25:06 2019-08-14 11:25:07,285 __main__ INFO current:2019-08-14 11:25:07 2019-08-14 11:25:08,288 __main__ INFO current:2019-08-14 11:25:08 2019-08-14 11:25:09,291 __main__ INFO current:2019-08-14 11:25:09 2019-08-14 11:25:10,294 __main__ INFO current:2019-08-14 11:25:10 *** 中略 *** 2019-08-14 11:25:25,405 __main__ INFO current:2019-08-14 11:25:25 2019-08-14 11:25:26,409 __main__ INFO current:2019-08-14 11:25:26 2019-08-14 11:25:27,412 __main__ INFO current:2019-08-14 11:25:27 2019-08-14 11:25:28,415 __main__ INFO current:2019-08-14 11:25:28 2019-08-14 11:25:29,418 __main__ INFO current:2019-08-14 11:25:29 2019-08-14 11:25:30,427 __main__ INFO current:2019-08-14 11:25:30 2019-08-14 11:27:48,380 __main__ INFO current:2019-08-14 11:27:48 2019-08-14 11:27:49,383 __main__ INFO current:2019-08-14 11:27:49 2019-08-14 11:27:50,386 __main__ INFO current:2019-08-14 11:27:50 2019-08-14 11:27:51,389 __main__ INFO current:2019-08-14 11:27:51 2019-08-14 11:27:52,398 __main__ INFO current:2019-08-14 11:27:52
ログのタイムスタンプを見ていくと、11:25:04に起動したアプリケーションがログを記録して行き、11:25:30のあたりでNTPによってシステム時計が調整されて、つぎから11:27:48として正確な時刻で記録されていく。
これだと、起動してからNTPの同期が完了するまでの間のdatetime.now()やログのタイムスタンプはあてにならないことになる。
アプリケーションの起動をsystemd-timesyncdの後にしてみる
NTPの同期をするのがsystemd-timesyncdなので、アプリケーションのsystemdの設定を次のように、After=systemd-timesyncd.serviceと起動順の指定をしてサービス登録する。
これでsystemd-timesyncdサービスが起動してからアプリケーションが起動するようになる。
[Unit] Description = My Application After=systemd-timesyncd.service [Service] ExecStart = /home/pi/app/venv/bin/python app.py WorkingDirectory = /home/pi/app User=pi Restart=always Type=simple [Install] WantedBy = multi-user.target
が、これで改めて記録したログを観察すると次のようになる。
2019-08-14 11:39:33,913 __main__ INFO current:2019-08-14 11:39:33 2019-08-14 11:39:34,917 __main__ INFO current:2019-08-14 11:39:34 2019-08-14 11:39:35,921 __main__ INFO current:2019-08-14 11:39:35 *** 中略 *** 2019-08-14 11:39:57,052 __main__ INFO current:2019-08-14 11:39:57 2019-08-14 11:39:58,055 __main__ INFO current:2019-08-14 11:39:58 2019-08-14 11:39:59,059 __main__ INFO current:2019-08-14 11:39:59 2019-08-14 11:40:00,063 __main__ INFO current:2019-08-14 11:40:00 2019-08-14 11:43:03,507 __main__ INFO current:2019-08-14 11:43:03 2019-08-14 11:43:04,510 __main__ INFO current:2019-08-14 11:43:04 2019-08-14 11:43:05,514 __main__ INFO current:2019-08-14 11:43:05 2019-08-14 11:43:06,517 __main__ INFO current:2019-08-14 11:43:06 2019-08-14 11:43:07,521 __main__ INFO current:2019-08-14 11:43:07
11:39:33に起動してログを取り始め、11:40:00のあたりでNTPの同期が反映されて、11:43:03から正確な時刻で記録されていく。
syslogみるとmyapp.serviceの起動より後にsystemd-timesyncdで時刻同期されているのがわかる。
Aug 14 11:39:31 raspberrypi systemd[1]: Started My Application. Aug 14 11:39:31 raspberrypi systemd[1]: Started Daily man-db regeneration. Aug 14 11:39:31 raspberrypi systemd[1]: Reached target Timers. Aug 14 11:39:31 raspberrypi systemd[1]: Started triggerhappy global hotkey daemon. Aug 14 11:39:31 raspberrypi systemd[1]: Started System Logging Service. *** 中略 *** Aug 14 11:43:02 raspberrypi systemd-timesyncd[274]: Synchronized to time server for the first time 133.243.238.243:123 (ntp.nict.jp).
これはsystemd-timesyncdの起動タイミングとNTPで同期されるタイミングが異なるためで、NTPが同期されたタイミングを正しく待つ必要がある。
NTPの同期が完了されるまで待ってアプリケーションを起動する
これを実現するためにwait-timesyncを作った。
systemd-timesyncdが同期したらタイムスタンプを更新する/var/lib/systemd/clockファイルの更新日時を監視するようになっている。
#!/bin/bash TARGET=${WAIT_CLOCK_TARGET:-"/var/lib/systemd/clock"} TIMEOUT=${WAIT_TIMEOUT:-60} CHANGE=0 LAST_TS=`stat -c %Y $TARGET` for i in `seq 1 $TIMEOUT` ; do TS=`stat -c %Y $TARGET` if [ $LAST_TS != $TS ]; then CHANGE=1 echo "timesyncd clock updated [$i sec waited]" break fi sleep 1 done if [ $CHANGE == 0 ]; then echo "timeout watch timesyncd clock update" fi
これを次の/etc/systemd/system/wait-timesync.serviceでsystemdにサービス登録する。
[Unit] Description = Wait timesyncd After=systemd-timesyncd.service [Service] ExecStart = /usr/local/bin/wait-timesync EnvironmentFile = /etc/default/wait-timesync Type=oneshot [Install] WantedBy = multi-user.target
監視対象のclockファイルは場所が違う場合があるので、次のように環境変数で指定するようにしてある。同期待ちのタイムアウト（秒）も環境変数で指定する。これは、/etc/default/wait-timesyncファイルとして設置し、参照する。
WAIT_CLOCK_TARGET=/var/lib/systemd/clock WAIT_TIMEOUT=60
これを利用してmyapp.serviceのsystemd設定を変更し、After=wait-timesync.serviceとして再設定する。
[Unit] Description = My Application After=wait-timesync.service [Service] ExecStart = /home/pi/app/venv/bin/python app.py WorkingDirectory = /home/pi/app User=pi Restart=always Type=simple [Install] WantedBy = multi-user.target
改めてOSを起動してログファイルを確認すると次のようになり、途中で同期されてタイムスタンプが変わることはなくなる。
2019-08-14 11:49:08,968 __main__ INFO current:2019-08-14 11:49:08 2019-08-14 11:49:09,971 __main__ INFO current:2019-08-14 11:49:09 2019-08-14 11:49:10,975 __main__ INFO current:2019-08-14 11:49:10 2019-08-14 11:49:11,980 __main__ INFO current:2019-08-14 11:49:11 2019-08-14 11:49:12,984 __main__ INFO current:2019-08-14 11:49:12 2019-08-14 11:49:13,989 __main__ INFO current:2019-08-14 11:49:13 2019-08-14 11:49:14,993 __main__ INFO current:2019-08-14 11:49:14 2019-08-14 11:49:15,997 __main__ INFO current:2019-08-14 11:49:15
このとき、syslogを見ると次のようになっている。
Aug 14 11:46:04 raspberrypi systemd[1]: Starting Wait timesyncd... Aug 14 11:46:04 raspberrypi systemd[1]: Starting OpenBSD Secure Shell server... Aug 14 11:46:04 raspberrypi systemd[1]: Starting Permit User Sessions... *** 中略 *** Aug 14 11:49:06 raspberrypi systemd-timesyncd[281]: Synchronized to time server for the first time 133.243.238.243:123 (ntp.nict.jp). Aug 14 11:49:07 raspberrypi wait-timesync[469]: timesyncd clock updated [21 sec waited] Aug 14 11:49:07 raspberrypi systemd[1]: wait-timesync.service: Succeeded. Aug 14 11:49:07 raspberrypi systemd[1]: Started Wait timesyncd. Aug 14 11:49:07 raspberrypi systemd[1]: Started My Application.
アプリケーションの起動がwait-timesyncの完了後になり、NTPの同期後になっていることがわかる。ちなみにNTPの同期にはwait-timesyncが起動してから21秒かかっていることが分かる。
アプリケーションの起動が待たされることにはなるけど、RTCをRaspberry PIに載せるまでは行かないけどタイムスタンプは正確にしときたいみたいな用途に使えると思う。
