Sometimes nmstate raises an ApplyError exception

[tyll]

When testing #60 nmstate sometimes raises an unhandled exception:

LC_ALL=C nmstatectl set /tmp/nmstate_linkagg_debug-1535467463-FlJO5z
2018-08-28 10:51:27,053 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/25 created for all devices: 60
2018-08-28 10:51:27,074 root         DEBUG    Connection adding succeeded: dev=web-bond
2018-08-28 10:51:27,074 root         DEBUG    NM action queue exhausted, quiting mainloop
2018-08-28 10:51:27,097 root         DEBUG    Connection adding succeeded: dev=web-bond
2018-08-28 10:51:27,105 root         DEBUG    Connection adding succeeded: dev=eth1
2018-08-28 10:51:27,137 root         ERROR    NM main-loop aborted: Connection activation failed: error=nm-manager-error-quark: The device 'web-bond' has no connections available for activation. (2)
2018-08-28 10:51:27,185 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/25 rollback executed: dbus.Dictionary({dbus.String(u'/org/freedesktop/NetworkManager/Devices/1'): dbus.UInt32(0L), dbus.String(u'/org/freedesktop/NetworkManager/Devices/2'): dbus.UInt32(0L), dbus.String(u'/org/freedesktop/NetworkManager/Devices/5'): dbus.UInt32(0L)}, signature=dbus.Signature('su'))
Traceback (most recent call last):
  File "/root/.local/bin/nmstatectl", line 10, in <module>
    sys.exit(main())
  File "/root/.local/lib/python2.7/site-packages/nmstatectl/nmstatectl.py", line 44, in main
    return args.func(args)
  File "/root/.local/lib/python2.7/site-packages/nmstatectl/nmstatectl.py", line 116, in apply
    netapplier.apply(state)
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 38, in apply
    _apply_ifaces_state(desired_state['interfaces'])
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 52, in _apply_ifaces_state
    _edit_interfaces(ifaces_desired_state, ifaces_current_state)
  File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 74, in _setup_providers
    raise ApplyError(mainloop.error)
libnmstate.netapplier.ApplyError: run execution

State:

{
    "interfaces": [
        {
            "link-aggregation": {
                "mode": "802.3ad", 
                "slaves": [
                    "eth1"
                ], 
                "options": {}
            }, 
            "state": "up", 
            "type": "bond", 
            "name": "web-bond"
        }
    ]
}

Initial state:

nmstatectl show
{
    "interfaces": [
        {
            "ipv4": {
                "enabled": false
            },
            "name": "lo",
            "state": "down",
            "type": "unknown"
        },
        {
            "ipv4": {
                "addresses": [
                    {
                        "ip": "192.168.122.193",
                        "prefix-length": 24
                    }
                ],
                "enabled": true
            },
            "name": "eth0",
            "state": "up",
            "type": "ethernet"
        },
        {
            "ipv4": {
                "enabled": false
            },
            "name": "eth1",
            "state": "down",
            "type": "ethernet"
        },
        {
            "ipv4": {
                "enabled": false
            },
            "name": "web-bond",
            "state": "down",
            "type": "bond"
        }
    ]
}

The error sometimes happen when I do this:

nmstatectl set <<EOF
{
    "interfaces": [
        {
            "link-aggregation": {
                "mode": "802.3ad", 
                "slaves": [
                    "eth1"
                ], 
                "options": {}
            }, 
            "state": "up", 
            "type": "bond", 
            "name": "web-bond"
        }
    ]
}
EOF

If the error does not happen, run nmcli con delete eth1 web-bond and try again. Or try again without removing the interfaces to try to trigger the error in #62.

[tyll]

@EdDev just wondering, is this error something that can be used to demonstrate the rollback?

[EdDev]

Yes, this is a good one to demonstrate the rollback (if the rollback works as expected). But if this is not consistently occurring, it will be problematic to show it. Perhaps it is even host dependent.

[EdDev]

