Page MenuHomeVyOS Platform

syslog doesn't start automatically
Closed, ResolvedPublicBUG

Description

On a recent rolling (12/30), it appears firewall rules aren't being logged despite having log enable on them.

The fix was simply:

sudo systemctl restart rsyslog

and firewall rules immediately started being logged.

Not sure if this is an ordering problem or what.

Details

Difficulty level
Normal (likely a few hours)
Version
1.3-rolling
Why the issue appeared?
Will be filled on close
Is it a breaking change?
Unspecified (possibly destroys the router)

Event Timeline

kroy created this task.Jan 2 2020, 11:08 PM
hagbard claimed this task.Jan 7 2020, 9:00 PM

looks like service syslog did disappear from the default config.

kroy added a comment.Jan 7 2020, 9:34 PM

It definitely remains in my config:

# show system syslog
 global {
     facility all {
         level info
     }
     facility protocols {
         level debug
     }
     preserve-fqdn
 }
 host 10.22.22.108 {
     facility all {
         level all
         protocol udp
     }
     port 1514
 }

systemctl renamed it to syslog, so it won't be restarted correctly and the conf script won't generate the files correctly. It is correctly named within init.d.

hagbard triaged this task as Normal priority.Jan 7 2020, 9:51 PM
hagbard changed Difficulty level from Unknown (require assessment) to Normal (likely a few hours).
kroy added a comment.Jan 8 2020, 12:41 AM

Confirmed fix with that commit.

Thanks!

hagbard closed this task as Resolved.Jan 8 2020, 4:27 PM
hagbard moved this task from In Progress to Finished on the VyOS 1.3 Equuleus board.
kroy reopened this task as Open.Mar 16 2020, 4:57 PM

@hagbard This problem is back on a rolling built on the 14th. Fix again was to run

sudo systemctl restart rsyslog

kroy moved this task from Finished to Need Triage on the VyOS 1.3 Equuleus board.Mar 16 2020, 4:57 PM
pasik added a subscriber: pasik.Mar 16 2020, 9:10 PM
tjh added a subscriber: tjh.Apr 15 2020, 1:55 AM

I've just encountered this bug with Vyos 1.2.5 (final, official ISO)

tim@ferrari# show firewall name LAN-IN
 default-action accept
 rule 500 {
     action drop
     description "Drop Camera Internet Traffic"
     log enable
     source {
         address 192.168.0.11-192.168.0.12
     }
 }
tim@ferrari:~$ sudo dmesg
<snip lots of other logs>
[17307.419805] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=35628 SEQ=86
[17308.420206] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=35628 SEQ=87
[17309.420410] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=35628 SEQ=88
tim@ferrari:~$ show log firewall name LAN-IN rule 500
tim@ferrari:~$ show log firewall name LAN-IN
tim@ferrari:~$

Then I've done

sudo systemctl restart rsyslog

And now:

tim@ferrari:~$ show log firewall name LAN-IN rule 500
Apr 15 13:48:08 ferrari kernel: [17008.910748] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=64297 SEQ=0
Apr 15 13:48:08 ferrari kernel: [17009.925573] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=64297 SEQ=1
Apr 15 13:48:08 ferrari kernel: [17012.263513] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=20266 SEQ=0
Apr 15 13:48:08 ferrari kernel: [17013.264533] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=20266 SEQ=1
Apr 15 13:48:08 ferrari kernel: [17014.264657] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=20266 SEQ=2

However the restart trick only seems to work once, additional logs being written to dmesg aren't being logged to the firewall log, even if I restart syslog

Hi @tjh

Thanks for confirming this.

I have also seeing this behavior.

Logs are just buffered somewhere. Everytime you restart syslog they appears and then again start buffering.

And for me the strange thing is this only appears in a physical box. If I run the same image in a vm everything just works fine.

Can you confirm this that for you it is also happening in physical box not in a vm?

Regards

jjakob added a subscriber: jjakob.Apr 24 2020, 12:20 PM

