Page MenuHomeVyOS Platform

vyos-configd throws an exception during an image upgrade
Closed, ResolvedPublicBUG

Description

Dear Vyos experts,

The image version I am currently running (1.5-rolling-202407280023)has always worked perfectly.
However, when I tried to upgrade to the new images( 1.5-rolling-202410180006 ), I encountered an exception that caused the upgrade to fail. Here is the error I encountered:

Oct 23 17:09:52 vyos vyos-configd[692]: Sending reply: 1
Oct 23 17:09:52 vyos vyos-configd[692]: Received request: msg_size
Oct 23 17:09:52 vyos vyos-configd[692]: Sending reply: 0
Oct 23 17:09:52 vyos sudo[2331]: pam_unix(sudo:session): session closed for user root
Oct 23 17:09:52 vyos sudo[2358]:     root : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh -c '/usr/sbin/vyshim VYOS_TAGNODE_VALUE=\'lo\' /usr/libexec/vyos/conf_mode/interfaces_loopback.py'
Oct 23 17:09:52 vyos sudo[2358]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Oct 23 17:09:52 vyos vyos-configd[692]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=lo/usr/libexec/vyos/conf_mode/interfaces_loopback.py"}
Oct 23 17:09:53 vyos vyos-configd[692]: Sending reply: 1
Oct 23 17:09:53 vyos vyos-configd[692]: Received request: msg_size
Oct 23 17:09:53 vyos vyos-configd[692]: Sending reply: 0
Oct 23 17:09:53 vyos sudo[2358]: pam_unix(sudo:session): session closed for user root
Oct 23 17:09:53 vyos sudo[2397]:     root : PWD=/ ; USER=root ; COMMAND=/usr/bin/sh -c '/usr/sbin/vyshim VYOS_TAGNODE_VALUE=\'br0\' /usr/libexec/vyos/conf_mode/interfaces_bridge.py'
Oct 23 17:09:53 vyos sudo[2397]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Oct 23 17:09:53 vyos vyos-configd[692]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=br0/usr/libexec/vyos/conf_mode/interfaces_bridge.py"}
Oct 23 17:09:53 vyos zebra[1646]: [H5BRT-63K8T] Cannot find bridge-vlan IF (7) for vlan update
Oct 23 17:09:53 vyos (udev-worker)[2241]: Network interface NamePolicy= disabled on kernel command line.
Oct 23 17:09:53 vyos kernel: br0: port 1(eth0) entered blocking state
Oct 23 17:09:53 vyos kernel: br0: port 1(eth0) entered disabled state
Oct 23 17:09:53 vyos kernel: igc 0000:01:00.0 eth0: entered allmulticast mode
Oct 23 17:09:53 vyos kernel: igc 0000:01:00.0 eth0: entered promiscuous mode
Oct 23 17:09:53 vyos kernel: br0: port 2(eth1) entered blocking state
Oct 23 17:09:53 vyos kernel: br0: port 2(eth1) entered disabled state
Oct 23 17:09:53 vyos kernel: igc 0000:02:00.0 eth1: entered allmulticast mode
Oct 23 17:09:53 vyos kernel: igc 0000:02:00.0 eth1: entered promiscuous mode
Oct 23 17:09:53 vyos netplugd[1246]: br0: state DOWN flags 0x00001002 BROADCAST,MULTICAST -> 0x00001003 UP,BROADCAST,MULTICAST
Oct 23 17:09:53 vyos vyos-configd[692]: Sending reply: 1
Oct 23 17:09:53 vyos vyos-configd[692]: Received request: msg_size
Oct 23 17:09:53 vyos vyos-configd[692]: Sending reply: 0
Oct 23 17:09:53 vyos vyos-configd[692]: Received message: send
Oct 23 17:09:53 vyos vyos-configd[692]: VyOS had an issue completing a command.
Oct 23 17:09:53 vyos vyos-configd[692]: We are sorry that you encountered a problem while using VyOS.
Oct 23 17:09:53 vyos vyos-configd[692]: There are a few things you can do to help us (and yourself):
Oct 23 17:09:53 vyos vyos-configd[692]: - Contact us using the online help desk if you have a subscription:
Oct 23 17:09:53 vyos vyos-configd[692]:   https://support.vyos.io/
Oct 23 17:09:53 vyos vyos-configd[692]: - Make sure you are running the latest version of VyOS available at:
Oct 23 17:09:53 vyos vyos-configd[692]:   https://vyos.net/get/
Oct 23 17:09:53 vyos vyos-configd[692]: - Consult the community forum to see how to handle this issue:
Oct 23 17:09:53 vyos vyos-configd[692]:   https://forum.vyos.io
Oct 23 17:09:53 vyos vyos-configd[692]: - Join us on Slack where our users exchange help and advice:
Oct 23 17:09:53 vyos vyos-configd[692]:   https://vyos.slack.com
Oct 23 17:09:53 vyos vyos-configd[692]: When reporting problems, please include as much information as possible:
Oct 23 17:09:53 vyos vyos-configd[692]: - do not obfuscate any data (feel free to contact us privately if your
Oct 23 17:09:53 vyos vyos-configd[692]:   business policy requires it)
Oct 23 17:09:53 vyos vyos-configd[692]: - and include all the information presented below
Oct 23 17:09:53 vyos vyos-configd[692]: Report time:      2024-10-23 09:09:53
Oct 23 17:09:53 vyos vyos-configd[692]: Image version:    VyOS 1.5-rolling-202410180006
Oct 23 17:09:53 vyos vyos-configd[692]: Release train:    current
Oct 23 17:09:53 vyos vyos-configd[692]: Built by:         [email protected]
Oct 23 17:09:53 vyos vyos-configd[692]: Built on:         Fri 18 Oct 2024 00:07 UTC
Oct 23 17:09:53 vyos vyos-configd[692]: Build UUID:       a6dc3e7c-619f-4051-937a-93b4adac485f
Oct 23 17:09:53 vyos vyos-configd[692]: Build commit ID:  2359180068a653
Oct 23 17:09:53 vyos vyos-configd[692]: Architecture:     x86_64
Oct 23 17:09:53 vyos vyos-configd[692]: Boot via:         installed image
Oct 23 17:09:53 vyos vyos-configd[692]: System type:      bare metal
Oct 23 17:09:53 vyos vyos-configd[692]: Hardware vendor:  CncTion
Oct 23 17:09:53 vyos vyos-configd[692]: Hardware model:   N4100-4L
Oct 23 17:09:53 vyos vyos-configd[692]: Hardware S/N:     Default string
Oct 23 17:09:53 vyos vyos-configd[692]: Hardware UUID:    03000200-0400-0500-0006-000700080009
Oct 23 17:09:53 vyos vyos-configd[692]: Traceback (most recent call last):
Oct 23 17:09:53 vyos vyos-configd[692]:   File "/usr/libexec/vyos/services/vyos-configd", line 326, in <module>
Oct 23 17:09:53 vyos vyos-configd[692]:     message = json.loads(msg)
Oct 23 17:09:53 vyos vyos-configd[692]:               ^^^^^^^^^^^^^^^
Oct 23 17:09:53 vyos vyos-configd[692]:   File "/usr/lib/python3.11/json/__init__.py", line 346, in loads
Oct 23 17:09:53 vyos vyos-configd[692]:     return _default_decoder.decode(s)
Oct 23 17:09:53 vyos vyos-configd[692]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^
Oct 23 17:09:53 vyos vyos-configd[692]:   File "/usr/lib/python3.11/json/decoder.py", line 337, in decode
Oct 23 17:09:53 vyos vyos-configd[692]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Oct 23 17:09:53 vyos vyos-configd[692]:                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Oct 23 17:09:53 vyos vyos-configd[692]:   File "/usr/lib/python3.11/json/decoder.py", line 355, in raw_decode
Oct 23 17:09:53 vyos vyos-configd[692]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Oct 23 17:09:53 vyos vyos-configd[692]: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Oct 23 17:09:53 vyos vyos-configd[692]: noteworthy:
Oct 23 17:09:53 vyos vyos-configd[692]: cmd 'nft --check delete element inet vrf_zones ct_iface_map { "lo" }'
Oct 23 17:09:53 vyos vyos-configd[692]: returned (out):
Oct 23 17:09:53 vyos vyos-configd[692]: returned (err):
Oct 23 17:09:53 vyos vyos-configd[692]: Error: Could not process rule: No such file or directory
Oct 23 17:09:53 vyos vyos-configd[692]: delete element inet vrf_zones ct_iface_map { lo }
Oct 23 17:09:53 vyos vyos-configd[692]:                                              ^^
Oct 23 17:09:53 vyos vyos-configd[692]: cmd 'ip link show dev br0'
Oct 23 17:09:53 vyos vyos-configd[692]: returned (out):
Oct 23 17:09:53 vyos vyos-configd[692]: returned (err):
Oct 23 17:09:53 vyos vyos-configd[692]: Device "br0" does not exist.
Oct 23 17:09:53 vyos vyos-configd[692]: cmd 'ip link show dev br0'
Oct 23 17:09:53 vyos vyos-configd[692]: returned (out):
Oct 23 17:09:53 vyos vyos-configd[692]: returned (err):
Oct 23 17:09:53 vyos vyos-configd[692]: Device "br0" does not exist.
Oct 23 17:09:53 vyos vyos-configd[692]: cmd 'nft --check delete element inet vrf_zones ct_iface_map { "br0" }'
Oct 23 17:09:53 vyos vyos-configd[692]: returned (out):
Oct 23 17:09:53 vyos vyos-configd[692]: returned (err):
Oct 23 17:09:53 vyos vyos-configd[692]: Error: Could not process rule: No such file or directory
Oct 23 17:09:53 vyos vyos-configd[692]: delete element inet vrf_zones ct_iface_map { br0 }
Oct 23 17:09:53 vyos vyos-configd[692]:                                              ^^^
Oct 23 17:09:53 vyos python3[692]: Report time:      2024-10-23 09:09:53
Oct 23 17:09:53 vyos python3[692]: Image version:    VyOS 1.5-rolling-202410180006
Oct 23 17:09:53 vyos python3[692]: Release train:    current
Oct 23 17:09:53 vyos python3[692]: Built by:         [email protected]
Oct 23 17:09:53 vyos python3[692]: Built on:         Fri 18 Oct 2024 00:07 UTC
Oct 23 17:09:53 vyos python3[692]: Build UUID:       a6dc3e7c-619f-4051-937a-93b4adac485f
Oct 23 17:09:53 vyos python3[692]: Build commit ID:  2359180068a653
Oct 23 17:09:53 vyos Architecture[692]:     x86_64
Oct 23 17:09:53 vyos python3[692]: Boot via:         installed image
Oct 23 17:09:53 vyos python3[692]: System type:      bare metal
Oct 23 17:09:53 vyos python3[692]: Hardware vendor:  CncTion
Oct 23 17:09:53 vyos python3[692]: Hardware model:   N4100-4L
Oct 23 17:09:53 vyos python3[692]: Hardware S/N:     Default string
Oct 23 17:09:53 vyos python3[692]: Hardware UUID:    03000200-0400-0500-0006-000700080009
Oct 23 17:09:53 vyos python3[692]: Traceback (most recent call last):
Oct 23 17:09:53 vyos python3[692]:   File "/usr/libexec/vyos/services/vyos-configd", line 326, in <module>
Oct 23 17:09:53 vyos python3[692]:     message = json.loads(msg)
Oct 23 17:09:53 vyos python3[692]:               ^^^^^^^^^^^^^^^
Oct 23 17:09:53 vyos python3[692]:   File "/usr/lib/python3.11/json/__init__.py", line 346, in loads
Oct 23 17:09:53 vyos python3[692]:     return _default_decoder.decode(s)
Oct 23 17:09:53 vyos python3[692]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^
Oct 23 17:09:53 vyos python3[692]:   File "/usr/lib/python3.11/json/decoder.py", line 337, in decode
Oct 23 17:09:53 vyos python3[692]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Oct 23 17:09:53 vyos python3[692]:                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Oct 23 17:09:53 vyos python3[692]:   File "/usr/lib/python3.11/json/decoder.py", line 355, in raw_decode
Oct 23 17:09:53 vyos python3[692]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Oct 23 17:09:53 vyos json.decoder.JSONDecodeError[692]: Expecting value: line 1 column 1 (char 0)
Oct 23 17:09:53 vyos noteworthy[692]: 
Oct 23 17:09:53 vyos python3[692]: cmd 'nft --check delete element inet vrf_zones ct_iface_map { "lo" }'
Oct 23 17:09:53 vyos python3[692]: returned (out):
Oct 23 17:09:53 vyos python3[692]: returned (err):
Oct 23 17:09:53 vyos Error[692]: Could not process rule: No such file or directory
Oct 23 17:09:53 vyos python3[692]: delete element inet vrf_zones ct_iface_map { lo }
Oct 23 17:09:53 vyos python3[692]:                                              ^^
Oct 23 17:09:53 vyos python3[692]: cmd 'ip link show dev br0'
Oct 23 17:09:53 vyos python3[692]: returned (out):
Oct 23 17:09:53 vyos python3[692]: returned (err):
Oct 23 17:09:53 vyos python3[692]: Device "br0" does not exist.
Oct 23 17:09:53 vyos python3[692]: cmd 'ip link show dev br0'
Oct 23 17:09:53 vyos python3[692]: returned (out):
Oct 23 17:09:53 vyos python3[692]: returned (err):
Oct 23 17:09:53 vyos python3[692]: Device "br0" does not exist.
Oct 23 17:09:53 vyos python3[692]: cmd 'nft --check delete element inet vrf_zones ct_iface_map { "br0" }'
Oct 23 17:09:53 vyos python3[692]: returned (out):
Oct 23 17:09:53 vyos python3[692]: returned (err):
Oct 23 17:09:53 vyos Error[692]: Could not process rule: No such file or directory
Oct 23 17:09:53 vyos python3[692]: delete element inet vrf_zones ct_iface_map { br0 }
Oct 23 17:09:53 vyos python3[692]:                                              ^^^
Oct 23 17:09:53 vyos systemd[1]: vyos-configd.service: Main process exited, code=exited, status=1/FAILURE
Oct 23 17:09:53 vyos systemd[1]: vyos-configd.service: Failed with result 'exit-code'.
Oct 23 17:09:53 vyos systemd[1]: vyos-configd.service: Consumed 8.208s CPU time.
Oct 23 17:09:54 vyos systemd[1]: vyos-configd.service: Scheduled restart job, restart counter is at 1.
Oct 23 17:09:54 vyos systemd[1]: Stopped vyos-configd.service - VyOS configuration daemon.
Oct 23 17:09:54 vyos systemd[1]: vyos-configd.service: Consumed 8.208s CPU time.
Oct 23 17:09:54 vyos systemd[1]: Started vyos-configd.service - VyOS configuration daemon.