I do not really understand how this is happening, as the bond profile is created (callback confirms it) but the activation fails. Perhaps the NM logs can hint what is going on?

[tyll]

I got this error also when trying to remove a bond interface:

mstatectl set nmstate/del-bond.json 
2018-08-28 14:45:08,789 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/4 created for all devices: 60
2018-08-28 14:45:08,843 root         DEBUG    Connection deletion succeeded: dev=web-bond
2018-08-28 14:45:08,861 root         DEBUG    Connection deletion succeeded: dev=web-bond
2018-08-28 14:45:08,952 root         ERROR    NM main-loop aborted: Connection deletion failed: error=nm-settings-error-quark: Error checking authorization: connection was deleted (0)
2018-08-28 14:45:08,953 root         DEBUG    Connection deletion aborted: error=g-io-error-quark: Operation was cancelled (19)
2018-08-28 14:45:09,104 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/4 rollback executed: dbus.Dictionary({dbus.String(u'/org/freedesktop/NetworkManager/Devices/1'): dbus.UInt32(0L), dbus.String(u'/org/freedesktop/NetworkManager/Devices/2'): dbus.UInt32(0L), dbus.String(u'/org/freedesktop/NetworkManager/Devices/3'): dbus.UInt32(0L), dbus.String(u'/org/freedesktop/NetworkManager/Devices/4'): dbus.UInt32(0L)}, signature=dbus.Signature('su'))
Traceback (most recent call last):
  File "/root/.local/bin/nmstatectl", line 10, in <module>
    sys.exit(main())
  File "/root/.local/lib/python2.7/site-packages/nmstatectl/nmstatectl.py", line 44, in main
    return args.func(args)
  File "/root/.local/lib/python2.7/site-packages/nmstatectl/nmstatectl.py", line 116, in apply
    netapplier.apply(state)
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 38, in apply
    _apply_ifaces_state(desired_state['interfaces'])
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 52, in _apply_ifaces_state
    _edit_interfaces(ifaces_desired_state, ifaces_current_state)
  File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 74, in _setup_providers
    raise ApplyError(mainloop.error)
libnmstate.netapplier.ApplyError: run execution

# cat nmstate/del-bond.json 
{
    "interfaces": [
        {
            "ipv4": {
                "enabled": false
            },
            "name": "eth1",
            "state": "absent",
            "type": "ethernet"
        },
        {
            "ipv4": {
                "enabled": false
            },
            "link-aggregation": {
                "mode": "802.3ad",
                "options": {},
                "slaves": [
                    "eth1"
                ]
            },
            "name": "web-bond",
            "state": "absent",
            "type": "bond"
        }
    ]
}

# nmstatectl show
{
    "interfaces": [
        {
            "ipv4": {
                "enabled": false
            },
            "name": "lo",
            "state": "down",
            "type": "unknown"
        },
        {
            "ipv4": {
                "addresses": [
                    {
                        "ip": "192.168.122.193",
                        "prefix-length": 24
                    }
                ],
                "enabled": true
            },
            "name": "eth0",
            "state": "up",
            "type": "ethernet"
        },
        {
            "ipv4": {
                "enabled": false
            },
            "name": "eth1",
            "state": "up",
            "type": "ethernet"
        },
        {
            "ipv4": {
                "enabled": false
            },
            "link-aggregation": {
                "mode": "802.3ad",
                "options": {},
                "slaves": [
                    "eth1"
                ]
            },
            "name": "web-bond",
            "state": "up",
            "type": "bond"
        }
    ]
}

networkmanager2.log

[tyll]

I noticed that the nmstate output states twice:

Connection adding succeeded: dev=web-bond

or

Connection deletion succeeded: dev=web-bond

And also the network manager logs state:

