実現したいこと

ラズベリーパイでHomebridgeを稼働させており、ログファイルに任意の文字列が発生したときに、Homebride を再起動させたい。

前提

Homebridge のログファイルの最終行に"Socket had a problem and will reconnect to"と出てきたらHomebridgeサーバーを再起動させたいと思っています。

監視対象のファイルは/var/lib/homebridge.log
以下のようなスクリプトを書き、nohup ./logchecker.sh &で実行、スクリプトは（まずは動作検証用に）スマホにLINEを送る内容になっています。

#!/bin/sh
# Target
TARGET_LOG="/var/lib/homebridge/homebridge.log"

# Word for detection
_error_conditions="Socket had a problem and will reconnect to"

hit_action() {
    while read i
    do
        echo $i | grep -q "${_error_conditions}"
        if [ $? = "0" ];then
            # Script
		curl -X POST -H 'Authorization: Bearer API key hogehoge' -F 'message=hogehoge' https://notify-api.line.me/api/notify
        fi
	sleep 10
    done
}

# main
if [ ! -f ${TARGET_LOG} ];then
    touch ${TARGET_LOG}
fi

tail -n 1 -f $TARGET_LOG | hit_action

発生している問題・エラーメッセージ

狙いどおりlogファイルの最終行がSocket had a problem and will reconnect to XXXXX...になるとスクリプトは動くのですが、その後ログが進んで最終行が別の内容になっても、killするまで10秒ごとにLINEに通知が飛び続けます。
スクリプトの実行は1回だけでよいのですが、どのように解決すればよいでしょうか。

その他

当方非プログラマの超初心者です。コピペしたプログラムを改変する程度のスキルです。
上記のスクリプトは以下から拝借しております。
https://qiita.com/Qrg/items/107928672569a8141222

【2022/03/23/11/19追記】otn様への回答

一度エラーが発動すると下記のようなエラーが同時に1行～10行ぐらい書き込まれます（行数は状況により変化、デバイス名部分は伏せています）。なおタイムスタンプはありません。このエラーを放置すると、５秒置き程度で同じエラーが書き込まれます。プラグインを再起動するとエラーは静まります。本来はこのプラグインのエラーを修正すべきだと思いますが、このプラグインの開発者ではありませんので。。。Githubでissueとして上げてはいます。

[Tuya] Socket had a problem and will reconnect to "デバイス1" (EHOSTUNREACH)
[Tuya] Socket had a problem and will reconnect to "デバイス2" (Error: ERR_CONNECTION_TIMED_OUT)
[Tuya] Socket had a problem and will reconnect to "デバイス3" (Error: ERR_CONNECTION_TIMED_OUT)
[Tuya] Socket had a problem and will reconnect to "デバイス4" (Error: ERR_CONNECTION_TIMED_OUT)

otn様のいう通り一気に10行書き込まれたら10回curlしているのをループとして見えている可能性もあり、これをまとめて１回にする方法があれば、それでもいいのかもしれません。

【2022/03/23/11/19追記】otn様へｍの回答２

ps fx で下記のような内容が得られます。

30645 ?        S      0:00 sshd: pi@notty
30646 ?        Ss     0:00  \_ /usr/lib/openssh/sftp-server
30610 ?        Ss     0:00 /lib/systemd/systemd --user
30611 ?        S      0:00  \_ (sd-pam)
30561 ?        S      0:00 /bin/sh ./logchecker.sh
30562 ?        S      0:00  \_ tail -n 0 -f /var/lib/homebridge/homebridge.log
30563 ?        S      0:00  \_ /bin/sh ./logchecker.sh
31971 ?        S      0:00      \_ curl -k https://hogehoge
18040 ?        Ssl    1:01 hb-service
18056 ?        Sl     0:32  \_ homebridge
18069 ?        Sl     0:12  |   \_ homebridge: homebridge-hogehoge1
18077 ?        Sl     0:35  |   \_ homebridge: homebridge-hogehoge2
18079 ?        Sl     0:35  |   \_ homebridge: homebridge-hogehoge3
18089 ?        Sl     0:15  |   \_ homebridge: homebridge-hogehoge4
　　　　　　　　　　　・
　　　　　　　　　　　・
　　　　　　　　　　　・

setoppu

2023/03/21 02:34

ログファイルならは同じ行にタイムスタンプとか出ていませんかね？検出したときのタイムスタンプをファイル（/tmp/logchecher）などに記録して、同じタイムスタンプだったら中断、異なるタイムスタンプだったらタイムスタンプを更新して実行。のように処理すればよいかと。

melian

2023/03/21 02:48

本題とは関係ありませんが、 while read i で入力待ちになりますので、必ず 10 秒待機する、という必要がなければ sleep 10 は不要になります。

