[krillin] disable WiFi, Mobile Data not available

[Dave Morley]

STEPS:
1. Install RTM88 on krillin
2. Use the system a litlle on wifi
3. Pull down the indicator network
4. Disable Wifi

EXPECTED:
I expect the system to seemless flip over to using 3g

ACTUAL:
I got no page (see screen shot) I tried pinging google and got ping: unknown host google.com

ip route gave no feedback
phablet@ubuntu-phablet:~$ nmcli dev
DEVICE TYPE STATE
/ril_1 gsm disconnected
/ril_0 gsm connected
wlan0 802-11-wireless unavailable

Devices is correct.

The debug.txt in comment #3 clearly shows that mobile data is connected via the list-modems output and list-contexts output. This output also agrees with the nmcli output which shows /ril_0 as connected. The smoking gun here looks to be the routing table, which is empty.

[Launchpad Janitor (janitor)]

Status changed to 'Confirmed' because the bug affects multiple users.

[Niklas Wenzel (nikwen)]

I've seen the same on mako (ubuntu-rtm/devel image #3).

[Michał Sawicz (saviq)]

This sounds a lot like bug #1357321 no?

[Michał Sawicz (saviq)]

Ah no, scratch that.

[Tony Espy (awe)]

So taking a look at the sylog, I see WLAN blocked, then I see a failure when NM tries to re-configure the routing table:

Oct 7 15:14:44 ubuntu-phablet URfkill[1064]: Setting WLAN devices to blocked
Oct 7 15:14:44 ubuntu-phablet URfkill[1064]: Setting WLAN to blocked
Oct 7 15:14:18 ubuntu-phablet wpa_supplicant[1986]: message repeated 115 times: [ wlan0: CTRL-EVENT-SCAN-STARTED ]
Oct 7 15:14:44 ubuntu-phablet wpa_supplicant[1986]: wlan0: CTRL-EVENT-DISCONNECTED bssid=64:70:02:39:0b:1d reason=0 locally_generated=1
Oct 7 15:14:44 ubuntu-phablet dhclient: receive_packet failed on wlan0: Network is down
Oct 7 15:14:44 ubuntu-phablet wpa_supplicant[1986]: rfkill: WLAN soft blocked
Oct 7 15:14:44 ubuntu-phablet kernel: [21417.062848] (1)[6069:kworker/1:1]cfg80211: Calling CRDA to update world regulatory domain
Oct 7 15:14:44 ubuntu-phablet URfkill[1064]: device_changed_cb: phy0
Oct 7 15:14:44 ubuntu-phablet URfkill[1064]: killswitch state: KILLSWITCH_STATE_UNBLOCKED new_state: KILLSWITCH_STATE_SOFT_BLOCKED
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <info> (wlan0): supplicant interface state: completed -> disabled
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <info> (wlan0): device state change: activated -> unavailable (reason 'none') [100 20 0]
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <info> (wlan0): deactivating device (reason 'none') [0]
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 30305
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <error> [1412694884.484495] [nm-system.c:965] add_ip4_route_to_gateway(): (ccmni0): failed to add I\
Pv4 route to gateway (-12)
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <info> Policy set '/234308403223936/context1' (ccmni0) as default for IPv4 routing and DNS.
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <info> Writing DNS information to /sbin/resolvconf
Oct 7 15:14:44 ubuntu-phablet dnsmasq[7722]: setting upstream servers from DBus
Oct 7 15:14:44 ubuntu-phablet dnsmasq[7722]: using nameserver 149.254.230.7#53
Oct 7 15:14:44 ubuntu-phablet dnsmasq[7722]: using nameserver 149.254.192.126#53
Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <info> WiFi now disabled by radio killswitch

[Tony Espy (awe)]

This looks like the culprit, according to Mathieu, -12 indicates object-not-found from libnl ( netlink ):

Oct 7 15:14:44 ubuntu-phablet NetworkManager[1581]: <error> [1412694884.484495] [nm-system.c:965] add_ip4_route_to_gateway(): (ccmni0): failed to add IPv4 route to gateway (-12)

[Tony Espy (awe)]

On other interesting point is that settings for the mobile data context are a bit odd in that the gateway and address returned from the operator are both the same:

Interface=ccmni0 DomainNameServers=149.254.230.7,149.254.192.126, Gateway=10.129.20.112 Address=10.129.20.112 Netmask=255.255.255.0 Method=static

This doesn't appear to cause problems when the mobile data connection is initially configured, however for some reason when WiFi is disabled it is causing an issue.

On initial configuration, we setup up the route for mobile data and then set it as default.

