Bug 1289523

Mind, this has been going on for a while now, ever since RHEL6, but it got a bit more silent in RHEL7. At least in RHEL6, NM would complain it couldn't find a connection definition, now it just doesn't do anything.

Would you attach NetworkManager logs so that we can see what is happening?
(Either in /var/log/messages of # journalctl -b 0 -u NetworkManager)

> 3. Click to start the WWAN connection.
I suppose you use gnome-shell for this.

Can you attach output of
$ nmcli device
$ nmcli con
$ mmcli -L
before step 3)

You can list your profiles in command line an try connecting there with
$ nmcli con
$ nmcli con up <name of your WWAN profile>

Note that NetworkManager in RHEL 6 and RHEL 7 are quite different.

(In reply to Jirka Klimes from comment #2)
> Would you attach NetworkManager logs so that we can see what is happening?
> (Either in /var/log/messages of # journalctl -b 0 -u NetworkManager)

As I mentioned, there used to be quite verbose records in RHEL6, but not any more. Sometimes I get this (then again, sometimes not even that):

gnome-session: (gnome-shell:6182): libnm-glib-WARNING **: Device activation failed: (32) Connection 'XXXXXX' is not available on the device cdc-wdm0 at this time.

> > 3. Click to start the WWAN connection.
> I suppose you use gnome-shell for this.

True.

> Can you attach output of
> $ nmcli device
> $ nmcli con
> $ mmcli -L
> before step 3)

It all looks quite normal:

$ nmcli dev
DEVICE             TYPE      STATE         CONNECTION 
...
cdc-wdm0           gsm       disconnected  --         
...

$ nmcli con
NAME                       UUID                                  TYPE             DEVICE     
...
XXXXXX                    47adda34-7962-4814-b9ce-266f6f02ee1e  gsm              --         
...

$ mmcli -L

Found 1 modems:
        /org/freedesktop/ModemManager1/Modem/10 [Generic] MBIM [1199:A001]

Do note that this is the only "gsm" type connection profile I have created, so the applet should have no problem identifying it and linking it to the device.

> You can list your profiles in command line an try connecting there with
> $ nmcli con
> $ nmcli con up <name of your WWAN profile>

It's the same end result, but only with an additional message:

$ nmcli con up XXXXXX
Error: Connection activation failed: No suitable device found for this connection.

> Note that NetworkManager in RHEL 6 and RHEL 7 are quite different.

I'm aware of that, thanks for reminding me of nmcli though.

(In reply to Grega Bremec from comment #3)
> $ nmcli con up XXXXXX
> Error: Connection activation failed: No suitable device found for this
> connection.
>

This usually means that there is no device compatible with the connection. It could be caused by many reasons, for example the profile has a specific MAC address set, etc. But in this case it probably means that the device is in a state that is not really usable.

The NetworkManager and ModemManager logs would help (/var/log/messages or journalctl).
You can switch on debug logging on NetworkManager with
$ sudo nmcli gen log level debug
and restore normal level with 
$ sudo nmcli gen log level info

You are not seriously suggesting that the starting up of nm-connection-editor, opening and saving the connection definition, somehow magically changes the device's state from "not really usable" (whatever that is) to "usable"?

I can wait for days and nothing is going to change until I perform the above operation. I can tell when a device is not initialized properly, and this is not one of these cases.

Hopefully this will make it clear.

If I try to activate the connection using nmcli, prior to replacing its definition from within nm-connection-editor, this happens every single time:

Dec 28 16:00:45 xxxxxx NetworkManager[3118]: <debug> [1451314845.322007] [settings/nm-agent-manager.c:322] impl_agent_manager_register_with_capabilities(): (:1.7958/nmcli-connect/1000) requesting permissions
...
Dec 28 16:00:45 xxxxxx NetworkManager[3118]: <debug> [1451314845.334933] [settings/nm-agent-manager.c:234] agent_register_permissions_done(): (:1.7958/nmcli-connect/1000) agent registered
...
Dec 28 16:00:45 xxxxxx NetworkManager[3118]: <debug> [1451314845.346453] [settings/nm-agent-manager.c:117] remove_agent(): (:1.7958/nmcli-connect/1000) agent unregistered or disappeared

When I start nm-connection-editor and open the connection definition, I get the following record in the log:

Dec 28 16:01:50 xxxxxx NetworkManager[3118]: <debug> [1451314910.526058] [settings/nm-agent-manager.c:833] get_done_cb(): (:1.84/org.gnome.Shell.NetworkAgent/1000) agent returned no secrets for request 0x7fee18a40e00/XXXXXX/ppp
Dec 28 16:01:50 xxxxxx NetworkManager[3118]: <debug> [1451314910.526099] [settings/nm-settings-connection.c:802] agent_secrets_done_cb(): settings-connection[0x7fee18931da0,47adda34-7962-4814-b9ce-266f6f02ee1e]: (ppp:230) secrets request error: (4) No agents were available for this request.

After saving it, an agent is "initiated" with the secret:

Dec 28 16:01:56 xxxxxx NetworkManager[3118]: <debug> [1451314916.268795] [settings/nm-agent-manager.c:1321] nm_agent_manager_save_secrets(): Saving secrets for connection /org/freedesktop/NetworkManager/Settings/16 (XXXXXX)
Dec 28 16:01:56 xxxxxx NetworkManager[3118]: <debug> [1451314916.268836] [settings/nm-agent-manager.c:580] request_add_agent(): (:1.84/org.gnome.Shell.NetworkAgent/1000) agent allowed for secrets request 0x7fee189dd040/XXXXXX
...
Dec 28 16:01:56 xxxxxx NetworkManager[3118]: <debug> [1451314916.283045] [settings/nm-agent-manager.c:1272] save_done_cb(): (:1.84/org.gnome.Shell.NetworkAgent/1000) agent saved secrets for request 0x7fee189dd040/XXXXXX

Whenever I activate the corresponding connection subsequently, NM is happy:

Dec 28 16:02:33 xxxxxx NetworkManager[3118]: <debug> [1451314953.773423] [settings/nm-agent-manager.c:234] agent_register_permissions_done(): (:1.7963/nmcli-connect/1000) agent registered
Dec 28 16:02:33 xxxxxx NetworkManager[3118]: <debug> [1451314953.773457] [nm-policy.c:844] reset_autoconnect_for_failed_secrets(): Re-enabling autoconnect for all connections with failed secrets
...
Dec 28 16:02:33 xxxxxx NetworkManager[3118]: <info>  (cdc-wdm0): Activation: starting connection 'XXXXXX' (47adda34-7962-4814-b9ce-266f6f02ee1e)

It would help if you could attach NetworkManger logs for the failing case.
They are either in /var/log/messages of via journalctl -b 0 -u NetworkManager.

@Blueowl, the above actually *are* the logs.

Looks like an nmcli bug, it may be quitting too early, or nmcli may not be spawned with the right flags to let the secret agent answer requests.

(In reply to Dan Williams from comment #9)
> Looks like an nmcli bug, it may be quitting too early, or nmcli may not be
> spawned with the right flags to let the secret agent answer requests.

I don't think so, Dan, because this is what I get in the logs from the Gnome applet as well:

May  2 10:53:29 xxxxxx NetworkManager[1265]: <debug> [1462179209.935061] [devices/nm-device.c:7956] nm_device_add_pending_action(): [0x7efc40d80c30] (cdc-wdm0): add_pending_action (1): 'activation::0x7efc40c60180'
May  2 10:53:29 xxxxxx NetworkManager[1265]: <debug> [1462179209.935164] [nm-auth-manager.c:302] nm_auth_manager_polkit_authority_check_authorization(): auth: call[159816]: CheckAuthorization(org.freedesktop.NetworkManager.network-control), subject=unix-process[pid=14039, uid=1000, start=4205]
May  2 10:53:29 xxxxxx NetworkManager[1265]: <debug> [1462179209.944550] [nm-auth-manager.c:210] check_authorization_cb(): auth: call[159816]: CheckAuthorization succeeded: (is_authorized=1, is_challenge=0)
May  2 10:53:29 xxxxxx NetworkManager[1265]: <debug> [1462179209.944707] [nm-manager.c:2907] _internal_activation_failed(): Failed to activate 'XXXXXX': Connection 'XXXXXX' is not available on the device cdc-wdm0 at this time.
May  2 10:53:29 xxxxxx NetworkManager[1265]: <debug> [1462179209.944736] [nm-active-connection.c:514] check_master_ready(): active-connection[0x7efc40c60180]: not signalling master-ready (not activating)
May  2 10:53:29 xxxxxx NetworkManager[1265]: <debug> [1462179209.944747] [devices/nm-device.c:7989] nm_device_remove_pending_action(): [0x7efc40d80c30] (cdc-wdm0): remove_pending_action (0): 'activation::0x7efc40c60180'
May  2 10:53:29 xxxxxx NetworkManager[1265]: <debug> [1462179209.944765] [nm-active-connection.c:514] check_master_ready(): active-connection[0x7efc40c60180]: not signalling master-ready (not activating)
May  2 10:53:29 xxxxxx gnome-session: (gnome-shell:14039): libnm-glib-WARNING **: Device activation failed: (32) Connection 'XXXXXX' is not available on the device cdc-wdm0 at this time.

Also, do note that the above connection change (comment 6) is done using nm-connection-editor, but using "nmcli con edit" results in the same (just some additional details):

May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.194225] [nm-auth-manager.c:302] nm_auth_manager_polkit_authority_check_authorization(): auth: call[160074]: CheckAuthorization(org.freedesktop.NetworkManager.settings.modify.system), subject=unix-process[pid=5457, uid=1000, start=144823349]
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.201844] [nm-auth-manager.c:210] check_authorization_cb(): auth: call[160074]: CheckAuthorization succeeded: (is_authorized=1, is_challenge=0)
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.203597] [NetworkManagerUtils.c:2575] nm_utils_log_connection_diff(): ++ connection 'replace-and-commit-disk' (0x7efc280014c0/NMSimpleConnection < 0x7efc40cf9780/NMKeyfileConnection):
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.203624] [NetworkManagerUtils.c:2596] nm_utils_log_connection_diff(): ++ connection                [ 0x7efc40e82bc0 < 0x7efc40cffcf0 ]
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.203633] [NetworkManagerUtils.c:2610] nm_utils_log_connection_diff(): ++ connection.timestamp      = 1461415238 < 1461183521
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.204028] [settings/nm-settings-connection.c:517] nm_settings_connection_replace_settings(): settings-connection[0x7efc40cf9780,47adda34-7962-4814-b9ce-266f6f02ee1e]: replace settings from connection 0x7efc280014c0 (XXXXXX)
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.215607] [settings/nm-agent-manager.c:1321] nm_agent_manager_save_secrets(): Saving secrets for connection /org/freedesktop/NetworkManager/Settings/55 (XXXXXX)
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.215636] [settings/nm-agent-manager.c:580] request_add_agent(): (:1.114/org.gnome.Shell.NetworkAgent/1000) agent allowed for secrets request 0x7efc40d8e120/XXXXXX
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.215874] [devices/nm-device.c:7956] nm_device_add_pending_action(): [0x7efc40daefa0] (00:F4:6F:6D:7A:04): add_pending_action (1): 'autoactivate'
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.215902] [devices/nm-device.c:7956] nm_device_add_pending_action(): [0x7efc40d80c30] (cdc-wdm0): add_pending_action (1): 'autoactivate'
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.216873] [settings/nm-agent-manager.c:617] request_next_agent(): (:1.114/org.gnome.Shell.NetworkAgent/1000) agent saving secrets for request 0x7efc40d8e120/XXXXXX
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.228857] [devices/nm-device.c:7989] nm_device_remove_pending_action(): [0x7efc40daefa0] (00:F4:6F:6D:7A:04): remove_pending_action (0): 'autoactivate'
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.230427] [devices/nm-device.c:7989] nm_device_remove_pending_action(): [0x7efc40d80c30] (cdc-wdm0): remove_pending_action (0): 'autoactivate'
May  2 11:00:29 xxxxxx NetworkManager[1265]: <debug> [1462179629.240667] [settings/nm-agent-manager.c:1272] save_done_cb(): (:1.114/org.gnome.Shell.NetworkAgent/1000) agent saved secrets for request 0x7efc40d8e120/XXXXXX

