Bug 1289523 - Mobile broadband (WWAN) connection not detected after suspend
Summary: Mobile broadband (WWAN) connection not detected after suspend
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: NetworkManager
Version: 7.2
Hardware: x86_64
OS: Linux
medium
medium
Target Milestone: rc
: ---
Assignee: Francesco Giudici
QA Contact: Desktop QE
URL:
Whiteboard:
Depends On:
Blocks: 1301628 1313485
TreeView+ depends on / blocked
 
Reported: 2015-12-08 11:48 UTC by Grega Bremec
Modified: 2016-11-03 19:04 UTC (History)
12 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-11-03 19:04:57 UTC


Attachments (Terms of Use)


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHSA-2016:2581 normal SHIPPED_LIVE Low: NetworkManager security, bug fix, and enhancement update 2016-11-03 12:08:07 UTC

Description Grega Bremec 2015-12-08 11:48:00 UTC
Description of problem:
After resuming from suspend, any mobile broadband connection is simply ignored until saved again using nm-connection-editor.

Version-Release number of selected component (if applicable):
Name        : NetworkManager-wwan
Epoch       : 1
Version     : 1.0.6
Release     : 27.el7

How reproducible:
Always.

Steps to Reproduce:
1. Suspend & resume.
2. Wait for NM to re-claim all devices.
3. Click to start the WWAN connection.
4. Observe nothing happening, while NM fails after a timeout.
5. Start nm-connection-editor.
6. Open connection definition.
7. Click "Save".
8. Repeat step 3.
9. Observe it succeed.

Actual results:
Nothing happens when a broadband connection is started.

Expected results:
Either:
 - successfully establishing a connection
 - a failure due to premature startup (device not claimed yet)
 - either one of possible timeouts (initializing, registering on network, ...)

Additional info:

Comment 1 Grega Bremec 2015-12-08 11:49:50 UTC
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.

Comment 2 Jirka Klimes 2015-12-08 14:39:14 UTC
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.

Comment 3 Grega Bremec 2015-12-08 16:44:50 UTC
(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.

Comment 4 Jirka Klimes 2015-12-11 07:48:05 UTC
(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

Comment 5 Grega Bremec 2015-12-11 10:41:54 UTC
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.

Comment 6 Grega Bremec 2015-12-28 15:12:46 UTC
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)

Comment 7 Blueowl 2016-01-25 13:32:03 UTC
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.

Comment 8 Grega Bremec 2016-01-25 17:20:39 UTC
@Blueowl, the above actually *are* the logs.

Comment 9 Dan Williams 2016-04-26 15:42:34 UTC
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.

Comment 10 Grega Bremec 2016-05-02 09:06:23 UTC
(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.

Comment 11 Francesco Giudici 2016-06-01 16:38:23 UTC
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

Comment 12 Grega Bremec 2016-06-01 16:49:31 UTC
(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 (???).

Comment 13 Francesco Giudici 2016-06-01 16:55:38 UTC
 
> 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

Comment 14 Grega Bremec 2016-06-01 17:00:20 UTC
(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. :)

Comment 15 Francesco Giudici 2016-06-06 09:35:32 UTC
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.

Comment 16 Francesco Giudici 2016-06-06 09:38:13 UTC
Sorry, there was an issue with the link of the fix... here the correct one:
https://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=cb751012a2f4b8ef236eab2a7c65687c99205806

Comment 17 Grega Bremec 2016-06-06 09:41:41 UTC
(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!

Comment 18 Francesco Giudici 2016-06-06 09:50:15 UTC
(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).

Comment 20 Vladimir Benes 2016-09-14 12:25:27 UTC
PIN secured device is correctly reconnected after resume from suspend w/o entering PIN in GNOME Shell.

Comment 21 Grega Bremec 2016-09-14 12:31:19 UTC
I can confirm this as well. Thanks!

Comment 23 errata-xmlrpc 2016-11-03 19:04:57 UTC
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


Note You need to log in before you can comment on or make changes to this bug.