Do they appear in the journal? sudo journalctl -f
I think logs go to systemd-journald first, then are forwarded to rsyslog,
which logs them to files. I've said some time ago, ever since 1.2 moved
to Buster and journald came in, that we should move more to native
journald logging away from rsyslog. I enable persistent journal storage
in /etc/systemd/journald.conf after every upgrade just because of this,
the rsyslog config is buggy/broken, it doesn't log half of what it
should, it stays in journald, so I just use journalctl to look at all
logs. I don't know if journald supports logging to separate files like
rsyslog though, by default it uses its own binary format, I think that
can be changed and maybe rsyslog file behavior moved to journald.

tjh added a comment.EditedApr 24 2020, 8:52 PM

@jjakob No, it's not logged in the journal either:

Note test ping sent with FW rule and logging applied appears in dmesg:

[Sat Apr 25 00:00:07 2020] Process accounting resumed
[Sat Apr 25 08:48:13 2020] [LAN-IN-500-D] IN=eth1 OUT=pppoe0 MAC=de:dd:38:7c:da:e9:78:11:dc:70:b9:4d:08:00 SRC=192.168.0.11 DST=139.130.4.5 LEN=84 TOS=0x00 PREC=0x00 TTL=63 ID=0 DF PROTO=ICMP TYPE=8 CODE=0 ID=19726 SEQ=0

But does not appear in journal:

Apr 25 08:47:13 ferrari sudo[32339]: tim : TTY=pts/1 ; PWD=/home/tim ; USER=root ; COMMAND=/bin/dmesg
Apr 25 08:47:13 ferrari sudo[32339]: pam_unix(sudo:session): session opened for user root by tim(uid=0)
Apr 25 08:47:13 ferrari sudo[32339]: pam_unix(sudo:session): session closed for user root
Apr 25 08:47:21 ferrari newgrp[32397]: user 'tim' (login 'tim' on pts/1) switched to group 'vyattacfg'
Apr 25 08:48:13 ferrari newgrp[32397]: user 'tim' (login 'tim' on pts/1) returned to group 'users'
Apr 25 08:48:14 ferrari sudo[32542]: tim : TTY=pts/1 ; PWD=/home/tim ; USER=root ; COMMAND=/bin/dmesg
Apr 25 08:48:14 ferrari sudo[32542]: pam_unix(sudo:session): session opened for user root by tim(uid=0)
Apr 25 08:48:14 ferrari sudo[32542]: pam_unix(sudo:session): session closed for user root
Apr 25 08:48:18 ferrari sudo[32544]: tim : TTY=pts/1 ; PWD=/home/tim ; USER=root ; COMMAND=/bin/dmesg
Apr 25 08:48:18 ferrari sudo[32544]: pam_unix(sudo:session): session opened for user root by tim(uid=0)
Apr 25 08:48:18 ferrari sudo[32544]: pam_unix(sudo:session): session closed for user root
Apr 25 08:48:40 ferrari sudo[32562]: tim : TTY=pts/1 ; PWD=/home/tim ; USER=root ; COMMAND=/bin/journalctl -f
Apr 25 08:48:40 ferrari sudo[32562]: pam_unix(sudo:session): session opened for user root by tim(uid=0)
Apr 25 08:48:44 ferrari sudo[32562]: pam_unix(sudo:session): session closed for user root
Apr 25 08:49:21 ferrari sudo[32581]: tim : TTY=pts/1 ; PWD=/home/tim ; USER=root ; COMMAND=/bin/dmesg -T
Apr 25 08:49:21 ferrari sudo[32581]: pam_unix(sudo:session): session opened for user root by tim(uid=0)
Apr 25 08:49:21 ferrari sudo[32581]: pam_unix(sudo:session): session closed for user root
Apr 25 08:49:50 ferrari sudo[32583]: tim : TTY=pts/1 ; PWD=/home/tim ; USER=root ; COMMAND=/bin/journalctl -f
Apr 25 08:49:50 ferrari sudo[32583]: pam_unix(sudo:session): session opened for user root by tim(uid=0)
Apr 25 08:50:00 ferrari sudo[32583]: pam_unix(sudo:session): session closed for user root
Apr 25 08:50:03 ferrari sudo[32585]: tim : TTY=pts/1 ; PWD=/home/tim ; USER=root ; COMMAND=/bin/journalctl
Apr 25 08:50:03 ferrari sudo[32585]: pam_unix(sudo:session): session opened for user root by tim(uid=0)