After either change, the connection becomes available and operational.

Hi Grega,
   my guess is that you have pin on SIM, on suspend the modem reset its state and loses the "unlock" state.Then NM 1.0.6 would not submit the pin again once back from the suspend and would not be able to restart the session.

I have to ask you a couple of questions more to verify this:
1) Do you have a pin on the SIM used in your Broadband Modem? 
2) Can you please post also the output of:
    mmcli -m <your modem id>  
   (you should get the modem id with 'mmcli -L' just before issuing the above command)

Thanks

(In reply to Francesco Giudici from comment #11)
> Hi Grega,
>    my guess is that you have pin on SIM, on suspend the modem reset its
> state and loses the "unlock" state.Then NM 1.0.6 would not submit the pin
> again once back from the suspend and would not be able to restart the
> session.

Hi, Francesco,

Thanks for the insight, indeed it makes sense.

> I have to ask you a couple of questions more to verify this:
> 1) Do you have a pin on the SIM used in your Broadband Modem? 

Yes, of course. :)

> 2) Can you please post also the output of:
>     mmcli -m <your modem id>  
>    (you should get the modem id with 'mmcli -L' just before issuing the
> above command)

Here it is:

$ mmcli -m /org/freedesktop/ModemManager1/Modem/88

/org/freedesktop/ModemManager1/Modem/88 (device id 'ef04154a454fa964e6bf49fa5efaaa1d529359f1')
  -------------------------
  Hardware |   manufacturer: 'Generic'
           |          model: 'MBIM [1199:A001]'
           |       revision: 'FIH7160_V1.1_MODEM_01.1349.12'
           |      supported: 'gsm-umts, lte'
           |        current: 'gsm-umts, lte'
           |   equipment id: '013937004862643'
  -------------------------
  System   |         device: '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-4'
           |        drivers: 'cdc_mbim, cdc_acm'
           |         plugin: 'Generic'
           |   primary port: 'cdc-wdm0'
           |          ports: 'wwp0s20u4 (net), cdc-wdm0 (mbim), ttyACM0 (at)'
  -------------------------
  Numbers  |           own : 'unknown'
  -------------------------
  Status   |           lock: 'sim-pin'
           | unlock retries: 'sim-pin (3)'
           |          state: 'locked'
           |    power state: 'on'
           |    access tech: 'unknown'
           | signal quality: '0' (cached)
  -------------------------
  Modes    |      supported: 'allowed: 2g, 3g, 4g; preferred: none'
           |        current: 'allowed: 2g, 3g, 4g; preferred: none'
  -------------------------
  Bands    |      supported: 'unknown'
           |        current: 'unknown'
  -------------------------
  IP       |      supported: 'ipv4, ipv6, ipv4v6'
  -------------------------
  SIM      |           path: '/org/freedesktop/ModemManager1/SIM/88'

