Reason for "Connection is not available on the device at this time."

[Ana Rodríguez López <rodrilopez ana gmail com>]

Hi,

I have this problem with two devices: modem GSM (after disconnection and power off) and Ethernet device (usb0).

I cannot find a way to debug this, I set the NM debug mode with:

sudo dbus-send --system --print-reply --dest=org.freedesktop.NetworkManager /org/freedesktop/NetworkManager org.freedesktop.NetworkManager.SetLogging string:"debug" string:""

But I still don't see any reason. For the Modem:

Jan 09 15:17:57 D130102 NetworkManager[246]: <info>  [1515511077.4440] (cdc-wdm0): modem state changed, 'disabled' --> 'enabling' (reason: user-requested)
Jan 09 15:17:57 D130102 NetworkManager[246]: <debug> [1515511077.4446] device[0x79c940] (cdc-wdm0): add_pending_action (1): 'recheck-available'
Jan 09 15:17:57 D130102 NetworkManager[246]: <debug> [1515511077.4558] device[0x79c940] (cdc-wdm0): remove_pending_action (0): 'recheck-available'
Jan 09 15:17:57 D130102 NetworkManager[246]: <info>  [1515511077.5026] (cdc-wdm0): modem state changed, 'enabling' --> 'disabled' (reason: unknown)
Jan 09 15:17:57 D130102 NetworkManager[246]: <debug> [1515511077.5031] device[0x79c940] (cdc-wdm0): add_pending_action (1): 'recheck-available'
Jan 09 15:17:57 D130102 NetworkManager[246]: <debug> [1515511077.5040] device[0x79c940] (cdc-wdm0): remove_pending_action (0): 'recheck-available'
Jan 09 15:17:59 D130102 NetworkManager[246]: <debug> [1515511079.7748] ++ connection 'replace-and-commit-disk' (0x7c1050/NMSimpleConnection < 0x719078/NMSKeyfileConnection):
Jan 09 15:17:59 D130102 NetworkManager[246]: <debug> [1515511079.7804] ++ connection                [ 0x7a1c78 < 0x6f6e18 ]
Jan 09 15:17:59 D130102 NetworkManager[246]: <debug> [1515511079.7819] ++ connection.autoconnect    < FALSE
Jan 09 15:17:59 D130102 NetworkManager[246]: <debug> [1515511079.8245] settings-connection[0x719078,baa2af1b-e21e-7bcf-f1ac-1a775c46ddc3]: replace settings from connection 0x7c1050 (ModemGSM)
Jan 09 15:17:59 D130102 NetworkManager[246]: <info>  [1515511079.9239] keyfile: update /etc/NetworkManager/system-connections/ModemGSM (baa2af1b-e21e-7bcf-f1ac-1a775c46ddc3,"ModemGSM")
Jan 09 15:17:59 D130102 NetworkManager[246]: <debug> [1515511079.9557] Saving secrets for connection /org/freedesktop/NetworkManager/Settings/1 (ModemGSM)
Jan 09 15:17:59 D130102 NetworkManager[246]: <info>  [1515511079.9678] audit: op="connection-update" uuid="baa2af1b-e21e-7bcf-f1ac-1a775c46ddc3" name="ModemGSM" args="connection.autoconnect" pid=1754 uid=0 result="success"
Jan 09 15:18:01 D130102 NetworkManager[246]: <debug> [1515511081.0742] active-connection[0x6f9710]: set device "cdc-wdm0" [0x79c940]
Jan 09 15:18:01 D130102 NetworkManager[246]: <debug> [1515511081.0794] device[0x79c940] (cdc-wdm0): add_pending_action (1): 'activation-0x6f9710'
Jan 09 15:18:01 D130102 NetworkManager[246]: <debug> [1515511081.1226] active-connection[0x6f9710]: constructed (NMActRequest, version-id 79)
Jan 09 15:18:01 D130102 NetworkManager[246]: <info>  [1515511081.1276] audit: op="connection-activate" uuid="baa2af1b-e21e-7bcf-f1ac-1a775c46ddc3" name="ModemGSM" pid=1754 uid=0 result="fail" reason="Connection 'ModemGSM' is not available on the device cdc-wdm0 at this time."
Jan 09 15:18:01 D130102 NetworkManager[246]: <debug> [1515511081.1280] manager: Failed to activate 'ModemGSM': Connection 'ModemGSM' is not available on the device cdc-wdm0 at this time.

For the usb0:

Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.1080] agent-manager: req[0x744dd8, :1.47/nmcli-connect/0]: requesting permissions
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.1095] agent-manager: req[0x744dd8, :1.47/nmcli-connect/0]: agent registered
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.1109] policy: re-enabling autoconnect for all connections with failed secrets
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.1864] active-connection[0x6f9668]: set device "usb0" [0x734708]
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.1921] device[0x734708] (usb0): add_pending_action (1): 'activation-0x6f9668'
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2201] active-connection[0x6f9668]: constructed (NMActRequest, version-id 80)
Jan 09 15:26:09 D130102 NetworkManager[246]: <info>  [1515511569.2430] audit: op="connection-activate" uuid="66d1285e-9905-4991-99c8-25fa3b3aa08a" name="UsbHost" pid=1873 uid=0 result="fail" reason="Connection 'UsbHost' is not available on the device usb0 at this time."
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2485] manager: Failed to activate 'UsbHost': Connection 'UsbHost' is not available on the device usb0 at this time.
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2489] active-connection[0x6f9668]: set state deactivating (was unknown)
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2493] active-connection[0x6f9668]: check-master-ready: not signalling (state deactivating, no master)
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2496] device[0x734708] (usb0): remove_pending_action (0): 'activation-0x6f9668'
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2500] active-connection[0x6f9668]: set state deactivated (was deactivating)
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2504] active-connection[0x6f9668]: check-master-ready: not signalling (state deactivated, no master)
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.2569] active-connection[0x6f9668]: disposing
Jan 09 15:26:09 D130102 NetworkManager[246]: <debug> [1515511569.3988] agent-manager: req[0x744dd8, :1.47/nmcli-connect/0]: agent unregistered or disappeared

Is there a way to see what is happening? Am I missing to do something?