Leaving Wifi does not connect to mobile carrier data (GSM)

I believe this is related to bug 1418077

@Pat

Unfortunately that's not true as bug #1418077 is for a regression in the new version of network-manager in vivid.

I will give this a try tomorrow. To date, I had always kept the phone alive while walking out of range of an access point. The description here states that the phone was suspended ( or at least the screen turned off ).

I confirm the scenario in the description on 14.09-proposed/krillin #263

I could reproduce by booting the phone, unplugged, in an area with known wifi, so the phone auto-connects and wait until it deep suspends before leaving the wifi area. When you resume the phone the cellular data connection will never establish.

I checked that the phone uses the SIM with the data plan.
The active context returned by list-contexts is correct.
The output of ip route is empty.

@Leopoldo

A couple of questions...

1. Do you have more than one SIM installed in your phone?

2. If you're familiar with using adb, or have the terminal installed could you run the following command and paste the output into this bug:

$ sudo grep "Suspended for" /var/log/syslog

3. Finally, could you please try to set your phone to '2g' only mode and see if the problem still occurs?

I'm in the States, so I only have 2g available and am not able to reproduce the bug. Likewise, @Jean-Baptiste also told me earlier today that he was unable to reproduce the problem when his phone was set to 2g.

This bug may be related to bug #1436411 which also describes problems with the phone becoming idle with an active 3g connection.

Also, just an aside, even though I waited close to 30m before waking my phone, I confirmed that it never truly suspended as all of the "Suspended for" messages showed 0.000.

My testing was done with a krillin running image #20 ( ubuntu-touch/ubuntu-rtm/14.09 ). I had an AT&T SIM inserted into slot #2.

@Jean-Baptiste

Can you attach your syslog, as well as the output from 'list-modems', 'ip route', and 'ifconfig'?

output of ip route is empty.

In discussion with @Jean-Baptiste, when the phone is woken up, the indicator shows a non-connection icon. Other points:

  * 'nmcli d' - shows both modems are disconnected
 * 'list-modems' - shows the first SIM slot registered to the carrier, however it's ConnectionManager interface shows 'Attached' is 0
 * 'list-contexts' - shows an active context with valid IP Settings

This looks like a MTK-specific ofono bug, possibly triggered by a suspend-related modem driver problem.

Hi again,
here are some answers to your questions. This bug just repeated this morning after leaving home wifi. No 3g data connection on the street, and 40 minutes later I still don't have data connection.

I am using the BQ phone with the official repos.

1. Do you have more than one SIM installed in your phone?

No, I only have one SIM card installed.

2. If you're familiar with using adb, or have the terminal installed could you run the following command and paste the output into this bug:

$ sudo grep "Suspended for" /var/log/syslog

Same results as Tony, phone shows that it never truly suspended as all of the "Suspended for" messages showed 0.000.

3. Finally, could you please try to set your phone to '2g' only mode and see if the problem still occurs?

I will give this a try next time I walk out of wifi range.

I tried to collect more traces by starting ofono with the following command:
OFONO_RIL_DEVICE=mtk OFONO_RIL_NUM_SIM_SLOTS=2 OFONO_RIL_TRACE="" ofonod -nd -P stktest,provision,sap,udev,dun,smart,hfp

but I couldn't reproduce the bug.

I am not familiar with adb tool, but if you point me out how to do it properly i can post my logs when the bug repeats, which is typically every single morning walking from home to work. Once there i reboot phone and 3g connectivity is back.

I am on r20 image by the way.

@Jean-Baptiste

So the "-d" flags by itself means enable debug messages for every single source file in ofono. As there have been previous 'racy' issues with the mtkmodem, enabling all these messages may be preventing the problem from happening.

Could you instead try this first:

OFONO_RIL_DEVICE=mtk OFONO_RIL_NUM_SIM_SLOTS=2 OFONO_RIL_TRACE="" ofonod -n -d src/gprs.c,drivers/rilmodem/gprs-context.c,plugins/mtk.c -P stktest,provision,sap,udev,dun,smart,hfp

If that still fails, then try again without the OFONO_RIL_TRACE.

@Leopoldo

Have you installed all available system updates?