When WiFi connection, we setup a route for WiFi, then make it the default route ( ie. we don't remove the mobile data route ).

When WiFi is again disabled, we remove the WiFi route, and attempt to set the mobile data route as the default again. It's during this logic that the failure occurs.

[Mathieu Trudel-Lapierre (cyphermox)]

I'm seeing this peculiar message in syslog:
Oct 7 13:22:03 ubuntu-phablet kernel: [14655.999891] (0)[1956:rild][ccci/net] (1)CCMNI0 close

I'm not sure why rild decides it suddently wants to turn ccmni0 off; but that could well explain why there is no ip address on the interface, and no routes to support setting the default gateway back to mobile later on.

I don't think it's requested by NM; because there is earlier evidence in the same log that when NM asks for it; you instead see a message like:
(0)[1956:NetworkManager][ccci/net] (1)CCMNI0 close

Along with NM's own logs for the disconnection; but I'll keep looking at that side anyway.

Reassigning to Tony for now, until we can verify if it's rild that is doing something it shouldn't.

[Tony Espy (awe)]

Here's a summary:

EE Internet connects @ 9:45AM
WiFI connects @ 9:52 ( +7m )
ccmni0 closed @ 13:22 ( +3:30 )
WiFi disabled @ 15:14 ( +5:22 )

My theory is that rild closes the connection because it's been idle for 3:30, which seems reasonable. That said, rild has a standard mechanism to notify when a data call is closed. We should be seeing a RIL_UNSOL_DATA_CALL_LIST_CHANGED message from rild, and the call representing the data call should either be present with active=0, or not present in the list. Either of these conditions will cause rilmodem to notify the ofono core that the context has been deactivated.

[Tony Espy (awe)]

I tried to reproduce this on krillin / rtm-proposed #120.

I have a T-Mobile SIM in slot 1, and an ATT SIM in slot 2.

I verified that mobile data was connected using slot 1, and then associated with an AP.

I left the phone alone for 4+ hours, and the mobile data connection seems to still be up & running ( although WiFi is still set as the default route ).

There must be some condition ( possibly on the server side ) that triggers the modem to disconnect.

[Tony Espy (awe)]

Here's some instructions for how to get some debug traces from ofono:

As root:

1. stop ofono
2. edit the file /etc/init/ofono.override and add:

 - env OFONO_RIL_TRACE=y
   ( right before the ofono command line )

  - add "-d drivers/rilmodem/gprs-context.c" to the ofono command line

3. disable WiFi & reboot

4. ensure that the mobile data is connected before enabling WiFi

5. if/when the problem occurs, please grab syslog and attach to the bug

It's not necessary to disable WiFi, it just makes the problem more obvious.

Note - the clear signs that the problem has been reproduced include:

 - the output of list-contexts shows one of the contexts is connected ( ie. it shows IP Settings )

 - the output of 'netstat -rn' will show no routes

[Tony Espy (awe)]

The current theory is that some event is causing rild to disconnect/destroy the GPRS device, and that this event doesn't generate the proper unsolicited event to ofono.

Unfortunately, we haven't yet been able to reliably reproduce this with the latest images.

After discussing with Dave, he's described that this usually happens to him when he leaves his flat via an elevator which when between floors, causes signal to be lost. That said, we have tested forcing modem disconnects in the past on krillin, and they worked as expected. It's possible that the disconnect is operator induced...

That said, I've added an incomplete network-manager task to the bug as we once we better understand this bug, it will probably be wise to add logic to network-manager to mark the connection as invalid when the GPRS device disappears. This will make our stack more robust.

[Tony Espy (awe)]

Changed ofono status to Incomplete as well until we're able to reliably reproduce.

[Dave Morley (davmor2)]

Tony will look at this tomorrow, I'm reflashing the phone too often today. I do have it on my schedule though :)

[Dave Morley (davmor2)]

Everytime I add the debug stuff to this it doesn't seem to die I will try it again tonight and see if dies over the weekend and leave it on the one image

[Tony Espy (awe)]

@Dave

Can you still reproduce with a stock RTM image ( ie. no debug options configured )?

[Launchpad Janitor (janitor)]

[Expired for network-manager (Ubuntu) because there has been no activity for 60 days.]

[Tony Espy (awe)]

Updated status of the ofono (Ubuntu) task to Invalid. The network-manager task had already gone from Incomplete to Expired, but there doesn't seem to be any way for me to mark the ofono (Ubuntu) task Expired.

@Dave

If you can re-create still, please feel free to re-open.

[Alfonso Sanchez-Beato (alfonsosanchezbeato)]

Reproduced. syslog attached. Steps:

1. Start the phone
2. Check that you have network connectivity
3. Disable WiFi
4. Check that you cannot connect to network although cellular data is ON.

The mobile context was up, cnmi0 was up, phone was attached, but "ip route" showed nothing.

Adding a default route for ccmni0 made "ping 8.8.8.8" work.

Recent research has shown that rild in krillin sets ups ccmni0, but does nothing with routes, so this points to NM, as it is the one that should add the route.

$ system-image-cli -i
current build number: 270
device name: krillin
channel: ubuntu-touch/ubuntu-rtm/14.09-proposed
last update: 2015-04-14 16:00:29
version version: 270
version ubuntu: 20150410.1
version device: 20150408-4f14058
version custom: 20150409-665-29-206