時にはシステムサービスログにping出力がありません(無効なデバイスとしてマークされています)

時にはシステムサービスログにping出力がありません(無効なデバイスとしてマークされています)

ping私はこれをシステムサービスユニットで実行されるスクリプトで使用しています。 ping出力は、デバイスログから時々(しばしば)失われます。つまり、失われますjournalctl --user -u MyUnit

pingスクリプトが独自のループで呼び出される長期実行スクリプトであるか(バリアント1)、タイマーを使用して定期的に起動するか(バリエーション2)、それを観察できます。また、スクリプトが実際に実行されたことを確認するために、追加のファイルにタイムスタンプを記録しています。実際はいつもそうです。


変形1

スクリプト:

$ cat ~/ping_test
#!/bin/bash
ITERATION=0
while true
do
    echo "Iteration $ITERATION"
    let ITERATION=ITERATION+1
    date >> timestamps
    ping -c 1 vodafone.de
    sleep 10
done

サービスユニット:

$ cat ~/.config/systemd/user/ping_test.service
[Unit]
Description=Ping Test
    
[Service]
ExecStart=%h/ping_test
    
[Install]
WantedBy=default.target

亜種2

スクリプト:

$ cat ~/myscript
#!/bin/bash
echo HELLO
date >> timestamps
ping -c 1 vodafone.de

サービスユニット:

$ cat ~/.config/systemd/user/test.service
[Unit]
description = test

[Service]
ExecStart=%h/myscript

[Install]
WantedBy=default.target

タイマー装置:

$ cat ~/.config/systemd/user/test.timer
[Unit]
Description = myscript

[Timer]
OnCalendar=*-*-* *:*:0/10
AccuracySec=1s

[Install]
WantedBy=timers.target

以下はバリアント2の出力ですが、バリアント1には実際に同じ問題があります。

以下にping別の出力が表示されますが、出力が欠落している可能性があるユニットログを示します。HELLO間に出力がない連続メッセージを表示します。PING

$ journalctl --user -n 40 --no-pager -u test
Dec 20 16:16:20 debian myscript[2839]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Dec 20 16:16:20 debian myscript[2839]: rtt min/avg/max/mdev = 21.241/21.241/21.241/0.000 ms
Dec 20 16:16:30 debian systemd[1686]: Started test.service.
Dec 20 16:16:30 debian myscript[2842]: HELLO
Dec 20 16:16:40 debian systemd[1686]: Started test.service.
Dec 20 16:16:40 debian myscript[2845]: HELLO
Dec 20 16:16:50 debian systemd[1686]: Started test.service.
Dec 20 16:16:50 debian myscript[2849]: HELLO
Dec 20 16:16:50 debian myscript[2850]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Dec 20 16:16:50 debian myscript[2850]: 64 bytes from hilfe.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=20.6 ms
Dec 20 16:16:50 debian myscript[2850]: --- vodafone.de ping statistics ---
Dec 20 16:16:50 debian myscript[2850]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Dec 20 16:16:50 debian myscript[2850]: rtt min/avg/max/mdev = 20.591/20.591/20.591/0.000 ms
Dec 20 16:17:00 debian systemd[1686]: Started test.service.
Dec 20 16:17:00 debian myscript[2852]: HELLO
Dec 20 16:17:00 debian myscript[2853]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Dec 20 16:17:00 debian myscript[2853]: 64 bytes from incubator.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=17.7 ms
Dec 20 16:17:00 debian myscript[2853]: --- vodafone.de ping statistics ---
Dec 20 16:17:00 debian myscript[2853]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Dec 20 16:17:00 debian myscript[2853]: rtt min/avg/max/mdev = 17.718/17.718/17.718/0.000 ms
Dec 20 16:17:10 debian systemd[1686]: Started test.service.
Dec 20 16:17:10 debian myscript[2862]: HELLO
Dec 20 16:17:20 debian systemd[1686]: Started test.service.
Dec 20 16:17:20 debian myscript[2865]: HELLO
Dec 20 16:17:30 debian systemd[1686]: Started test.service.
Dec 20 16:17:30 debian myscript[2869]: HELLO
Dec 20 16:17:30 debian myscript[2870]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Dec 20 16:17:30 debian myscript[2870]: 64 bytes from hilfe.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=20.3 ms
Dec 20 16:17:30 debian myscript[2870]: --- vodafone.de ping statistics ---
Dec 20 16:17:30 debian myscript[2870]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Dec 20 16:17:30 debian myscript[2870]: rtt min/avg/max/mdev = 20.328/20.328/20.328/0.000 ms
Dec 20 16:17:40 debian systemd[1686]: Started test.service.
Dec 20 16:17:40 debian myscript[2872]: HELLO
Dec 20 16:17:40 debian myscript[2873]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Dec 20 16:17:40 debian myscript[2873]: 64 bytes from incubator.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=22.9 ms
Dec 20 16:17:40 debian myscript[2873]: --- vodafone.de ping statistics ---
Dec 20 16:17:40 debian myscript[2873]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Dec 20 16:17:40 debian myscript[2873]: rtt min/avg/max/mdev = 22.900/22.900/22.900/0.000 ms
Dec 20 16:17:50 debian systemd[1686]: Started test.service.
Dec 20 16:17:50 debian myscript[2877]: HELLO

以下は、fromの出力がping失われることなく実際に表示されますが、ユニットが時々正しくないことを示しています。PING出力は時々1より低く(myscript間違って)、時には1よりも低い[email protected]/test.service(正しい)。

