search

sonic-net / sonic-buildimage

Scripts which perform an installable binary image build for SONiC
Other
728 stars 1.39k forks source link

[rsyslog] rsyslogd is flooding ERR and WARNING after system startup #6675

Open bingwang-ms opened 3 years ago

bingwang-ms commented 3 years ago

Description

rsyslogd is flooding ERRs and WARNINGs after system startup

syslog.68.gz:Feb  3 18:53:06.045398 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.045518 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.045870 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.045989 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.046351 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.046470 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.046801 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.046900 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.047184 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.047284 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.047590 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.047685 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.047966 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.048072 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.048363 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.048455 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.048733 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.048947 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.049419 str-7260cx3-acs-2 ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]
syslog.68.gz:Feb  3 18:53:06.049581 str-7260cx3-acs-2 ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.1901.0 try https://www.rsyslog.com/e/2354 ]

The logs usually keeps flooding for a few seconds after system startup. It's possibly caused by some unready service. Could we supress these ERRs and WARNINGs?

syslog.45.gz syslog.34.gz

Steps to reproduce the issue:

  1. Run some test case including reboot

Describe the results you received:

Describe the results you expected:

Additional information you deem important (e.g. issue happens only occasionally):

**Output of `show version`:**
SONiC Software Version: SONiC.HEAD.339-5c8b70ea
Distribution: Debian 10.7
Kernel: 4.19.0-9-2-amd64
Build commit: 5c8b70ea
Build date: Tue Feb  2 02:33:34 UTC 2021
Built by: johnar@jenkins-worker-22

Platform: x86_64-arista_7260cx3_64
HwSKU: Arista-7260CX3-D108C8
ASIC: broadcom
ASIC Count: 1
Serial Number: SSJ17432414
Uptime: 02:17:48 up  2:47,  1 user,  load average: 5.03, 4.10, 4.20

Docker images:
REPOSITORY                    TAG                 IMAGE ID            SIZE
docker-fpm-frr                HEAD.339-5c8b70ea   f3c9e3af45ae        427MB
docker-fpm-frr                latest              f3c9e3af45ae        427MB
docker-snmp                   HEAD.339-5c8b70ea   b400adc665fe        438MB
docker-snmp                   latest              b400adc665fe        438MB
docker-syncd-brcm             HEAD.339-5c8b70ea   3cdf85f51e97        679MB
docker-syncd-brcm             latest              3cdf85f51e97        679MB
docker-teamd                  HEAD.339-5c8b70ea   500b6b47959d        408MB
docker-teamd                  latest              500b6b47959d        408MB
docker-router-advertiser      HEAD.339-5c8b70ea   cff46295d07e        397MB
docker-router-advertiser      latest              cff46295d07e        397MB
docker-platform-monitor       HEAD.339-5c8b70ea   6b9a0beca7a2        605MB
docker-platform-monitor       latest              6b9a0beca7a2        605MB
docker-macsec                 HEAD.339-5c8b70ea   43cc58ffeecc        411MB
docker-macsec                 latest              43cc58ffeecc        411MB
docker-lldp                   HEAD.339-5c8b70ea   9e76d9751a62        437MB
docker-lldp                   latest              9e76d9751a62        437MB
docker-dhcp-relay             HEAD.339-5c8b70ea   d2f9996298b3        404MB
docker-dhcp-relay             latest              d2f9996298b3        404MB
docker-database               HEAD.339-5c8b70ea   a5e285ed330f        397MB
docker-database               latest              a5e285ed330f        397MB
docker-sonic-mgmt-framework   HEAD.339-5c8b70ea   83f9a5f79f47        615MB
docker-sonic-mgmt-framework   latest              83f9a5f79f47        615MB
docker-orchagent              HEAD.339-5c8b70ea   a6aa19dd2381        426MB
docker-orchagent              latest              a6aa19dd2381        426MB
docker-nat                    HEAD.339-5c8b70ea   8e925ec8392f        411MB
docker-nat                    latest              8e925ec8392f        411MB
docker-sonic-telemetry        HEAD.339-5c8b70ea   77e2f48bbe40        472MB
docker-sonic-telemetry        latest              77e2f48bbe40        472MB
docker-sflow                  HEAD.339-5c8b70ea   928f9bdd6490        408MB
docker-sflow                  latest              928f9bdd6490        408MB
**Attach debug file `sudo generate_dump`:**

