Bug 2175665

Summary: nmstatectl service unit starts before NetworkManager dbus is ready
Product: Red Hat Enterprise Linux 9 Reporter: Quique Llorente <ellorent>
Component: nmstateAssignee: Gris Ge <fge>
Status: VERIFIED --- QA Contact: Mingyu Shi <mshi>
Severity: high Docs Contact:
Priority: unspecified    
Version: 9.2CC: ferferna, jiji, jishi, network-qe, sfaye, till
Target Milestone: rcKeywords: Triaged
Target Release: ---   
Hardware: Unspecified   
OS: Linux   
Whiteboard:
Fixed In Version: Doc Type: No Doc Update
Doc Text:
Story Points: ---
Clone Of:
: 2177188 (view as bug list) Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Quique Llorente 2023-03-06 09:32:17 UTC
Description of problem:
When using the nmstate.service the state configured at /etc/nmstate is not applied with the following error 

Mar  6 07:50:05.269335 systemd[1]: Starting nmstate.service - Apply nmstate on-disk state...
Mar  6 07:50:05.277998 systemd[1]: Finished systemd-homed-activate.service - Home Area Activation.  
Mar  6 07:50:05.278000 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-homed-activate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' 
Mar  6 07:50:05.280000 audit: BPF prog-id=67 op=LOAD                            
Mar  6 07:50:05.281000 audit: BPF prog-id=68 op=LOAD                            
Mar  6 07:50:05.281000 audit: BPF prog-id=69 op=LOAD                            
Mar  6 07:50:05.290390 systemd[1]: Starting systemd-hostnamed.service - Hostname Service...
Mar  6 07:50:05.294788 systemd[1]: Started chronyd.service - NTP client/server. 
Mar  6 07:50:05.298000 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=chronyd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar  6 07:50:05.308385 nmstatectl[1263]: [2023-03-06T07:50:05Z WARN  nmstate::nm::nm_dbus::error] Unknown DBUS error MethodError("org.freedesktop.DBus.Error.UnknownMethod", Some("Object does not exist at path “/org/freedesktop/NetworkManager”"), Msg { type: Error, sender: ":1.3", reply-serial: 2, body: Signature: [
Mar  6 07:50:05.308385 nmstatectl[1263]:             s (115),                    
Mar  6 07:50:05.308385 nmstatectl[1263]:     ] })                                
Mar  6 07:50:05.310309 nmstatectl[1263]: [2023-03-06T07:50:05Z ERROR nmstatectl::service] Failed to apply state file /etc/nmstate/br-ex.yml: NmstateError: Bug: DbusConnectionError: org.freedesktop.DBus.Error.UnknownMethod: Object does not exist at path “/org/freedesktop/NetworkManager”
Mar  6 07:50:05.310867 systemd[1]: nmstate.service: Deactivated successfully.    

Version-Release number of selected component (if applicable): 2.2.5-1.fc37


How reproducible: Always