Mind you, this is immediately after resume. When I open & save the connection definition, the state of the lock does not change, it still says "locked". However, the behaviour of "nm con up" apparently does (???).

 
> Mind you, this is immediately after resume. When I open & save the
> connection definition, the state of the lock does not change, it still says
> "locked". However, the behaviour of "nm con up" apparently does (???).

Yeah, I have to check what exactly happens then... anyway, this issue should be no more present in nm-1.2 (it would be of help if you can give it a try).
I have to find where it has been fixed.

Thanks

(In reply to Francesco Giudici from comment #13)
>  
> > Mind you, this is immediately after resume. When I open & save the
> > connection definition, the state of the lock does not change, it still says
> > "locked". However, the behaviour of "nm con up" apparently does (???).
> 
> Yeah, I have to check what exactly happens then... anyway, this issue should
> be no more present in nm-1.2 (it would be of help if you can give it a try).
> I have to find where it has been fixed.

I'm afraid unless it's in one of the RHEL 7 repos (like HTB or something) it's not an option for me as I'm using workstation for two simple reasons - the QA it gets before release and the fact I simply can't reinstall or do a major upgrade every 6 months. :(

Fedora was a nice ride, but unfortunately it's way past that time. :)

Hi Grega, I have been able to reproduce it.
I found that the issue has been solved by Dan with:
https:cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=cb751012a2f4b8ef236eab2a7c65687c99205806/

The fix is present upstream on 1-2 (from beta1) and has been backported on 1.0.12.

It will be released in RHEL 7.3.

Thanks for reporting.

Sorry, there was an issue with the link of the fix... here the correct one:
https://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=cb751012a2f4b8ef236eab2a7c65687c99205806

(In reply to Francesco Giudici from comment #15)
> Hi Grega, I have been able to reproduce it.
> I found that the issue has been solved by Dan with:
> https:cgit.freedesktop.org/NetworkManager/NetworkManager/commit/
> ?id=cb751012a2f4b8ef236eab2a7c65687c99205806/
> 
> The fix is present upstream on 1-2 (from beta1) and has been backported on
> 1.0.12.
> 
> It will be released in RHEL 7.3.
> 
> Thanks for reporting.

Hi, Francesco,

Thanks for the push here, and all the additional info.

I'll have an eye out for 1.0.12 and make sure I test it as soon as it's available.

If I understand correctly from the above link, this is NetworkManager-wwan RPM.

Thanks again!

(In reply to Grega Bremec from comment #17)
> 
> If I understand correctly from the above link, this is NetworkManager-wwan
> RPM.

Exactly!

It will be released with RHEL 7.3 which will be shipped with an higher version of NM (and so NetworkManager-wwan).

PIN secured device is correctly reconnected after resume from suspend w/o entering PIN in GNOME Shell.

I can confirm this as well. Thanks!

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHSA-2016-2581.html