行動規範の内容に同意します

回答1件

ベストアンサー

スクリプトにループする要因は無いです。

10秒待っていますが、10秒以内に対象メッセージ行が複数回出ると、最新のメッセージが対象でなくても、未読の該当メッセージを全て処理し続けますが、その現象をみて「ループしている」と誤解しているのではないでしょうか？
当然ですが、対象メッセージが100行あると100回curlを実行しますよ。

追記：一度通知したら10秒間無視するサンプル(Bash)

date +%sは、1970-01-01 00:00:00 からの経過秒数です。

Bash
1last=0
2hit_action() {
3    while read i
4    do
5        echo $i | grep -q "${_error_conditions}"
6        if [ $? = "0" ];then
7            now=$(date +%s)
8            if [ "$now" -gt "$last" ];then
9                通知処理
10                let last=now+10
11            fi
12        fi
13    done
14}

投稿2023/03/21 05:05

編集2023/03/23 03:04

otn

総合スコア84557

otn

2023/03/21 10:03

そもそも、メッセージの発生頻度が10秒に1行以上あると、どんどん未処理がたまって遅延していきますね。

skel

2023/03/22 10:36

はい、そのはずなのですが…sleepを削除して実行してみると、やはりループが発動します。この場合は1秒おきにLINEが飛んできてしまいます。

otn

2023/03/22 12:13

該当メッセージはどの程度（何秒に何件）あるのでしょうか？

skel

2023/03/23 02:21

本文に追記させていただきましたのでご確認いただけますと幸いです。

otn

2023/03/23 03:04 編集

ログファイルを見てみて、該当メッセージが短時間に10行書き込まれているのなら、LINE通知が短時間に10回発生するのはシェルスクリプトに書かれている通りなので、正常動作です。「一度メッセージが発生したら、指定時間内は新たな該当メッセージが発生しても無視する」という仕様にしたければ、そのように書く必要があります。サンプルを追記しておきます。

skel

2023/03/23 03:26

サンプル誠にありがとうございます。こちらに書き換えて実行したところ、やはり0.5秒おきにループが発動します。追記2で書かかせていただいた通り、プロセスの二重起動の可能性もあるので、10秒おきに2回発動ならまだわかるのですが、そうではない状況です。

otn

2023/03/23 03:46

パイプで処理しているので、プロセス構成はそれで正常です。別の端末で、 tail -f /var/lib/homebridge/homebridge.log | grep --line-buffered "Socket had a problem and will reconnect to" の出力を目で監視してみて、該当ログがN行しか増えていないのに、通知がN+1件以上でることはありますか？（--line-buffered は必須）また、念のため /bin/sh でなく /bin/bash で実行してみてください。

skel

2023/03/23 15:15

こちら実験をしてみたところ、過去のログの行を全て走査して、Socket had a problem and will reconnect toがある行すべてを吐き出していました。全部で1000行以上あったので1000回以上curlしようとしていたようです。そこで一旦ログファイルをまっさらにし、人為的に"Socket had a problem and will reconnect to"を書き込んだところ、ループせずにスクリプトが走りました！その後しばらく放置して別のログ内容が書き込まれたあとに、もう一度"Socket had a problem and will reconnect to"を発生させても、冒頭の行には反応せずに末尾の行だけを認識するようになりました。なぜ以前のログファイルではすべての行を走査してしまうのか原因はわかりませんが、とにかく狙い通りの挙動になったので、質問は解決としたいと思います。誠にありがとうございました。

otn

2023/03/23 15:55

> こちら実験をしてみたところ、過去のログの行を全て走査して、Socket had a problem and will reconnect toがある行すべてを吐き出していました。 tail -n 1 -f では、ファイルに追加書きをしている限りはそういうことは起こらないので、あり得るとしたら、ログを書くプログラムが、追加書きで無く毎回ファイル先頭から全件書いてるとかですかね。その場合は、tail -f を使っても追加された行だけを取得することは出来ませんので、別の方法を考える必要があります。

otn

2023/03/23 15:56

ところで、指摘し漏れてましたが、普通に追加書きされる前提だとして、普通はこのスクリプト実行開始後に出たログを対象にしたいでしょうから、 tail -n 0 -f でしょうか。

skel

2023/03/23 16:40

そうでうすね、tail -n 0が本来の使い方だと思います。いろいろ試行錯誤しているうちに1にしていたのでこれは0に戻しました。ありがとうございます。 > あり得るとしたら、ログを書くプログラムが、追加書きで無く毎回ファイル先頭から全件書いてるとかですかね。大いにありうる推理です。しかしlogファイルを更改したあとは、逆にループを再現できなくなってしまったので原因はよくわからず。。。

行動規範の内容に同意します