Steps to Reproduce:
1. Add a configuration to /etc/nmstate/*.yml
2. Check configuration after startup
3.

Actual results:
State is not applied with the following error
Mar  6 07:50:05.269335 systemd[1]: Starting nmstate.service - Apply nmstate on-disk state...
Mar  6 07:50:05.277998 systemd[1]: Finished systemd-homed-activate.service - Home Area Activation.  
Mar  6 07:50:05.278000 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-homed-activate comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success' 
Mar  6 07:50:05.280000 audit: BPF prog-id=67 op=LOAD                            
Mar  6 07:50:05.281000 audit: BPF prog-id=68 op=LOAD                            
Mar  6 07:50:05.281000 audit: BPF prog-id=69 op=LOAD                            
Mar  6 07:50:05.290390 systemd[1]: Starting systemd-hostnamed.service - Hostname Service...
Mar  6 07:50:05.294788 systemd[1]: Started chronyd.service - NTP client/server. 
Mar  6 07:50:05.298000 audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=chronyd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Mar  6 07:50:05.308385 nmstatectl[1263]: [2023-03-06T07:50:05Z WARN  nmstate::nm::nm_dbus::error] Unknown DBUS error MethodError("org.freedesktop.DBus.Error.UnknownMethod", Some("Object does not exist at path “/org/freedesktop/NetworkManager”"), Msg { type: Error, sender: ":1.3", reply-serial: 2, body: Signature: [
Mar  6 07:50:05.308385 nmstatectl[1263]:             s (115),                    
Mar  6 07:50:05.308385 nmstatectl[1263]:     ] })                                
Mar  6 07:50:05.310309 nmstatectl[1263]: [2023-03-06T07:50:05Z ERROR nmstatectl::service] Failed to apply state file /etc/nmstate/br-ex.yml: NmstateError: Bug: DbusConnectionError: org.freedesktop.DBus.Error.UnknownMethod: Object does not exist at path “/org/freedesktop/NetworkManager”
Mar  6 07:50:05.310867 systemd[1]: nmstate.service: Deactivated successfully.   


Expected results:
State should be applied

Additional info:
There is already a fix https://github.com/nmstate/nmstate/pull/2265

Comment 1 Gris Ge 2023-03-06 09:35:04 UTC
Patch posted to upstream https://github.com/nmstate/nmstate/pull/2265

To test the bug:
 * Store a desire state YAML file as /etc/nmstate/foo.yml
 * `sudo systemctl enable nmstate`
 * `reboot`
 * check whether desire state been applied. or `journalctl -u nmstate`

Comment 4 Mingyu Shi 2023-04-24 08:50:37 UTC
Verified with:
nmstate-2.2.9-1.el9.x86_64
NetworkManager-1.43.6-1.el9.x86_64
DISTRO=RHEL-9.3.0-20230423.30

Put veth0.yml in /etc/nmstate:
dns-resolver: {}
route-rules: {}
routes:
  running:
  - destination: 2620:52:0:49c2::/64
    next-hop-interface: veth0
    next-hop-address: '::'
    metric: 100
    table-id: 254
  - destination: ::/0
    next-hop-interface: veth0
    next-hop-address: fe80::ee3e:f702:1d90:80a1
    metric: 100
    table-id: 254
  - destination: 0.0.0.0/0
    next-hop-interface: veth0
    next-hop-address: 10.73.195.254
    metric: 100
    table-id: 254
interfaces:
- name: veth0
  type: veth
  state: up
  veth:
    peer: veth0_p
  mac-address: 14:18:77:6D:51:08
  mtu: 8500
  min-mtu: 60
  max-mtu: 9000
  wait-ip: any
  ipv4:
    enabled: true
    dhcp: true
    address:
    - ip: 192.168.199.1
      prefix-length: 23
    auto-dns: true
    auto-gateway: true
    auto-routes: true
    auto-route-table-id: 0
  ipv6:
    enabled: true
    dhcp: true
    autoconf: true
    address:
    - ip: 2620:52:0:49c2:1618:77ff:fe6d:5107
      prefix-length: 64
    - ip: fe80::1618:77ff:fe6d:5107
      prefix-length: 64
    auto-dns: true
    auto-gateway: true
    auto-routes: true
    auto-route-table-id: 0
    addr-gen-mode: eui64
  accept-all-mac-addresses: false
  lldp:
    enabled: false

`systemctl enable nmstate` and reboot system, get:
[16:48:10@dell-per730-20 ~]0# nmcli con
NAME      UUID                                  TYPE      DEVICE  
veth0     c8130521-2694-42ab-b946-af1e9251b5f1  veth      veth0   
eno1      79a38ec3-db52-49cd-b172-85fc7f59cff9  ethernet  eno1    
lo        fda50bb7-a817-4024-9ad0-1db02fad5451  loopback  lo      
veth0_p   197ce7b3-4a2e-4cf2-a201-4ca4af6d621b  veth      veth0_p 
eno2      5ca4cb28-18bd-4493-9390-906024a2a123  ethernet  --      
eno3      1b5661b6-b42e-4f56-b816-20e7f4349c5e  ethernet  --      
eno4      d1f9d3af-87f1-468d-af04-c9347e61d367  ethernet  --      
enp6s0f0  c486a668-2d7d-4c17-8ad3-342d82c84483  ethernet  --      
enp6s0f1  82b43fd1-01a5-4e11-9f37-55ccdfc6da6c  ethernet  --      
[16:49:22@dell-per730-20 ~]0# nms show veth0
dns-resolver: {}
route-rules: {}
routes: {}
interfaces:
- name: veth0
  type: veth
  state: up
  mac-address: 14:18:77:6D:51:08
  mtu: 8500
  min-mtu: 68
  max-mtu: 65535
  wait-ip: any
  ipv4:
    enabled: true
    dhcp: true
    dhcp-client-id: ll
    auto-dns: true
    auto-gateway: true
    auto-routes: true
    auto-route-table-id: 0
  ipv6:
    enabled: true
    dhcp: true
    autoconf: true
    dhcp-duid: ll
    address:
    - ip: fe80::1618:77ff:fe6d:5108
      prefix-length: 64
    auto-dns: true
    auto-gateway: true
    auto-routes: true
    auto-route-table-id: 0
    addr-gen-mode: eui64
  accept-all-mac-addresses: false
  lldp:
    enabled: false
  ethtool:
    feature:
      tx-sctp-segmentation: true
      tx-generic-segmentation: true
      tx-gre-segmentation: true
      tx-ipxip4-segmentation: true
      rx-checksum: true
      tx-udp-segmentation: true
      rx-gro-list: false
      tx-scatter-gather-fraglist: true
      rx-udp-gro-forwarding: false
      tx-tcp-ecn-segmentation: true
      tx-udp_tnl-csum-segmentation: true
      tx-vlan-stag-hw-insert: true
      tx-checksum-sctp: true
      tx-gre-csum-segmentation: true
      tx-tcp6-segmentation: true
      tx-tcp-mangleid-segmentation: true
      rx-gro: false
      highdma: true
      tx-tcp-segmentation: true
      tx-vlan-hw-insert: true
      tx-ipxip6-segmentation: true
      rx-vlan-hw-parse: true
      tx-udp_tnl-segmentation: true
      tx-nocache-copy: false
      tx-gso-list: true
      rx-vlan-stag-hw-parse: true
      tx-checksum-ip-generic: true
  veth:
    peer: veth0_p