After connection drops, mobile-data takes ~5m to re-connect

interestingly... on mako i'm only seeing this when switching from umts to gsm, not switching from gsm to umts.

I've also reproduced this when disabling wifi, it took nearly 6 minutes before network-manager tried to activate the ofono context.

I've seen some reports of these; but without logs this is the kind of thing that is impossible to debug.

Could someone seeing this enable debug logs in NetworkManager (editing /etc/init/network-manager.conf and adding --log-level=debug --log-domains=core,mb to the Exec line) as well as enabling ofono debug logs (same idea, add -d to the Exec line), and try to follow the states reported from /usr/share/ofono/scripts/list-modems as the time passes, since this seems to be roughly limited to about a 10 minutes window?

Logs would end up in /var/log/syslog; the full syslog is useful to debug this behavior.

Those logs are from the 2 sec before changing the tech pref on /ril_1, to when data started working again.

reportedly affects rtm as well

from what I see this only happens when changing the technology in settings, whereas when turning off wifi or when coming up at boot cell data is ready right away

seems less critical given that is not a frequent occurrence although obviously a lousy user experience

I see a similar effect on mako vivid-proposed. Sometimes after doing nothing for a few hours I pick up the phone and find it having no data connection at all, without any action from me. This could potentially be because of short 3G network outages. I can confirm that switching from 3G to 2G in the indicator triggers that.

BTW, I tried to enable/disable flight mode, disable/enable mobile data, and further toggle between 2G and 3G, and nothing of that brings it back. Although I didn't wait for a very long time, I'll give it 30 mins now.

Normally it looks like this:

$ ip route
default via 10.51.99.33 dev rmnet_usb0 proto static metric 1024
10.51.99.33 dev rmnet_usb0 proto static scope link metric 1024
100.148.199.0/24 dev rmnet_usb0 proto kernel scope link src 10.51.99.34

But after this happens, "ip route" is completely blank and "ip a |grep UP" only shows lo.

"sudo service network-manager restart" helps, this recovers the 3G connection within a few secs.

The other big problem here is that when I'm connected to wifi, I expect to have a 3G connection as well so things like MMS will work. Currently when I'm connected to wifi MMS does not work at all - I cannot recv MMS attachements because those require a data connection and there doesn't seem to be one.

So to summarize, I see the following problems being reported here:

1. vivid/krillin: when mobile data is active, and radio technology preference is changed, mobile data connection is not always restored.

2. vivid/mako: disable wifi, mobile data connection takes >= 6m to be restored. Note, when this happens, be sure to check 'nmcli d', as there's been an outstanding indicator-network bug around *forever* about too much latency between panel icon changes. See bug #1339792.

3. Hearsay ( from pmcgowan ) that these problems occur on RTM too?

4. Reports from pitti that mobile data occasionally drops and isn't restored. @pitti, what device are you using? This sounds similar to a bug #1425987 reported by Jean Baptiste.

5. No mobile data connection when WiFi connection active; this affects MMS.

So... let's keep this bug for discussions related to the original problem, ie. when the radio data technology is changed, NM takes ~5-6m to restore mobile data connection.

If problem with disabling WiFi can be reproduced, then Ken, please file a new bug for it.

Let's use Jean-Baptiste's bug to track cellular connection dropping and not being restored.

Bill, please file a new bug regarding your MMS issue. We actually do in fact keep the mobile data connection active when WiFi is activated, NM just changes the default route. Note, you may be seeing issues due to issues with US operators.

Also, running mako/vivid-devel/#122, I was able to re-create Jonas' original bug.

I see a delay of 5-6m between changing radio technology and mobile data being re-established. I see it going from 2g -> 3g and visa versa.

Looking at the log, when the technology changes, the NM SCPlugin-Ofono runs as it watches the ofono settings files via inotify. I wonder if this is part of the puzzle. Also, I checked and ofono's ConnectionManager re-attaches pretty quick with the new technology, so the delay is definitely on NM's side.

Tony Espy [2015-03-05 1:36 -0000]:
> 4. Reports from pitti that mobile data occasionally drops and isn't
> restored. @pitti, what device are you using?

