![systemd 服务日志中偶尔缺少 ping 输出(标记为错误的单位)](https://linux22.com/image/227382/systemd%20%E6%9C%8D%E5%8A%A1%E6%97%A5%E5%BF%97%E4%B8%AD%E5%81%B6%E5%B0%94%E7%BC%BA%E5%B0%91%20ping%20%E8%BE%93%E5%87%BA%EF%BC%88%E6%A0%87%E8%AE%B0%E4%B8%BA%E9%94%99%E8%AF%AF%E7%9A%84%E5%8D%95%E4%BD%8D%EF%BC%89.png)
我正在一个脚本中使用ping
,该脚本在 systemd 服务单元中运行。 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
输出有时低于单位myscript
(错误),有时低于单位[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 查看其所有活动。