Aug 28 14:45:08 rhel76-cloud NetworkManager[607]: <info>  [1535481908.9346] audit: op="connection-delete" uuid="c742a177-7057-46f6-9d37-03c2858c2f09" name="eth1" pid=1529 uid=0 result="fail" reason="Error checking authorization: connection was deleted"
Aug 28 14:45:08 rhel76-cloud NetworkManager[607]: <trace> [1535481908.9349] dbus-object[0x55901318f250]: unexport: "/org/freedesktop/NetworkManager/Settings/4"
Aug 28 14:45:08 rhel76-cloud NetworkManager[607]: <info>  [1535481908.9351] audit: op="connection-delete" uuid="c742a177-7057-46f6-9d37-03c2858c2f09" name="eth1" pid=1529 uid=0 result="success"

So it seems to remove/create the same profile twice which might cause these errors.

[EdDev]

@tyll , could you please check if #65 resolved this issue?

[tyll]

@EdDev the error is still present- is it not for you?

nmstatectl set <<EOF
> {
>     "interfaces": [
>         {
>             "link-aggregation": {
>                 "mode": "802.3ad", 
>                 "slaves": [
>                     "eth1"
>                 ], 
>                 "options": {}
>             }, 
>             "state": "up", 
>             "type": "bond", 
>             "name": "web-bond"
>         }
>     ]
> }
> EOF
2018-09-04 05:56:00,876 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/1 created for all devices: 60
2018-09-04 05:56:00,927 root         DEBUG    Connection adding succeeded: dev=web-bond
2018-09-04 05:56:00,927 root         DEBUG    NM action queue exhausted, quiting mainloop
2018-09-04 05:56:00,947 root         DEBUG    Connection adding succeeded: dev=web-bond
2018-09-04 05:56:00,957 root         DEBUG    Connection adding succeeded: dev=eth1
2018-09-04 05:56:00,958 root         ERROR    NM main-loop aborted: Connection activation failed: error=nm-manager-error-quark: The device 'web-bond' has no connections available for activation. (2)
2018-09-04 05:56:00,995 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/1 rollback executed: dbus.Dictionary({dbus.String(u'/org/freedesktop/NetworkManager/Devices/1'): dbus.UInt32(0L), dbus.String(u'/org/freedesktop/NetworkManager/Devices/2'): dbus.UInt32(0L), dbus.String(u'/org/freedesktop/NetworkManager/Devices/3'): dbus.UInt32(0L)}, signature=dbus.Signature('su'))
Traceback (most recent call last):
  File "/root/.local/bin/nmstatectl", line 10, in <module>
    sys.exit(main())
  File "/root/.local/lib/python2.7/site-packages/nmstatectl/nmstatectl.py", line 44, in main
    return args.func(args)
  File "/root/.local/lib/python2.7/site-packages/nmstatectl/nmstatectl.py", line 116, in apply
    netapplier.apply(state)
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 38, in apply
    _apply_ifaces_state(desired_state['interfaces'])
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 52, in _apply_ifaces_state
    _edit_interfaces(ifaces_desired_state, ifaces_current_state)
  File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
    self.gen.next()
  File "/root/.local/lib/python2.7/site-packages/libnmstate/netapplier.py", line 74, in _setup_providers
    raise ApplyError(mainloop.error)
libnmstate.netapplier.ApplyError: run execution

Logfile for this error:

# nmstatectl set <<EOF
> {
>     "interfaces": [
>         {
>             "link-aggregation": {
>                 "mode": "802.3ad", 
>                 "slaves": [
>                     "eth1"
>                 ], 
>                 "options": {}
>             }, 
>             "state": "up", 
>             "type": "bond", 
>             "name": "web-bond"
>         }
>     ]
> }
> EOF
2018-09-04 08:58:33,421 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/6 created for all devices: 60
2018-09-04 08:58:33,442 root         DEBUG    Connection update succeeded: dev=web-bond
2018-09-04 08:58:33,447 root         DEBUG    Connection update succeeded: dev=eth1
2018-09-04 08:58:33,510 root         DEBUG    Connection activation succeeded: dev=web-bond
2018-09-04 08:58:33,569 root         ERROR    NM main-loop aborted: Connection activation failed: error=nm-client-error-quark: Active connection removed before it was initialized (2)
2018-09-04 08:58:33,570 root         DEBUG    Connection activation canceled: error=g-io-error-quark: Operation was cancelled (19)
/usr/lib64/python2.7/site-packages/gi/overrides/GLib.py:574: Warning: g_object_unref: assertion 'G_IS_OBJECT (object)' failed
  super(MainLoop, self).run()