vivid-proposed on mako.

> This sounds similar to a bug #1425987 reported by Jean Baptiste.

Right. I got that more often last weekend when I was travelling.
Roaming between cells and going through areas without 3G (or even 2G)
coverage triggers that a lot more often. The main difference for me is
that data often does not come back on its own at all, even after hours
(even at home). I have to restart NM several times for it to come
back.

But indeed the original bug report here gives a nice reproducer
(changing data connection type). Let's fix that and then see how much
it fixes the other use cases.

So what seems to be happening, is that the radio technology switch causes the modem to unregister from the current carrier, and attempt to re-register using the new tech preference ( eg. umts, lte, gsm, ... ). This will cause the ofono ConnectionManager 'Attached' property to return FALSE until the phone re-registers and re-attaches to GPRS.

NM detects the device change state from 'Activated' to 'Failed' ( more on this later ) and in turn schedules an auto-activation attempt of the connection ( context1 ). As the modem's not attached, the activation fails and the retry_count gets decremented, and it tries again repeatedly ( with no delay ), until the retry_count ( initialized to four ) drops to zero.

At this point, NM disables the connection and adds a timeout of 300s in the future which will call a policy function that resets the connection's retry_count, and triggers a new autoconnect sequence. 300s / 60s/m == 5m, our mysterious delay.

What we need is some mechanism for autoconnect to be blocked when the modem is not registered. It looks like nm-device-modem.c implements something like this in it's device_state_changed(). It checks a bunch of reason codes, but NM_DEVICE_STATE_REASON_MODEM_NO_CARRIER ( which is the error returned by stage1 if the modem isn't registered ) isn't checked.

The code also would need a mechanism which would re-enable the autoconnect when the device becomes enabled again ( ie. when 'Attached' becomes TRUE again ).

Also with regards to the device 'Activated' to 'Failed' transition, it's a bit odd that 'Disconnected' isn't used, as 'Failed' causes a retry attempt to be wasted ( see nm-policy.c ) because device_state_changed() treats a new state of FAILED as a connect failure and decrements the retry_count.

So confirmed that adding a case for NM_DEVICE_STATE_REASON_MODEM_NO_CARRIER in device_state_changed ( nm-device-modem.c ), causes the connection to be blocked from auto-connecting.

I still see the initial retries decrement log message in device_state_changed ( nm-policy.c ), I mentioned this is due to the transition of the device from 'Activated' to 'Failed', it's not a new activation attempt. When this is logged( w/retries=4 ), I don't see any subsequent attempts to retry, ever.

nm-policy controls the clearing of the connection's 'autoconnect_blocked_reason' ( which is what gets used in this scenario to block autoconnect ), and at the moment, nothing done by the NM ofono code is triggering the right state changes to clear the reason when 'Attached' becomes TRUE again. Nor is there a timer set, as is done when an autoconnect sequence exceeds it's retry count ( ie. the ~5m timer mentioned above ).

Probably related bug here:
https://bugs.launchpad.net/canonical-devices-system-image/+bug/1435328

In this case it doesn't reconnect at all.

@Leopoldo

Actually it's a different problem, as this is a specific bug with the version of network-manager in vivid, whereas your phone is running Ubuntu RTM which has an older version of network-manager.

So I actually have a fix that seems to work now.

There was an additional problem I discovered where the disconnect_done logic in nm-modem-ofono.c was setting the modem state to CONNECTED, which was incorrect. I've pushed a new branch and associated with this bug. It needs a bit more cleanup before it's ready to land, but looks promising at this point.

This bug was fixed in the package network-manager - 0.9.10.0-4ubuntu14

---------------
network-manager (0.9.10.0-4ubuntu14) vivid; urgency=medium

  [ Tony Espy ]
  * Fix ofono mobile-data 5m reconnect bug (LP: #1418077)
  * Cleanup of the NM ofono code, getting rid of unused and/or
    code that was commented out.
 -- Ricardo Salveti de Araujo <email address hidden> Mon, 13 Apr 2015 01:35:11 -0300