and my interface configurations :

set interfaces bridge br0 address 'xxx.xxx.1.254/32'
set interfaces bridge br0 description 'WAN bridge'
set interfaces bridge br0 member interface eth0
set interfaces bridge br0 member interface eth1
set interfaces bridge br0 stp
set interfaces bridge br1 address 'xxx.xxx.0.1/24'
set interfaces bridge br1 address 'xxx.xxx.0.254/32'
set interfaces bridge br1 description 'LAN bridge'
set interfaces bridge br1 member interface eth2
set interfaces bridge br1 member interface eth3
set interfaces bridge br1 stp
set interfaces ethernet eth0 hw-id 'xx:xx:xx:xx:xx:6a'
set interfaces ethernet eth0 offload gro
set interfaces ethernet eth0 offload gso
set interfaces ethernet eth0 offload hw-tc-offload
set interfaces ethernet eth0 offload rfs
set interfaces ethernet eth0 offload rps
set interfaces ethernet eth0 offload sg
set interfaces ethernet eth0 offload tso
set interfaces ethernet eth0 ring-buffer rx '4096'
set interfaces ethernet eth0 ring-buffer tx '4096'
set interfaces ethernet eth1 hw-id 'xx:xx:xx:xx:xx:6b'
set interfaces ethernet eth1 offload gro
set interfaces ethernet eth1 offload gso
set interfaces ethernet eth1 offload hw-tc-offload
set interfaces ethernet eth1 offload rfs
set interfaces ethernet eth1 offload rps
set interfaces ethernet eth1 offload sg
set interfaces ethernet eth1 offload tso
set interfaces ethernet eth1 ring-buffer rx '4096'
set interfaces ethernet eth1 ring-buffer tx '4096'
set interfaces ethernet eth2 hw-id 'xx:xx:xx:xx:xx:6c'
set interfaces ethernet eth2 offload gro
set interfaces ethernet eth2 offload gso
set interfaces ethernet eth2 offload hw-tc-offload
set interfaces ethernet eth2 offload rfs
set interfaces ethernet eth2 offload rps
set interfaces ethernet eth2 offload sg
set interfaces ethernet eth2 offload tso
set interfaces ethernet eth2 ring-buffer rx '4096'
set interfaces ethernet eth2 ring-buffer tx '4096'
set interfaces ethernet eth3 hw-id 'xx:xx:xx:xx:xx:6d'
set interfaces ethernet eth3 offload gro
set interfaces ethernet eth3 offload gso
set interfaces ethernet eth3 offload hw-tc-offload
set interfaces ethernet eth3 offload rfs
set interfaces ethernet eth3 offload rps
set interfaces ethernet eth3 offload sg
set interfaces ethernet eth3 offload tso
set interfaces ethernet eth3 ring-buffer rx '4096'
set interfaces ethernet eth3 ring-buffer tx '4096'
set interfaces loopback lo
set interfaces pppoe pppoe0 authentication password xxxxxx
set interfaces pppoe pppoe0 authentication username xxxxxx
set interfaces pppoe pppoe0 dhcpv6-options pd 0 interface br1 address '1'
set interfaces pppoe pppoe0 dhcpv6-options pd 0 interface br1 sla-id '0'
set interfaces pppoe pppoe0 dhcpv6-options pd 0 length '60'
set interfaces pppoe pppoe0 ip adjust-mss 'clamp-mss-to-pmtu'
set interfaces pppoe pppoe0 ipv6 address autoconf
set interfaces pppoe pppoe0 ipv6 adjust-mss 'clamp-mss-to-pmtu'
set interfaces pppoe pppoe0 mtu '1480'
set interfaces pppoe pppoe0 source-interface 'br0'
set interfaces wireguard wg0 address 'xxx.xxx.0.1/24'
set interfaces wireguard wg0 description 'OSPF over WG HK Peer'
set interfaces wireguard wg0 ip adjust-mss 'clamp-mss-to-pmtu'
set interfaces wireguard wg0 peer to_HK address 'xxx.xxx.0.254'
set interfaces wireguard wg0 peer to_HK allowed-ips 'xxx.xxx.0.0/0'
set interfaces wireguard wg0 peer to_HK allowed-ips 'xxx.xxx.0.0/24'
set interfaces wireguard wg0 peer to_HK persistent-keepalive '5'
set interfaces wireguard wg0 peer to_HK port '5000'
set interfaces wireguard wg0 peer to_HK public-key 'xxxxx'
set interfaces wireguard wg0 private-key xxxxx

