GPS モジュールを見失ったら gpsd を再起動してみる
前回 暫くすると GPS モジュールの通信速度を見失いデータが取れなくなり、その後は通信速度が合っても、もう再認識してくれませんでした。(gpspipe や、gpsmon では見えるが、ntpshmmon, ntpq では見えない) その後も手動で gpsd を再起動すると復旧するものの数日でまた見えなくなります。
これでは使い物にならないので、gpsd を自動再起動するようにしたい。
何を確認するとデータが取れなくなったことが分かるのか
- ntpq -p で見えなくなる
- ntpshmon でも表示がなくなる
- モジュールが見えなくなって 1時間程度で /var/log/messages に以下のようなメッセージが出る
> grep -e pps -e USB0 /var/log/messages
Nov 4 02:16:45 Ras1 kernel: [ 3.662157] pps_core: LinuxPPS API ver. 1 registered
Nov 4 02:16:45 Ras1 kernel: [ 3.662182] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
Nov 4 02:16:45 Ras1 kernel: [ 3.669083] pps pps0: new PPS source pps@12.-1
Nov 4 02:16:45 Ras1 kernel: [ 3.669176] pps pps0: Registered IRQ 170 as PPS source
Nov 4 02:16:45 Ras1 kernel: [ 4.165748] usb 1-1.3: ch341-uart converter now attached to ttyUSB0
Nov 4 02:19:19 Ras1 kernel: [ 159.192374] pps_ldisc: PPS line discipline registered
Nov 4 02:19:19 Ras1 kernel: [ 159.193572] pps pps1: new PPS source serial0
Nov 4 02:19:19 Ras1 kernel: [ 159.193769] pps pps1: source "/dev/ttyS0" added
Nov 4 02:19:20 Ras1 kernel: [ 160.130532] pps pps2: new PPS source usbserial0
Nov 4 02:19:20 Ras1 kernel: [ 160.130575] pps pps2: source "/dev/ttyUSB0" added
May 9 15:49:21 Ras1 kernel: [210712.571722] pps pps1: removed
May 10 16:53:09 Ras1 kernel: [300941.054728] pps pps2: removed
May 10 16:53:09 Ras1 kernel: [300941.059082] ch341-uart ttyUSB0: ch341-uart converter now disconnected from ttyUSB0
May 12 08:31:55 Ras1 kernel: [443668.706049] pps pps1: new PPS source serial0
May 12 08:31:55 Ras1 kernel: [443668.706085] pps pps1: source "/dev/ttyS0" added
May 12 08:32:51 Ras1 kernel: [443724.613282] pps pps1: removed
May 12 08:32:57 Ras1 kernel: [443730.023783] pps pps1: new PPS source serial0
May 12 08:32:57 Ras1 kernel: [443730.023835] pps pps1: source "/dev/ttyS0" added
反応は遅いけど syslog でキーワードに反応して再起動してもらうと楽かな?
ということで syslog.conf に書き込む方針を決定。
gpsd 再起動用のスクリプトを用意
#!/bin/sh
/bin/systemctl stop gpsd
/bin/stty -F /dev/ttyS0 115200
/bin/stty -F /dev/ttyUSB0 115200
/bin/stty -F /dev/ttyUSB1 115200
/bin/sleep 1
sync
/bin/systemctl start gpsd
sleep 1 は気持ち。sync はおまけ。
raspbian の syslog は rsyslog なので
omprog モジュールでメッセージをプログラムに送ることができるらしい
omprog は標準で読み込まれないのでロードしてから使う必要がある。
モジュールのロードはルーセットの中に書くと動作しないらしいので、他のモジュールを読み込んでいる辺りに以下の行を追加
module(load="omprog") # provides kernel logging support
そして、再起動用のルールは末尾に追加
# ここから下はルーセットのところへ書く
# for GPSD restart
if ($syslogfacility-text == 'kern' and re_match($msg,'pps pps[0-9]+: removed'))
then {
action(type="omprog" binary="/root/bin/gpsd_restart")
}
# 本筋とは関係ないけど ntpd のログを別ファイルに書き出す設定
# メッセージの表示形式
template (name="ntp_mess" type="string" string="%timereported% %hostname% %syslogfacility-text%.%syslogseverity-text% %msg%\n")
# ファイル名は /var/log/ntp.log_yyyymm ←毎月ローテションする
template (name="NtpLogfile" type="string" string="/var/log/ntp.log_%$year%%$month%")
if ($programname == 'ntpd')
then {
action(type="omfile" template="ntp_mess" dynaFile="NtpLogfile")
}
正規表現のマッチは重いだろうから \$syslogseverity-text == "~" を前に追加したり、そもそも正規表現を \$msg contains "pps pps" and \$msg contains ": removed' に置き換えたほうが軽くなるかな?
ログが生成されるたびに起動されるのではなかった
ここまできて、メッセージが発生するたびにキックされるのではなく rsyslog 起動と同時にスクリプトが起動し、メッセージが発生すると標準入力から送られるらしい。ということに気づく。
なら、再起動スクリプトは標準入力を読んで入力があるごとに再起動を実施するように変更。
#!/bin/sh
STTY=/bin/stty
GPSCTL=/home/pi/opt/gpsd-3.18.1/gpsctl
while read LINE; do
/bin/systemctl stop gpsd
$STTY -F /dev/ttyS0 115200
$STTY -F /dev/ttyUSB0 115200
$STTY -F /dev/ttyUSB1 115200
/bin/sleep
sync
/bin/systemctl start gpsd
logger -p local0.notice "$0: I restarted gpsd myself!"
done
再起動するか試す
メッセージがでると再起動するか試すために gpsd を止めてみる。まずは kill で
# tail -f /var/log/messages &
# killall gpsd
May 22 14:40:40 Ras1 kernel: [1329800.503226] pps pps1: removed
May 22 14:40:40 Ras1 kernel: [1329800.505482] pps pps2: removed
May 22 14:40:40 Ras1 kernel: [1329800.509767] pps pps3: removed
May 22 14:40:42 Ras1 systemd[1]: Started GPS (Global Positioning System) Daemon.
May 22 14:40:42 Ras1 root: /root/bin/gpsd_restart: I restarted gpsd myself!
May 22 14:40:42 Ras1 systemd[1]: Stopping GPS (Global Positioning System) Daemon...
May 22 14:40:42 Ras1 systemd[1]: Stopped GPS (Global Positioning System) Daemon.
May 22 14:40:43 Ras1 systemd[1]: Started GPS (Global Positioning System) Daemon.
May 22 14:40:43 Ras1 root: /root/bin/gpsd_restart: I restarted gpsd myself!
May 22 14:40:43 Ras1 systemd[1]: Stopping GPS (Global Positioning System) Daemon...
May 22 14:40:43 Ras1 systemd[1]: Stopped GPS (Global Positioning System) Daemon.
May 22 14:40:45 Ras1 systemd[1]: Started GPS (Global Positioning System) Daemon.
May 22 14:40:45 Ras1 root: /root/bin/gpsd_restart: I restarted gpsd myself!
May 22 14:40:48 Ras1 kernel: [1329807.923670] pps pps1: new PPS source serial0
May 22 14:40:48 Ras1 kernel: [1329807.923704] pps pps1: source "/dev/ttyS0" added
May 22 14:40:50 Ras1 kernel: [1329810.405293] pps pps2: new PPS source usbserial0
May 22 14:40:50 Ras1 kernel: [1329810.405328] pps pps2: source "/dev/ttyUSB0" added
May 22 14:40:52 Ras1 kernel: [1329811.871231] pps pps3: new PPS source usbserial1
May 22 14:40:52 Ras1 kernel: [1329811.871272] pps pps3: source "/dev/ttyUSB1" added
次に systemctl でも止めてみる。
# systemctl stop gpsd
May 22 14:42:09 Ras1 systemd[1]: Stopping GPS (Global Positioning System) Daemon...
May 22 14:42:09 Ras1 kernel: [1329889.553439] pps pps1: removed
May 22 14:42:09 Ras1 kernel: [1329889.555570] pps pps2: removed
May 22 14:42:09 Ras1 kernel: [1329889.573435] pps pps3: removed
May 22 14:42:09 Ras1 systemd[1]: Stopped GPS (Global Positioning System) Daemon.
Warning: Stopping gpsd.service, but it can still be activated by:
gpsd.socket
root@Ras1:/var/log# May 22 14:42:11 Ras1 systemd[1]: Started GPS (Global Positioning System) Daemon.
May 22 14:42:11 Ras1 root: /root/bin/gpsd_restart: I restarted gpsd myself!
May 22 14:42:11 Ras1 systemd[1]: Stopping GPS (Global Positioning System) Daemon...
May 22 14:42:11 Ras1 systemd[1]: Stopped GPS (Global Positioning System) Daemon.
May 22 14:42:12 Ras1 systemd[1]: Started GPS (Global Positioning System) Daemon.
May 22 14:42:12 Ras1 root: /root/bin/gpsd_restart: I restarted gpsd myself!
May 22 14:42:12 Ras1 systemd[1]: Stopping GPS (Global Positioning System) Daemon...
May 22 14:42:12 Ras1 systemd[1]: Stopped GPS (Global Positioning System) Daemon.
May 22 14:42:14 Ras1 systemd[1]: Started GPS (Global Positioning System) Daemon.
May 22 14:42:14 Ras1 root: /root/bin/gpsd_restart: I restarted gpsd myself!
May 22 14:42:17 Ras1 kernel: [1329896.963811] pps pps1: new PPS source serial0
May 22 14:42:17 Ras1 kernel: [1329896.963848] pps pps1: source "/dev/ttyS0" added
May 22 14:42:19 Ras1 kernel: [1329899.407741] pps pps2: new PPS source usbserial0
May 22 14:42:19 Ras1 kernel: [1329899.407777] pps pps2: source "/dev/ttyUSB0" added
May 22 14:42:21 Ras1 kernel: [1329900.769227] pps pps3: new PPS source usbserial1
May 22 14:42:21 Ras1 kernel: [1329900.769277] pps pps3: source "/dev/ttyUSB1" added
3度 pps removed のメッセージが出ていて、3度再起動メッセージが出ているので
間違いなくメッセージに反応して無事起動するようですね。
3度再起動しても起動に時間がかかるためか無限再起動にはならなかった。良かった良かった。
でも、これは反応鈍いから 10 分ごとの cron で killall -0 gpsd で起動していること確認し、ntpshmmon -t 10 | cut --delim=" " -f 2 | sort -un | wc -l とかで、数を数えた方が停止時間は短くて済むのかな。
チェックを走らせるのではなく、syslog みたいに何か起こると教えてくれるのが良いなぁ。gpsd が『同期外しました∠(・_・)』とか、ntpd が『セマフォが見えなくなった o(・・= ・・)o』とか通知してくれたら良いのにな。
syslog にこんなログが取れていた
適当に追加した ntpd 用の syslog 設定にこんなメッセージが。
May 22 21:34:00 Ras1 daemon.notice SHM(5): access clash in shared memory
May 23 00:08:38 Ras1 daemon.notice SHM(5): access clash in shared memory
May 23 01:16:07 Ras1 daemon.notice SHM(5): access clash in shared memory
May 23 07:20:21 Ras1 daemon.notice SHM(5): access clash in shared memory
May 23 09:23:18 Ras1 daemon.notice SHM(5): access clash in shared memory
...
このメッセージに反応してやればいいんじゃないか?
ntp.log に gpsd も併せてログを吐くように設定。
再起動条件が二つになったので、どちらを検知したかログに吐くようにする。
# ntpd & gpsd logging
# 記録するメッセージの書式
template (name="ntp_mess" type="string" string="%timereported% %hostname% %syslogfacility-text%.%syslogseverity-text% %msg%\n")
# ログファイル名
template (name="NtpLogfile" type="string" string="/var/log/ntp.log_%$year%%$month%")
if ($programname == 'ntpd' or $programname == 'gpsd')
then {
action(type="omfile" template="ntp_mess" dynaFile="NtpLogfile")
}
# for GPSD restart
template (name="ppsRemoveMess" type="string" string="*logger* pps removed message detect.")
if (re_match($msg,'pps pps[0-9]+: removed') and $syslogfacility-text == 'kern')
then {
action(type="omfile" template="SHMCrashMess" dynaFile="ppsRemoveMess")
action(type="omprog" binary="/root/bin/gpsd_restart")
}
template (name="SHMCrashMess" type="string" string="*logger* semaphore access error detect.")
if ($programname == 'ntpd' and $syslogpriority-text == 'notice' and re_match($msg,'SHM([0-9]+): access clash in shared memory'))
then {
action(type="omfile" template="SHMCrashMess" dynaFile="NtpLogfile")
action(type="omprog" binary="/root/bin/gpsd_restart")
}
ntpsmhmon の出力を見て再起動する
これをやったらいままでの記事が...
ntpshmmon の出力 6種類 (3台) の結果が取れていることを確認する。
こんな shell script を作成し cron で回す。
#!/bin/sh
NTPSHMMON=/home/pi/opt/gpsd-3.18.1/ntpshmmon
count=`$NTPSHMMON -t 3 | grep sample | cut --delim=" " -f 2 | sort -u | wc -l`
if [ $count -ne 6 ]; then
logger -p local0.notice "$0: ntpshm ckeck, error detected."
echo | /root/bin/gpsd_restart
fi
/root/bin/gpsd_restart は上で書いたやつね。chmod +x して
*/10 * * * * /root/bin/ntp_semaphore_check
rsyslog とか頑張らずに shell スクリプトだけでよかったよね。
その後、気付いたら何度か検知して再起動している形跡が。
May 28 16:20:05 Ras1 root: /root/bin/ntp_semaphore_check: ntpshm ckeck, error detected.
May 28 16:20:05 Ras1 kernel: [1854169.176931] pps pps1: removed
May 28 16:20:05 Ras1 kernel: [1854169.178880] pps pps2: removed
May 28 16:20:05 Ras1 kernel: [1854169.183365] pps pps3: removed
May 28 16:20:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 28 16:20:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 28 16:20:08 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 28 16:20:09 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 28 16:20:12 Ras1 kernel: [1854175.807330] pps pps1: new PPS source serial0
May 28 16:20:12 Ras1 kernel: [1854175.807370] pps pps1: source "/dev/ttyS0" added
May 28 16:20:14 Ras1 kernel: [1854178.259457] pps pps2: new PPS source usbserial0
May 28 16:20:14 Ras1 kernel: [1854178.259495] pps pps2: source "/dev/ttyUSB0" added
May 28 16:20:16 Ras1 kernel: [1854179.679212] pps pps3: new PPS source usbserial1
May 28 16:20:16 Ras1 kernel: [1854179.679251] pps pps3: source "/dev/ttyUSB1" added
May 29 06:25:02 Ras1 liblogging-stdlog: [origin software="rsyslogd" swVersion="8.24.0" x-pid="25120" x-info="http://www.rs
yslog.com"] rsyslogd was HUPed
May 29 16:40:05 Ras1 root: /root/bin/ntp_semaphore_check: ntpshm ckeck, error detected.
May 29 16:40:05 Ras1 kernel: [1941769.311328] pps pps1: removed
May 29 16:40:05 Ras1 kernel: [1941769.313264] pps pps2: removed
May 29 16:40:05 Ras1 kernel: [1941769.482596] pps pps3: removed
May 29 16:40:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:40:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:40:07 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:40:08 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:40:11 Ras1 kernel: [1941776.161718] pps pps1: new PPS source serial0
May 29 16:40:11 Ras1 kernel: [1941776.161757] pps pps1: source "/dev/ttyS0" added
May 29 16:40:13 Ras1 kernel: [1941777.980825] pps pps2: new PPS source usbserial0
May 29 16:40:13 Ras1 kernel: [1941777.980861] pps pps2: source "/dev/ttyUSB0" added
May 29 16:40:15 Ras1 kernel: [1941779.414840] pps pps3: new PPS source usbserial1
May 29 16:40:15 Ras1 kernel: [1941779.414877] pps pps3: source "/dev/ttyUSB1" added
May 29 16:50:05 Ras1 root: /root/bin/ntp_semaphore_check: ntpshm ckeck, error detected.
May 29 16:50:05 Ras1 kernel: [1942369.736110] pps pps1: removed
May 29 16:50:05 Ras1 kernel: [1942369.738028] pps pps2: removed
May 29 16:50:05 Ras1 kernel: [1942369.743145] pps pps3: removed
May 29 16:50:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:50:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:50:07 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:50:08 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 16:50:11 Ras1 kernel: [1942376.156495] pps pps1: new PPS source serial0
May 29 16:50:11 Ras1 kernel: [1942376.156536] pps pps1: source "/dev/ttyS0" added
May 29 16:50:13 Ras1 kernel: [1942378.019658] pps pps2: new PPS source usbserial0
May 29 16:50:13 Ras1 kernel: [1942378.019694] pps pps2: source "/dev/ttyUSB0" added
May 29 16:50:15 Ras1 kernel: [1942379.415545] pps pps3: new PPS source usbserial1
May 29 16:50:15 Ras1 kernel: [1942379.415584] pps pps3: source "/dev/ttyUSB1" added
May 29 17:00:05 Ras1 root: /root/bin/ntp_semaphore_check: ntpshm ckeck, error detected.
May 29 17:00:05 Ras1 kernel: [1942969.740943] pps pps1: removed
May 29 17:00:05 Ras1 kernel: [1942969.743982] pps pps2: removed
May 29 17:00:05 Ras1 kernel: [1942969.748340] pps pps3: removed
May 29 17:00:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 17:00:06 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 17:00:07 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 17:00:08 Ras1 root: /root/bin/gpsd_restart: gpsd restart to me!
May 29 17:00:11 Ras1 kernel: [1942976.171453] pps pps1: new PPS source serial0
May 29 17:00:11 Ras1 kernel: [1942976.171489] pps pps1: source "/dev/ttyS0" added
May 29 17:00:13 Ras1 kernel: [1942978.013885] pps pps2: new PPS source usbserial0
May 29 17:00:13 Ras1 kernel: [1942978.013924] pps pps2: source "/dev/ttyUSB0" added
May 29 17:00:14 Ras1 kernel: [1942979.136086] pps pps3: new PPS source usbserial1
May 29 17:00:14 Ras1 kernel: [1942979.136127] pps pps3: source "/dev/ttyUSB1" added
セマフォでエラーを発見 → gpsd の再起動 → pps removed メッセージを 3回出力 → gpsd を再起動 x3回
となるみたいですねぇ。syslog の検知は止めた方がいいですね。
そして、一度の再起動では復旧しないこともあるっぽい。ちなみに ccze -A < messages で表示させるとこんなカラフルに。
そして、がんがん再起動はするもののやはり ntpd からは認識されず。
gpsmon で見ると、SHM(0) & SHM(2) (=UART経由) は生きてるんだけどなぁ。gpsd と ntpd の通信がうまくいかないんですねぇ。
そして、USBの 2ポートは通信速度が合わずダメ。こちらは gpsd の問題か。
gpsd の通信速度をする方法あるかなぁ?
上が Windows 上の ntpd 4.2.8p13、下が Raspberry Pi の ntpsec-1.1.3 (最新は 1.1.6)
3つの PPSで、UART のだけ offset が+で、USB が-ってのはなんでだ?逆じゃないのかなぁ???