adb is a command that you can run from a latop to pull files from a device. Do you have a laptop available, and if so, what OS does it run?

I tried without -d and without OFONO_RIL_TRACE and each time the problem goes away and I cannot reproduce the bug. Is there a way to set these option directly on boot, so I don't have to restart ofono just in case it matters.

@Jean-Baptiste, yes, you can modify /etc/init/ofono.override, adding "env OFONO_RIL_TRACE=""" and "-d" on the ofono execution line.

@Jean-Baptiste

But again, I would not add "-d" by itself, but use the more qualified version I included in comment #17.

I can reproduce this bug by just disabling WiFi.
The indicator shows a HSDPA network, but the phone remains offline.

When using 2G only, the network connection changes to 2G and is working.

My carrier is o2 germany.

Attached the screenshot of the terminal app when I got to reproduce this issue during the weekend.

The interesting issue is that the route was empty, device showing as connected but no interface when calling ifconfig.

current build number: 270
device name: krillin
channel: ubuntu-touch/ubuntu-rtm/14.09-proposed
last update: 2015-04-11 08:14:05
version version: 270
version ubuntu: 20150410.1
version device: 20150408-4f14058
version custom: 20150409-665-29-206

Will keep debug enabled at both ofono and networkmanager and see if I can get to reproduce it again.

OK, I think I figured it out after looking at a radio log of the problem reproduced by Alfonso.

First, there are a couple of MTK-specific unsolicited events that are received that look suspicious:

RIL_UNSOL_RESPONSE_PS_NETWORK_STATE_CHANGED
UNSOL_RESTRICTED_STATE_CHANGED
RIL_UNSOL_RESPONSE_PS_NETWORK_STATE_CHANGED
UNSOL_RESTRICTED_STATE_CHANGED
UNSOL_DATA_CALL_LIST_CHANGED

Turns the mtkmodem code overrides the normal NETWORK_STATE_CHANGED unsolicted request with the PS_NETWORK_STATE_CHANGED request. The RESTRICTED_STATE_CHANGED request doesn't seem to be listened for at all.

That said, I also see a UNSOL_DATA_CALL_LIST_CHANGED with the following payload:

01 00 00 00 F2 03 00 00 09 00 00 00 00 00 00 00

01 00 00 00 = unsolicted
F2 03 00 00 = UNSOL_DATA_CALL_LIST_CHANGED
09 00 00 00 = version
00 00 00 00 = number of calls

The function ril_gprs_context_call_list_changed() in /drivers/rilmodem/gprs-context.c handles this message. If tries to iterator over the call list, and if disconnect == TRUE, or active_cid_found == FALSE, it calls set_context_disconnect(). This function however only sets the internal rilmodem struct to disconnected state, and doesn't inform the ofono core of the disconnect. So, it leaves the connection internally disconnected, but to the rest of the system, it's still connected.

I imagine this may be the same bug as bug #1436427 ( which has been a theory all along ).

I'm working on a fix now, and should have something available to test by tomorrow.

@Tony, great catch! I have tested your changes and reproduced the bug. Now list-contexts does not show any active context when ccmni0 is down.

However, NM is not able to recover from this situation. It tries to add routes before we get the UNSOL_DATA_CALL_LIST_CHANGED event in ofono. After that it tries to activate a context, but fails. I think that for some reason it cannot completely recover after the error adding routes. I also see that I get the bug always and that there is a suspicious line from a kernel driver saying "CCMNI0 close" that I do not know who is triggering. I have tried also with NM from silo 9, but no luck either.

Please see attached log. To me these lines are interesting:

Apr 14 07:48:54 ubuntu-phablet nm-dispatcher: Dispatching action 'down' for wlan0
...
Apr 14 07:48:56 ubuntu-phablet kernel: [ 58.774157][ccci/net] (1)CCMNI0 close
...
Apr 14 07:48:56 ubuntu-phablet NetworkManager[1385]: <error> [1428997736.577516] [platform/nm-linux-platform.c:1714] add_object(): Netlink error adding 0.0.0.0/0 via 10.25.195.122 dev ccmni0 metric 1024 mss 0 src user: Object not found
...
Apr 14 07:48:56 ubuntu-phablet ofonod[1842]: [0,UNSOL]< UNSOL_DATA_CALL_LIST_CHANGED {version=9,num=0}