The above error caused both my WAN and LAN interfaces to not be up and running. I lost access to the router. I have successfully upgraded my configuration many times before. Please help me identify the reason. Thank you.

Details

Version
1.5-rolling-202410180006
Is it a breaking change?
Unspecified (possibly destroys the router)
Issue type
Bug (incorrect behavior)

Event Timeline

Viacheslav triaged this task as Normal priority.Oct 24 2024, 7:08 AM
jestabro raised the priority of this task from Normal to High.Nov 15 2024, 7:49 PM

The PR for the parent task:
https://vyos.dev/T6899
will avoid obscuring underlying errors. Revisit after merge of above.

It's not just on upgrade; I'm seeing the same problem in a fresh installation of VyOS 1.5-rolling-202411190007:

$ sudo journalctl -b -1 | grep -Ei "vyos-config|getty"
[...]
Nov 18 23:37:06 vyos vyos-configd[858]: Report time:      2024-11-18 23:37:06
Nov 18 23:37:06 vyos vyos-configd[858]: Image version:    VyOS 1.5-rolling-202411190007
Nov 18 23:37:06 vyos vyos-configd[858]: Release train:    current
Nov 18 23:37:06 vyos vyos-configd[858]: Built by:         [email protected]
Nov 18 23:37:06 vyos vyos-configd[858]: Built on:         Tue 19 Nov 2024 00:07 UTC
Nov 18 23:37:06 vyos vyos-configd[858]: Build UUID:       f05e0566-3146-4d70-98ee-28a588b76b67
Nov 18 23:37:06 vyos vyos-configd[858]: Build commit ID:  1e038ab2024ac4
Nov 18 23:37:06 vyos vyos-configd[858]: Architecture:     x86_64
Nov 18 23:37:06 vyos vyos-configd[858]: Boot via:         installed image
Nov 18 23:37:06 vyos vyos-configd[858]: System type:      bare metal
Nov 18 23:37:06 vyos vyos-configd[858]: Hardware vendor:  Default string
Nov 18 23:37:06 vyos vyos-configd[858]: Hardware model:   QDNV01
Nov 18 23:37:06 vyos vyos-configd[858]: Hardware S/N:     Default string
Nov 18 23:37:06 vyos vyos-configd[858]: Hardware UUID:    03000200-0400-0500-0006-000700080009
Nov 18 23:37:06 vyos vyos-configd[858]: Traceback (most recent call last):
Nov 18 23:37:06 vyos vyos-configd[858]:   File "/usr/libexec/vyos/services/vyos-configd", line 326, in <module>
Nov 18 23:37:06 vyos vyos-configd[858]:     message = json.loads(msg)
Nov 18 23:37:06 vyos vyos-configd[858]:               ^^^^^^^^^^^^^^^
Nov 18 23:37:06 vyos vyos-configd[858]:   File "/usr/lib/python3.11/json/__init__.py", line 346, in loads
Nov 18 23:37:06 vyos vyos-configd[858]:     return _default_decoder.decode(s)
Nov 18 23:37:06 vyos vyos-configd[858]:            ^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 18 23:37:06 vyos vyos-configd[858]:   File "/usr/lib/python3.11/json/decoder.py", line 337, in decode
Nov 18 23:37:06 vyos vyos-configd[858]:     obj, end = self.raw_decode(s, idx=_w(s, 0).end())
Nov 18 23:37:06 vyos vyos-configd[858]:                ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
Nov 18 23:37:06 vyos vyos-configd[858]:   File "/usr/lib/python3.11/json/decoder.py", line 355, in raw_decode
Nov 18 23:37:06 vyos vyos-configd[858]:     raise JSONDecodeError("Expecting value", s, err.value) from None
Nov 18 23:37:06 vyos vyos-configd[858]: json.decoder.JSONDecodeError: Expecting value: line 1 column 1 (char 0)
Nov 18 23:37:06 vyos vyos-configd[858]: noteworthy:
Nov 18 23:37:06 vyos vyos-configd[858]: cmd 'utmpdump /run/utmp'
Nov 18 23:37:06 vyos vyos-configd[858]: returned (out):
Nov 18 23:37:06 vyos vyos-configd[858]: [2] [00000] [~~  ] [reboot  ] [~           ] [6.6.61-vyos         ] [0.0.0.0        ] [2024-11-18T23:36:43,313264+00:00]
Nov 18 23:37:06 vyos vyos-configd[858]: [5] [01144] [tty1] [        ] [tty1        ] [                    ] [0.0.0.0        ] [2024-11-18T23:36:50,741945+00:00]
Nov 18 23:37:06 vyos vyos-configd[858]: [8] [01155] [tyS0] [        ] [ttyS0       ] [                    ] [0.0.0.0        ] [1970-01-01T00:00:00,000000+00:00]
Nov 18 23:37:06 vyos vyos-configd[858]: [1] [00051] [~~  ] [runlevel] [~           ] [6.6.61-vyos         ] [0.0.0.0        ] [2024-11-18T23:36:50,809515+00:00]
Nov 18 23:37:06 vyos vyos-configd[858]: returned (err):
Nov 18 23:37:06 vyos vyos-configd[858]: Utmp dump of /run/utmp
Nov 18 23:37:06 vyos vyos-configd[858]: cmd 'nft --check delete element inet vrf_zones ct_iface_map { "lo" }'
Nov 18 23:37:06 vyos vyos-configd[858]: returned (out):
Nov 18 23:37:06 vyos vyos-configd[858]: returned (err):
Nov 18 23:37:06 vyos vyos-configd[858]: Error: Could not process rule: No such file or directory
Nov 18 23:37:06 vyos vyos-configd[858]: delete element inet vrf_zones ct_iface_map { lo }
Nov 18 23:37:06 vyos vyos-configd[858]:                                              ^^
Nov 18 23:37:06 vyos vyos-configd[858]: cmd 'nft --check delete element inet vrf_zones ct_iface_map { "eth2" }'
Nov 18 23:37:06 vyos vyos-configd[858]: returned (out):
Nov 18 23:37:06 vyos vyos-configd[858]: returned (err):
Nov 18 23:37:06 vyos vyos-configd[858]: Error: Could not process rule: No such file or directory
Nov 18 23:37:06 vyos vyos-configd[858]: delete element inet vrf_zones ct_iface_map { eth2 }
Nov 18 23:37:06 vyos vyos-configd[858]:                                              ^^^^
Nov 18 23:37:06 vyos python3[858]:   File "/usr/libexec/vyos/services/vyos-configd", line 326, in <module>
Nov 18 23:37:07 vyos systemd[1]: vyos-configd.service: Main process exited, code=exited, status=1/FAILURE
Nov 18 23:37:07 vyos systemd[1]: vyos-configd.service: Failed with result 'exit-code'.
Nov 18 23:37:07 vyos systemd[1]: vyos-configd.service: Consumed 3.322s CPU time.
Nov 18 23:37:07 vyos systemd[1]: vyos-configd.service: Scheduled restart job, restart counter is at 1.
Nov 18 23:37:07 vyos systemd[1]: Stopped vyos-configd.service - VyOS configuration daemon.
Nov 18 23:37:07 vyos systemd[1]: vyos-configd.service: Consumed 3.322s CPU time.
Nov 18 23:37:07 vyos systemd[1]: Started vyos-configd.service - VyOS configuration daemon.
[...]