$ journalctl --user -n 40 --no-pager --output=with-unit
Wed 2023-12-20 16:20:10 UTC debian myscript[3065]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Wed 2023-12-20 16:20:10 UTC debian myscript[3065]: 64 bytes from hilfe.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=19.0 ms
Wed 2023-12-20 16:20:10 UTC debian myscript[3065]: --- vodafone.de ping statistics ---
Wed 2023-12-20 16:20:10 UTC debian myscript[3065]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Wed 2023-12-20 16:20:10 UTC debian myscript[3065]: rtt min/avg/max/mdev = 19.019/19.019/19.019/0.000 ms
Wed 2023-12-20 16:20:20 UTC debian [email protected]/init.scope[1686]: Started test.service.
Wed 2023-12-20 16:20:20 UTC debian [email protected]/test.service[3067]: HELLO
Wed 2023-12-20 16:20:20 UTC debian myscript[3068]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Wed 2023-12-20 16:20:20 UTC debian myscript[3068]: 64 bytes from hilfe.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=18.8 ms
Wed 2023-12-20 16:20:20 UTC debian myscript[3068]: --- vodafone.de ping statistics ---
Wed 2023-12-20 16:20:20 UTC debian myscript[3068]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Wed 2023-12-20 16:20:20 UTC debian myscript[3068]: rtt min/avg/max/mdev = 18.815/18.815/18.815/0.000 ms
Wed 2023-12-20 16:20:30 UTC debian [email protected]/init.scope[1686]: Started test.service.
Wed 2023-12-20 16:20:30 UTC debian [email protected]/test.service[3070]: HELLO
Wed 2023-12-20 16:20:30 UTC debian myscript[3071]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Wed 2023-12-20 16:20:30 UTC debian myscript[3071]: 64 bytes from incubator.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=17.8 ms
Wed 2023-12-20 16:20:30 UTC debian myscript[3071]: --- vodafone.de ping statistics ---
Wed 2023-12-20 16:20:30 UTC debian myscript[3071]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Wed 2023-12-20 16:20:30 UTC debian myscript[3071]: rtt min/avg/max/mdev = 17.773/17.773/17.773/0.000 ms
Wed 2023-12-20 16:20:40 UTC debian [email protected]/init.scope[1686]: Started test.service.
Wed 2023-12-20 16:20:40 UTC debian [email protected]/test.service[3073]: HELLO
Wed 2023-12-20 16:20:40 UTC debian myscript[3074]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Wed 2023-12-20 16:20:40 UTC debian myscript[3074]: 64 bytes from incubator.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=19.3 ms
Wed 2023-12-20 16:20:40 UTC debian myscript[3074]: --- vodafone.de ping statistics ---
Wed 2023-12-20 16:20:40 UTC debian myscript[3074]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Wed 2023-12-20 16:20:40 UTC debian myscript[3074]: rtt min/avg/max/mdev = 19.251/19.251/19.251/0.000 ms
Wed 2023-12-20 16:20:50 UTC debian [email protected]/init.scope[1686]: Started test.service.
Wed 2023-12-20 16:20:50 UTC debian [email protected]/test.service[3077]: HELLO
Wed 2023-12-20 16:20:50 UTC debian [email protected]/test.service[3078]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Wed 2023-12-20 16:20:50 UTC debian [email protected]/test.service[3078]: 64 bytes from incubator.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=20.9 ms
Wed 2023-12-20 16:20:50 UTC debian [email protected]/test.service[3078]: --- vodafone.de ping statistics ---
Wed 2023-12-20 16:20:50 UTC debian [email protected]/test.service[3078]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Wed 2023-12-20 16:20:50 UTC debian [email protected]/test.service[3078]: rtt min/avg/max/mdev = 20.893/20.893/20.893/0.000 ms
Wed 2023-12-20 16:21:00 UTC debian [email protected]/init.scope[1686]: Started test.service.
Wed 2023-12-20 16:21:00 UTC debian [email protected]/test.service[3080]: HELLO
Wed 2023-12-20 16:21:00 UTC debian myscript[3081]: PING vodafone.de (139.7.147.49) 56(84) bytes of data.
Wed 2023-12-20 16:21:00 UTC debian myscript[3081]: 64 bytes from hilfe.vodafone.de (139.7.147.49): icmp_seq=1 ttl=244 time=20.0 ms
Wed 2023-12-20 16:21:00 UTC debian myscript[3081]: --- vodafone.de ping statistics ---
Wed 2023-12-20 16:21:00 UTC debian myscript[3081]: 1 packets transmitted, 1 received, 0% packet loss, time 0ms
Wed 2023-12-20 16:21:00 UTC debian myscript[3081]: rtt min/avg/max/mdev = 19.992/19.992/19.992/0.000 ms

また、/var/log/syslog(を介してrsyslog)には以下も含まれます。みんな情報。

現在私はこれがsystemdのバグだと思います。私が見るサービス単位は次のとおりです。時々開始されたプロセスによって正しく「継承」されないため、ログは出力単位を正しくキャプチャしません。

仮想マシンとRaspberry Piオペレーティングシステムで実行されている影響を受けていないDebian 12 Live(標準)インスタンスで観察されました。

答え1

だからそうしないでください!

10秒ごとにpingを実行するタイマーデバイスを作成します。

/etc/systemd/system/ping.timer
[Unit]
Description=Runping every ten seconds

[Timer]
OnBootSec=10s

[Install]
WantedBy=timers.target

そして、サービスファイルは次のようになります。

/etc/systemd/system/ping.service
[Unit]
Description=pinger
[Service]
ExecStart=/usr/bin/ping -c 1 vodafone.de

daemon-reloadしてpingタイマーを有効にします。次に、Journalctl -u ping.service を使用してすべてのアクティビティを確認します。

関連情報