So we are near, but more changes are needed.

Some more traces when reproducing the bug:

/system/bin/logcat -v threadtime -b main -b radio

...
04-14 09:31:21.057 1844 1861 D use-Rlog/RLOG-AT: +CGEV: NW DEACT "IP", "100.125.255.239", 1
...
04-14 09:31:21.058 1844 1861 D use-Rlog/RLOG-RIL: configureNetworkInterface: Down E
04-14 09:31:21.105 1844 1861 D DHCP : ifc_down(ccmni0) = 0
04-14 09:31:21.106 1844 1861 D DHCP : ifc_set_addr(ccmni0, xx) = 0
...

The "NW DEACT" event means that the network has forced a deactivation. The interesting thing is that I get this when I deactivate WiFi, but only with one of my SIMs. The reason might be that I do not have enough credit to enable the data plan for that SIM. Why this happens exactly when I disable WiFi, I don't know. Maybe the connection had already been dropped by the operator and the modem notices at that time for some weird reason. Anyway, this event is the same you would receive if data is dropped for other reasons, so I hope this reproduces the bug.

So in theory, NM should react to the context 'Settings' property changing to empty, and tear down the connection.

For vivid testing, it's important however that the most recent version of NM which fixes the NM 5m reconnect bug #1418077 is used. This version is currently in the following silo:

https://launchpad.net/~ci-train-ppa-service/+archive/ubuntu/landing-009

...but as it's been marked PASSED by QA, it should be landing in the archive shortly.

We're currently testing RTM to see whether or not the same issue exists with NM.

Turns out pending version of NM was used for the vivid testing mentioned in comments #26 and #27.

Here's the latest update on what we know about this bug.

First, we have working fix for ofono's behavior when a DATA_CALL_LIST_CHANGED message is received with an empty call list, and the context stays active but becomes stale/non-working. This should land in a silo by early tomorrow.

Second, Alfonso has pointed out that there may be additional network-manager changes required. His original testing performed on krillin/vivid, and as there's still a race between the disconnect from ofono, and NM changing the default route, it's still possible for an error to be thrown when NM configures the default route for the modem. When this happen, NM leaves the connection in an inconsistent state. When he tried the same scenario on krillin/RTM plus the patched ofono, it worked. I believe he may have just been lucky, and the disconnect happened before the default route logic ran. This is a guess, so we have some more work to in figuring this out.

As these fixes are critical enough to warrant a hot-fix to RTM, we're going to concentrate on it first, and then address vivid.

I think the issue is the the nm_system_apply_ip4_config () method always returns TRUE, ignoring any errors from nm_system_device_set_ip4_route (), which returns NULL to signify an error adding a route.

I've added a preliminary fix for this, by adding logic to check for NULL and immediately return FALSE. instead of continuing to iterate the through any remaining routes to be added. Note, this may need to be re-worked to ensure that route object references are all properly cleaned up, but it should suffice for testing the fix.

A version of this first attempt at patching can found in my PPA:

https://launchpad.net/~awe/+archive/ubuntu/ppa

Note, as it's a FIX for RTM, it's the 0.9.8 version.

Side note: I have created bug #1444314 to address a weird thing I have seen in the files attached in comments #7 and #8.

Please disregard comment #31, as it's incorrect and discusses the wrong routing code.

@Alfonso

So looking closer at NM 0.9.8, the routing is updated by nm-policy.c in its device_state_changed() function. It calls update_routing_and_dns() in several places, which in turn calls update_ip4_routing(), which in turn calls nm_system_replace_default_ip4_route(). Only the last function returns an error code, so if adding the default route fails, the error doesn't bubble up, and the system is left partially configured.

I hacked nm_system_replace_default_ip4_route() to return an error on it's third invocation, then rebooted the system with WiFi disabled. The first call to replace_default_ip4_route() happens when the mobile data connection is established on reboot. Next I activated WiFi and the phone connected to an AP, that's the second route call. Finally I disabled WiFi and this triggers the third route call which fails. At this point we have a connection that NM still thinks is connected, with an empty routing table.