Speicherzugriffsfehler

networkmanager.log

[ffmancera]

Could we close this? @tyll

[tyll]

Yes, it seems to be working now:

2020-02-21 06:37:43,537 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/1 created for all devices: 60
2020-02-21 06:37:43,538 root         DEBUG    Adding new interfaces: ['web-bond']
2020-02-21 06:37:43,539 root         DEBUG    Editing interfaces: ['eth1']
2020-02-21 06:37:43,541 root         DEBUG    Executing NM action: func=add_connection_async
2020-02-21 06:37:43,569 root         DEBUG    Connection adding succeeded: dev=web-bond
2020-02-21 06:37:43,569 root         DEBUG    Executing NM action: func=add_connection_async
2020-02-21 06:37:43,583 root         DEBUG    Connection adding succeeded: dev=eth1
2020-02-21 06:37:43,583 root         DEBUG    Executing NM action: func=safe_activate_async
2020-02-21 06:37:43,592 root         DEBUG    Connection activation initiated: dev=web-bond, con-state=<enum NM_ACTIVE_CONNECTION_STATE_ACTIVATING of type NM.ActiveConnectionState>
2020-02-21 06:37:43,651 root         DEBUG    Connection activation succeeded: dev=web-bond, con-state=<enum NM_ACTIVE_CONNECTION_STATE_ACTIVATING of type NM.ActiveConnectionState>, dev-state=<enum NM_DEVICE_STATE_IP_CONFIG of type NM.DeviceState>, state-flags=<flags NM_ACTIVATION_STATE_FLAG_IS_MASTER | NM_ACTIVATION_STATE_FLAG_LAYER2_READY | NM_ACTIVATION_STATE_FLAG_MASTER_HAS_SLAVES of type NM.ActivationStateFlags>
2020-02-21 06:37:43,651 root         DEBUG    Executing NM action: func=_safe_modify_async
2020-02-21 06:37:43,660 root         DEBUG    Device reapply failed on eth1: error=nm-device-error-quark: Can't reapply changes to 'connection.autoconnect-slaves' setting (3)
Fallback to device activation
2020-02-21 06:37:43,681 root         DEBUG    Connection activation initiated: dev=eth1, con-state=<enum NM_ACTIVE_CONNECTION_STATE_ACTIVATING of type NM.ActiveConnectionState>
2020-02-21 06:37:43,698 root         DEBUG    Connection activation succeeded: dev=eth1, con-state=<enum NM_ACTIVE_CONNECTION_STATE_ACTIVATED of type NM.ActiveConnectionState>, dev-state=<enum NM_DEVICE_STATE_ACTIVATED of type NM.DeviceState>, state-flags=<flags NM_ACTIVATION_STATE_FLAG_IS_SLAVE | NM_ACTIVATION_STATE_FLAG_LAYER2_READY | NM_ACTIVATION_STATE_FLAG_IP4_READY | NM_ACTIVATION_STATE_FLAG_IP6_READY of type NM.ActivationStateFlags>
2020-02-21 06:37:44,199 root         DEBUG    NM action queue exhausted, quiting mainloop
2020-02-21 06:37:44,200 root         DEBUG    context.iteration() does not delete the context_busy_watcher, waiting 50 milliseconds
2020-02-21 06:37:44,248 root         DEBUG    Checkpoint /org/freedesktop/NetworkManager/Checkpoint/1 destroyed
Desired state applied: 
{
    "interfaces": [
        {
            "name": "web-bond",
            "type": "bond",
            "state": "up",
            "link-aggregation": {
                "mode": "802.3ad",
                "options": {},
                "slaves": [
                    "eth1"
                ]
            }
        }
    ]
}