@sajiby3k Nice idea re: Virtualised, but my Vyos is in KVM:

tim@ferrari:~$ show version
Version:          VyOS 1.2.5
Built by:         Sentrium S.L.
Built on:         Sun 12 Apr 2020 15:18 UTC
Build UUID:       1695c660-d785-4b16-a54b-66d6a02ea24f
Build Commit ID:  48cc9fc46569e6

Architecture:     x86_64
Boot via:         installed image
System type:      KVM guest

Hardware vendor:  QEMU
Hardware model:   Standard PC (i440FX + PIIX, 1996)
Hardware S/N:
Hardware UUID:    c5e52633-5bc7-4002-afa2-2b5ec2ec5766

Copyright:        VyOS maintainers and contributors

I am happy to provide remote access to my Vyos instance to the Vyos devs if you feel testing on a live box would help - This box is just my home Internet router.

My syslog config:

tim@ferrari:~$ conf
show[edit]
tim@ferrari# show system syslog
 global {
     facility all {
         level info
     }
     facility protocols {
         level debug
     }
 }
 host 192.168.0.252 {
     facility all {
         level debug
         protocol udp
     }
 }
[edit]
jair added a subscriber: jair.May 6 2020, 2:46 AM

Just wanted to add an update on this, as of today May-6-2020

Seems like the bug is still present, per @kroy < Thanks a lot for pointing me to the bug number.

As soon as I ran the command sudo systemctl restart rsyslog

I was able to see the log details, but if I try to check for new logs, I will need to run the command again to refresh or like another member said above, I will have to check dmesg messages.

$ show version

Version:          VyOS 1.2.5
Built by:         Sentrium S.L.
Built on:         Sun 12 Apr 2020 15:18 UTC
Build UUID:       1695c660-d785-4b16-a54b-66d6a02ea24f
Build Commit ID:  48cc9fc46569e6

Architecture:     x86_64
Boot via:         installed image
System type:      KVM guest

Hardware vendor:  QEMU
Hardware model:   Standard PC (i440FX + PIIX, 1996)
Hardware S/N:     
Hardware UUID:    41499136-d501-4949-bd96-ac3cfc1fa2ae

Copyright:        VyOS maintainers and contributors

Sincerely,

Codec added a subscriber: Codec.May 25 2020, 1:23 PM
lloydz added a subscriber: lloydz.Jun 12 2020, 5:10 PM
lloydz added a comment.EditedJun 13 2020, 3:41 PM

Just adding that I too am experiencing this same issue with 1.2.5 while sending firewall logs to a remote syslog server. Running the command

sudo systemctl restart rsyslog

will show firewall logging for a few seconds before it stops completely. Issuing the command again will result in the same thing - logs for a few seconds and then stop. It appears that logging outside of the firewall still functions as expected as regular console log entries are still being sent.

We are running in a VMware vSphere 6.7 environment. I've reverted back to 1.2.4 for the time being.

tjh added a comment.Jun 17 2020, 4:15 AM

Hmmm is it the fact I have a remote syslog configured that triggers this bug?
I didn't realise that, I'll have to remove it and see if it helps.
It's very frustrating not having the firewall logs available to view.

It looks like this bug is in the kernel.
1.2.5 - 4.19.106-amd64

I created iso (for crux) with kernel version - 4.19.114-amd64 and the firewall remote log works fine.

vyos@my-crux:~$ show version 
Version:          VyOS 1.2.5.my
Release Train:    crux

Built by:         sever
Built on:         Wed 24 Jun 2020 13:50 UTC
Build UUID:       b1633e79-9f67-4147-a1be-576650b94914
Build Commit ID:  e2ec2c5dfb2861

Architecture:     x86_64
Boot via:         installed image
System type:      KVM guest

Hardware vendor:  QEMU
Hardware model:   Standard PC (Q35 + ICH9, 2009)
Hardware S/N:     
Hardware UUID:    5b48a5b7-2fec-4b3f-a3ba-cfa5a2669da4

Copyright:        VyOS maintainers and contributors

Tested configuration:

vyos@my-crux:~$ show conf com | match "syslog|firew"
set firewall all-ping 'enable'
set firewall broadcast-ping 'disable'
set firewall config-trap 'disable'
set firewall ipv6-receive-redirects 'disable'
set firewall ipv6-src-route 'disable'
set firewall ip-src-route 'disable'
set firewall log-martians 'enable'
set firewall name LOCAL-IN default-action 'accept'
set firewall name LOCAL-IN enable-default-log
set firewall name LOCAL-IN rule 10 action 'accept'
set firewall name LOCAL-IN rule 10 destination port '22'
set firewall name LOCAL-IN rule 10 protocol 'tcp'
set firewall name LOCAL-IN rule 10 source address '192.168.122.0/24'
set firewall name LOCAL-IN rule 20 action 'accept'
set firewall name LOCAL-IN rule 20 protocol 'icmp'
set firewall name LOCAL-IN rule 20 source address '1.1.1.1'
set firewall name LOCAL-IN rule 30 action 'drop'
set firewall name LOCAL-IN rule 30 log 'enable'
set firewall name LOCAL-IN rule 30 protocol 'icmp'
set firewall name LOCAL-IN rule 30 source address '8.8.8.8'
set firewall receive-redirects 'disable'
set firewall send-redirects 'enable'
set firewall source-validation 'disable'
set firewall syn-cookies 'enable'
set firewall twa-hazards-protection 'disable'
set interfaces ethernet eth0 firewall local name 'LOCAL-IN'
set system syslog global facility all level 'info'
set system syslog global facility protocols level 'debug'
set system syslog global preserve-fqdn
set system syslog host 192.168.122.1 facility all level 'all'
set system syslog host 192.168.122.1 facility all protocol 'udp'

Logs from the remote log server:

Jun 24 17:49:05 my-crux kernel: [  996.589617] [LOCAL-IN-30-D] IN=eth0 OUT= MAC=52:54:00:64:33:ea:52:54:00:52:8b:fd:08:00 SRC=8.8.8.8 DST=192.168.122.11 LEN= 
Jun 24 17:49:06 my-crux kernel: [  997.617255] [LOCAL-IN-30-D] IN=eth0 OUT= MAC=52:54:00:64:33:ea:52:54:00:52:8b:fd:08:00 SRC=8.8.8.8 DST=192.168.122.11 LEN= 
Jun 24 17:49:07 my-crux kernel: [  998.641222] [LOCAL-IN-30-D] IN=eth0 OUT= MAC=52:54:00:64:33:ea:52:54:00:52:8b:fd:08:00 SRC=8.8.8.8 DST=192.168.122.11 LEN= 
Jun 24 17:49:08 my-crux kernel: [  999.665399] [LOCAL-IN-30-D] IN=eth0 OUT= MAC=52:54:00:64:33:ea:52:54:00:52:8b:fd:08:00 SRC=8.8.8.8 DST=192.168.122.11 LEN= 
Jun 24 17:49:09 my-crux kernel: [ 1000.689109] [LOCAL-IN-30-D] IN=eth0 OUT= MAC=52:54:00:64:33:ea:52:54:00:52:8b:fd:08:00 SRC=8.8.8.8 DST=192.168.122.11 LEN= 
Jun 24 17:49:10 my-crux kernel: [ 1001.713388] [LOCAL-IN-30-D] IN=eth0 OUT= MAC=52:54:00:64:33:ea:52:54:00:52:8b:fd:08:00 SRC=8.8.8.8 DST=192.168.122.11 LEN= 
Jun 24 17:49:11 my-crux kernel: [ 1002.737682] [LOCAL-IN-30-D] IN=eth0 OUT= MAC=52:54:00:64:33:ea:52:54:00:52:8b:fd:08:00 SRC=8.8.8.8 DST=192.168.122.11 LEN=
c-po claimed this task.Jun 24 2020, 3:07 PM
c-po edited projects, added VyOS 1.2 Crux (VyOS 1.2.6); removed VyOS 1.2 Crux.
c-po moved this task from Need Triage to Finished on the VyOS 1.3 Equuleus board.
c-po added a subscriber: hagbard.
c-po closed this task as Resolved.Jun 24 2020, 6:10 PM
erkin renamed this task from Firewall logging not working to syslog doesn't start automatically.Sep 9 2020, 1:01 PM