Next I deactivated the context manually, and NM turned around and re-established the connection, so I *think* this proves that the scenario you described in comment #26 isn't happening with NM 0.9.8.

At this point, as changing the NM logic isn't super straight-forward, I would suggest that we don't attempt to patch NM for utopic-RTM at this point, unless someone else is able to prove for certain that NM can get wedged in a bad state when the routing configuration fails.

@Tony, ok, probably after applying the ofono patch it is difficult to have this happening in RTM so it is not worth the effort. But I think we should fix this in vivid / NM 0.9.10, if the routing logic is still the same.

@Alfonso

To be clear, I attempted to simulate the failure by hard-coding a route failure on the 3rd route switch ( when WiFi is toggled off, NM replaces the route with the modem's interface ). This definitely left the connection inconsistent with the actual routing table, but I next was able to deactivate the context from the command-line, and NM successfully restarted the connection. So again, I don't think the scenario you describe in comment #26 is possible on RTM, so we'll just release the ofono patch.

I will try to force the scenario on vivid and see if I can reproduce the problem you described with NM not being able to re-establish the connection after a route failure before disconnect.

Hey.

I'm using latest RTM and I still routinely reboot after leaving my
wifi network. Turning off wifi through the indicator doesn't help
(that's what I do to save battery life) and just keeps the phone
disconnected for hours.

On Tue, Apr 21, 2015 at 6:25 PM, Tony Espy <email address hidden> wrote:
> @Alfonso
>
> To be clear, I attempted to simulate the failure by hard-coding a route
> failure on the 3rd route switch ( when WiFi is toggled off, NM replaces
> the route with the modem's interface ). This definitely left the
> connection inconsistent with the actual routing table, but I next was
> able to deactivate the context from the command-line, and NM
> successfully restarted the connection. So again, I don't think the
> scenario you describe in comment #26 is possible on RTM, so we'll just
> release the ofono patch.
>
> I will try to force the scenario on vivid and see if I can reproduce the
> problem you described with NM not being able to re-establish the
> connection after a route failure before disconnect.
>
> --
> You received this bug notification because you are subscribed to a
> duplicate bug report (1419897).
> https://bugs.launchpad.net/bugs/1435328
>
> Title:
> Leaving Wifi does not connect to mobile carrier data (GSM)
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/canonical-devices-system-image/+bug/1435328/+subscriptions

@Alfonso

Regarding comment #26, to be clear, your exact scenario was this:

1. Install SIM with no data credit in slot1; this connection comes up, but any attempt to send/receive data fails
2. Activate WiFi, and wait till it associates with an AP
3. Disable WiFi
( this forces a disconnect of the modem, and the corresponding route configuration fails )

What I see from the logs is the Netlink failures, at which point I also see the NM device state go from activated to failed ( reason: ip-config-unavailable ). NM tries context1 ( 'Internet movil' ) again and it fails the next time due to 'no-secrets', which seems odd. It then moves on and tries context3 ( '___ubuntu custom internet apn' w/a null APN name ) and each time it fails with reason = 'modem-no-carrier'. This is odd, as I only ever see a single 'now in state registered' ( output by nm-modem-ofono.c::update_ofono_enabled() ), and never see the modem become unregistered ( which happens when Online, Attached or Powered go FALSE ).

Looking at the NM ofono activation code, although the error printed is "could not activate context, modem is not registered', the code actually just checks whether the modem is in REGISTERED state when it tries to connect. It's possible that the modem state is still CONNECTED, and somehow this didn't get reset to REGISTERED when the Netlink errors occurred? The modem state is only set back to REGISTERED in disconnect_done () and update_ofono_enabled (). Perhaps in this case, since the modem state isn't reset, the subsequent activation attempts will all fail.

If you can still reliably reproduce, could you turn on NM debug logging ( sudo nmcli general logging level debug ) and try to reproduce again and provide system logs. I will also try to force a modem disconnect ( via tinfoil wrapping ), and see what happens on vivid.

This theory also provides more weight to the thought that this is a vivid-only issue with NM, as the ofono modem state code is radically different in NM 0.9.8.

@Tony

No, I cannot reproduce anymore easily. That SIM has now credit, and even when it did not have the sequence in #26 was not happening any more after a couple of days.

What I interpret from syslog in #26 is:

1. Apr 14 07:48:54 ubuntu-phablet nm-dispatcher: Dispatching action 'down' for wlan0
-> We are out of reach of WiFi, wifi is in disconnect state for NM

2. Apr 14 07:48:56 ubuntu-phablet kernel: [ 58.774157][ccci/net] (1)CCMNI0 close
-> For some reason/coincidence immediately after wifi is disconnected the modem discovers the current cellular data context is not valid anymore and rild shuts down interface ccmni0. ofono still does not know this has happened, so it still considers the context is active.

3. Apr 14 07:48:56 ubuntu-phablet NetworkManager[1385]: <error> [1428997736.577516] [platform/nm-linux-platform.c:1714] add_object(): Netlink error adding 0.0.0.0/0 via 10.25.195.122 dev ccmni0 metric 1024 mss 0 src user: Object not found
-> all ofono properties show that ccnmi0 is up and running so NM tries to create a default route that uses ccmni0, but it fails because ccmni is actually down.

4. Apr 14 07:48:56 ubuntu-phablet ofonod[1842]: [0,UNSOL]< UNSOL_DATA_CALL_LIST_CHANGED {version=9,num=0}
-> rild notifies ofono about a change in the state of the IP contexts, ofono deactivates the context at that moment.

The "coincidence" between WiFi disconnecting and modem shuting down ccmni0 produces this unfortunate intermix of events. Usually NM would have not tried to establish routes right between ccmni0 being shut down by rild and ofono noticing that. But, anyway NM should be able to recover after the failure to set up routes and it should have tried to activate the context once ofono signals there has been a deactivation.

@Alfonso

So I agree that the modem disconnect seen when WiFi is toggled off is rare, that said, per my previous comment #38, it looks NM definitely gets in a state where it doesn't recover. I didn't see where you specified how long you waited after the disconnect; it's possible that this is a permutation of bug #1418077, but as I didn't see a state message showing the modem transition to "searching", I don't think this is the case.

This may just be a timing issue. In this case, the route failures cause the connection failure, which is different than a connection failing due to the context being de-activated. Maybe it's this case which leaves the modem in 'connected' state?

I will try my force-route failure experiment on krillin/RTM and see if it triggers the same scenario.

Also, this may be related to the FM failures seen in RTM on arale and mako; see bug #1445080 for details.

This bug was fixed in the package ofono - 1.12.bzr6894+15.04.20150415~rtm-0ubuntu1

---------------
ofono (1.12.bzr6894+15.04.20150415~rtm-0ubuntu1) 14.09; urgency=medium

  [ Tony Espy ]
  * rilmodem/gprs-context.c: if data call list is empty, disconnect (LP: #1435328)
    If a DATA_CALL_LIST_CHANGED is received with an
    empty call list, and the gprs-context is not IDLE,
    disconnect the active data call.
 -- CI Train Bot <email address hidden> Wed, 15 Apr 2015 13:27:00 +0000

I tried to ./configure the package with the fix, giving the parameters specified in the readme file, but still I'm getting no such file or directory error. ( I did install GCC , plus the glib and d-bus libraries as asked).

Anything else I maybe doing wrong?

Thanks and sorry if there's something obvious that I'm missing.

@eotakos

Providing instructions for how to build the package from scratch are outside of the scope of this bug. You'd need to install all of the build dependencies for ofono, most of which aren't available from the default root filesystem. The only safe way to do this is to install a chroot on your device, but again this is beyond the scope of this bug.

I think you're much better off holding off for a few more days as the pending fix is currently staged, and has recently been approved by QA. It should hopefully land *soon*, although I can't give you an exact date.

If you've made your device writable, and wish to install the package directly, you could use apt to install it from the RTM archive, however doing so, could prevent future updates from working properly.

You could in theory extract the binary ( ofonod ) from the package, and run it in the foreground in /tmp, however again I think you're better off waiting for the update. The version of ofono with the fix is: 1.12.bzr6894+15.04.20150415~rtm-0ubuntu1.

Marked as FixReleased for vivid, as a new version has landed in our new overlay PPA: 1.12.bzr6894+15.04.20150424.1-0ubuntu1.