This results in the machine hanging at boot immediately after printing Mounting VyOS Config...done. This happens once every two or three boots, which I find a little odd.

I haven't yet dug any further into the problem. is there any more information that I can provide to be of assistance?

Thanks @gadams , and yes that was also mentioned in the forum discussion here:
https://forum.vyos.io/t/vyos-sometimes-does-not-start-properly/15486
I believe the correction made in the PR for the parent task T6899 should help reveal/resolve the issue.

T6899 merged; when rolling available, kindly retest. Thanks !

Hi @jestabro ,

Thank you for your work. I tried upgrading to the latest version 1.5-rolling-202411220007. After the upgrade, I still lost access to the LAN. However, after checking the logs, it seems that the previous exception has been fixed. There are just a few logs: Sending reply: error_code 1 with output. I'm not sure if this is a bug; could you please take a look?

Nov 22 12:23:45 vyos vyos-configd[694]: Received message: {"type": "init"}
Nov 22 12:23:47 vyos vyos-configd[694]: config session pid is 1872
Nov 22 12:23:47 vyos vyos-configd[694]: config session sudo_user is root
Nov 22 12:23:48 vyos vyos-configd[694]: commit_scripts: ['system_host-name', 'system_host-name', 'system_timezone', 'policy', 'system_conntrack', 'nat', 'system_ipv6', 'system_ip', 'interfaces_loopback_lo', 'interfaces_bridge_br0', 'interfaces_bridge_br1', 'system_sysctl', 'interfaces_ethernet_eth3', 'interfaces_ethernet_eth0', 'interfaces_ethernet_eth1', 'interfaces_ethernet_eth2', 'interfaces_pppoe_pppoe0', 'interfaces_wireguard_wg0', 'system_syslog', 'system_host-name', 'system_config-management', 'system_login', 'container', 'protocols_static', 'firewall', 'protocols_ospf', 'protocols_bfd', 'protocols_bgp', 'service_router-advert', 'service_ntp', 'qos', 'service_dhcp-server', 'service_dns_forwarding', 'service_dns_dynamic', 'system_task-scheduler_download_geo_files', 'system_task-scheduler_update_mosdns_rule', 'service_ssh', 'system_option', 'system_update-check']
Nov 22 12:23:48 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_host-name.py"}
Nov 22 12:23:48 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:48 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_host-name.py"}
Nov 22 12:23:48 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:49 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_timezone.py"}
Nov 22 12:23:49 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:50 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/policy.py"}
Nov 22 12:23:53 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:53 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_conntrack.py"}
Nov 22 12:23:53 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:53 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/nat.py"}
Nov 22 12:23:53 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:54 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_ip.py"}
Nov 22 12:23:54 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:54 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_ipv6.py"}
Nov 22 12:23:55 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:55 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=lo/usr/libexec/vyos/conf_mode/interfaces_loopback.py"}
Nov 22 12:23:55 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:55 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=br0/usr/libexec/vyos/conf_mode/interfaces_bridge.py"}
Nov 22 12:23:56 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:56 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=br1/usr/libexec/vyos/conf_mode/interfaces_bridge.py"}
Nov 22 12:23:56 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:56 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=eth1/usr/libexec/vyos/conf_mode/interfaces_ethernet.py"}
Nov 22 12:23:57 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:57 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=eth0/usr/libexec/vyos/conf_mode/interfaces_ethernet.py"}
Nov 22 12:23:58 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:23:59 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=eth2/usr/libexec/vyos/conf_mode/interfaces_ethernet.py"}
Nov 22 12:24:00 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:00 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=eth3/usr/libexec/vyos/conf_mode/interfaces_ethernet.py"}
Nov 22 12:24:01 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:01 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_sysctl.py"}
Nov 22 12:24:01 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:01 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=pppoe0/usr/libexec/vyos/conf_mode/interfaces_pppoe.py"}
Nov 22 12:24:01 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:02 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=wg0/usr/libexec/vyos/conf_mode/interfaces_wireguard.py"}
Nov 22 12:24:02 vyos sudo[3415]:     root : PWD=/ ; USER=root ; COMMAND=/usr/sbin/dmidecode -t 4
Nov 22 12:24:02 vyos sudo[3415]: pam_unix(sudo:session): session opened for user root(uid=0) by (uid=0)
Nov 22 12:24:02 vyos sudo[3415]: pam_unix(sudo:session): session closed for user root
Nov 22 12:24:02 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:02 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_syslog.py"}
Nov 22 12:24:03 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:03 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_config-management.py"}
Nov 22 12:24:03 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:03 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_login.py"}
Nov 22 12:24:05 vyos useradd[3493]: new user: name=vyos, UID=1002, GID=100, home=/home/vyos, shell=/bin/vbash, from=none
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group 'adm'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group 'disk'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group 'sudo'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group 'dip'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group 'vyattacfg'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group '_kea'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group 'frrvty'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to group 'frr'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group 'adm'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group 'disk'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group 'sudo'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group 'dip'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group 'vyattacfg'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group '_kea'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group 'frrvty'
Nov 22 12:24:05 vyos useradd[3493]: add 'vyos' to shadow group 'frr'
Nov 22 12:24:08 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:08 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_host-name.py"}
Nov 22 12:24:08 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:08 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_host-name.py"}
Nov 22 12:24:08 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:08 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_host-name.py"}
Nov 22 12:24:08 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:09 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/container.py"}
Nov 22 12:24:13 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:13 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/protocols_static.py"}
Nov 22 12:24:14 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:15 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/firewall.py"}
Nov 22 12:24:16 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:16 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/protocols_ospf.py"}
Nov 22 12:24:17 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:17 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/protocols_bfd.py"}
Nov 22 12:24:18 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:18 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/protocols_bgp.py"}
Nov 22 12:24:20 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:20 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/service_router-advert.py"}
Nov 22 12:24:20 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:20 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/service_ntp.py"}
Nov 22 12:24:22 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:22 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/qos.py"}
Nov 22 12:24:22 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:23 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/service_dhcp-server.py"}
Nov 22 12:24:23 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:24 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/service_dns_forwarding.py"}
Nov 22 12:24:25 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:26 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/service_dns_dynamic.py"}
Nov 22 12:24:27 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:27 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=update_mosdns_rule/usr/libexec/vyos/conf_mode/system_task-scheduler.py"}
Nov 22 12:24:27 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:27 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "VYOS_TAGNODE_VALUE=download_geo_files/usr/libexec/vyos/conf_mode/system_task-scheduler.py"}
Nov 22 12:24:27 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:27 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/service_ssh.py"}
Nov 22 12:24:27 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:27 vyos vyos-configd[694]: Received message: {"type": "node", "last": false, "data": "/usr/libexec/vyos/conf_mode/system_option.py"}
Nov 22 12:24:39 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:39 vyos vyos-configd[694]: Received message: {"type": "node", "last": true, "data": "/usr/libexec/vyos/conf_mode/system_update-check.py"}
Nov 22 12:24:39 vyos vyos-configd[694]: Sending reply: error_code 1 with output
Nov 22 12:24:39 vyos vyos-configd[694]: scripts_called: ['system_host-name', 'system_host-name', 'system_timezone', 'policy', 'system_conntrack', 'nat', 'system_ip', 'system_ipv6', 'interfaces_loopback_lo', 'interfaces_bridge_br0', 'interfaces_bridge_br1', 'interfaces_ethernet_eth1', 'interfaces_ethernet_eth0', 'interfaces_ethernet_eth2', 'interfaces_ethernet_eth3', 'system_sysctl', 'interfaces_pppoe_pppoe0', 'interfaces_wireguard_wg0', 'system_syslog', 'system_config-management', 'system_login', 'system_host-name', 'system_host-name', 'system_host-name', 'container', 'protocols_static', 'firewall', 'protocols_ospf', 'protocols_bfd', 'protocols_bgp', 'service_router-advert', 'service_ntp', 'qos', 'service_dhcp-server', 'service_dns_forwarding', 'service_dns_dynamic', 'system_task-scheduler_update_mosdns_rule', 'system_task-scheduler_download_geo_files', 'service_ssh', 'system_option', 'system_update-check']

