때때로 시스템 서비스 로그에서 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(표준) 인스턴스에서 관찰되었습니다.