```
(paste your output here)
```
stepanblyschak commented 3 years ago

@yxieca @bingwang-ms Is there a plan to fix this issue?

yxieca commented 3 years ago

@stepanblyschak IIRC, this issue is transient at boot up time. We searched internet and didn't found a good solution for this issue. At the moment, we are not actively working on this issue. Did you see side effect from this issue?

If you found solution, please share.

nazariig commented 2 years ago

The issue is observed during interfaces-config.service startup (e.g., config reload, cold/warm/fast reboot) The root cause is: networking reconfiguration

https://github.com/Azure/sonic-buildimage/blob/master/files/image_config/interfaces/interfaces-config.sh#L66

# Read sysctl conf files again
sysctl -p /etc/sysctl.d/90-dhcp6-systcl.conf

systemctl restart networking

# Clean-up created files
rm -f /tmp/ztp_input.json /tmp/ztp_port_data.json

Major services:

  1. rsyslog-config.service 
    
root@sonic:/home/admin# cat /lib/systemd/system/rsyslog-config.service
[Unit]
Description=Update rsyslog configuration
Requires=updategraph.service
After=updategraph.service
BindsTo=sonic.target
After=sonic.target

[Service] Type=oneshot RemainAfterExit=yes ExecStart=/usr/bin/rsyslog-config.sh

[Install] WantedBy=sonic.target


2. `rsyslog.service`
```bash
root@sonic:/home/admin# cat /lib/systemd/system/rsyslog.service
[Unit]
Description=System Logging Service
Requires=syslog.socket
Documentation=man:rsyslogd(8)
Documentation=man:rsyslog.conf(5)
Documentation=https://www.rsyslog.com/doc/

[Service]
Type=notify
ExecStart=/usr/sbin/rsyslogd -n
StandardOutput=null
Restart=on-failure

# Increase the default a bit in order to allow many simultaneous
# files to be monitored, we might need a lot of fds.
LimitNOFILE=16384

[Install]
WantedBy=multi-user.target
Alias=syslog.service
  1. interfaces-config.service 
    
root@sonic:/home/admin# cat /lib/systemd/system/interfaces-config.service
[Unit]
Description=Update interfaces configuration
Requires=updategraph.service
After=updategraph.service
BindsTo=sonic.target
After=sonic.target

[Service] Type=oneshot RemainAfterExit=yes ExecStart=/usr/bin/interfaces-config.sh

[Install] WantedBy=sonic.target


**Steps to repro:**
1. Restart networking
```bash
root@sonic:/home/admin# service networking restart
  1. Check the logs 
    root@sonic:/home/admin# tail -F /var/log/syslog | grep rsyslogd
Jun  1 17:12:23.476901 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.785421 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.785541 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.785749 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.785915 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.786096 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.786167 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.786427 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.786535 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.786709 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.786901 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.786982 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.787188 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.787279 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.787419 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.787532 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.787670 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.787877 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.787951 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.788106 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.788293 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.788540 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.788676 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.788812 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.788989 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.789082 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.789232 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.789451 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.789568 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.789637 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.789815 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.790198 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.790562 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.790662 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.790721 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.790801 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.790898 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:12:25.791019 sonic ERR rsyslogd: omfwd/udp: socket 9: sendto() error: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.791209 sonic ERR rsyslogd: omfwd: socket 9: error 101 sending via udp: Network is unreachable [v8.2102.0 try https://www.rsyslog.com/e/2354 ]
Jun  1 17:12:25.791254 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), retry 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:12:25.791474 sonic WARNING rsyslogd: action 'action-8-builtin:omfwd' suspended (module 'builtin:omfwd'), next retry is Wed Jun  1 17:12:55 2022, retry nbr 0. There should be messages before this one giving the reason for suspension. [v8.2102.0 try https://www.rsyslog.com/e/2007 ]
Jun  1 17:13:04.877561 sonic INFO rsyslogd: action 'action-8-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.2102.0 try https://www.rsyslog.com/e/2359 ]
Jun  1 17:13:05.314314 sonic INFO swss#rsyslogd: action 'action-0-builtin:omfwd' resumed (module 'builtin:omfwd') [v8.1901.0 try https://www.rsyslog.com/e/2359 ]