@opswill Yes, those debug messages report that vyos-configd is operating correctly: error_code 1 is 'success' in the enum list. Consequently, the obscuring error in vyos-configd has been resolved, and the root cause of your issue can now be investigated ...

@opswill I suggest closing this task and opening a separate task focused on the specific continuing issue.

For the record, I am seeing the same thing with the same build (but different config commands, since this is a fresh installation, and there's not much in config.boot).

I have two questions:

  1. Since this is a fresh install in my case, there likely aren't any errors in the config. What sort of errors are suspected to have caused the prior boot hangs? What should I look for in future boots?
  2. Sending reply: error_code 1 with output sure looks like an error. I thought confined was spewing lots of errors at me, one for each section of the initial config. I suggest we can improve the log messages there to make it clear that that's actually success. I'm happy to take that on as a task, if other folks agree.

@gadams I agree with 2, as becomes apparent in the current situation: it is misleading and should be changed so as to avoid confusion. If you want to take it up, that would be great; thanks. Regarding 1, if you are seeing boot hangs on a system with the above fix, we will need to investigate: I have not encountered it, so I can try to reproduce with the following information: rolling version; sanitized config; platform (vm or hardware). I suggest opening as a separate task, as the forum reports so far (unless I'm mistaken) have pointed to this one. Thanks again for the info.

To be clear, the clean-config boot hangs I was seeing were prior to this fix. Since the fix, I have yet to see the hang.

But if the hang was caused by this problem masking some other problem, then what problem could that be?

@gadams it may well have been the case that the fragile synchronization before the fix was in fact a cause of the problem, at least in some (all ?) cases. I expected however, that any other config error on boot could also trigger the complaint in vyos-configd, which would consequently drop any useful output. With the original change in T6326 and the fix in T6899, any output (error or otherwise) should now be robust and generally available (notably, through the http-api, which was the motivation to finally fix the output workaround for T6326).

Thanks to you and other reports for pointing out the issue.

Sounds reasonable! I'm not going to worry about it any more, unless I see any further symptoms. Thanks a lot for the fix and taking the time to respond here!

I'll look into improving the error message separately.

jestabro moved this task from Backlog - Bug to Completed on the VyOS Rolling board.

OMG. I just spent hours trying to diagnose why I was getting Sending reply: error_code 1 with output "error". The logging really needs to be improved.