Closed Bug 999363 Opened 6 years ago Closed 6 years ago

[tarako] unable to resume data connection for SIM2 after turning off WIFI

Categories

(Firefox OS Graveyard :: Vendcom, defect)

Product:
Firefox OS Graveyard
Component:
Vendcom
Platform:
Other
Other
Type:
defect
Priority:
Not set

Tracking

(blocking-b2g:1.3T+, b2g-v1.3T verified)

Status:
VERIFIED FIXED
Project Flags:
blocking-b2g 1.3T+
Tracking Flags:
Tracking Status
b2g-v1.3T --- verified

People

(Reporter: angelc04, Assigned: xinhe.yan)

References

Details

(Whiteboard: [ETA: 4/29] [POVB][sprd303780])

Attachments

(2 files, 1 obsolete file)

adb logcat
875.86 KB, text/x-log
Details
adblog_enabled wifi debug
515.85 KB, text/plain
Details
Attached file adb logcat (obsolete) — 
Steps to reproduce
-----------------------------------------------------------------------
1. change data SIM to SIM2 and Enable Data connection
   there should be data connection icon for SIM 2 on status bar.
2. Go to Settings -> WIFI, enable WIFI and connect to a AP
3. Turn off WIFI, and wait for a while
   --> data connection icon for SIM 2 could not resume.
4. Try to access some website
   --> data connection is unavailable.

Attached adb log. test starts: 04-22 18:31:48.980

Test build
-----------------------------------------------------------------------
Gaia      3f1d8332d127f1d6bc0fdbb08146ce1deb0efbc0
Gecko     https://hg.mozilla.org/releases/mozilla-b2g28_v1_3t/rev/5da76152c2bd
BuildID   20140421164001
Version   28.1
ro.build.version.incremental=eng.cltbld.20140421.201353
ro.build.date=Mon Apr 21 20:14:01 EDT 2014
We should check to see if this affects other DSDS devices on 1.3.
Keywords: qawanted
Eric - Can you check this?
Flags: needinfo?(echang)
v1.3 on Fugu works fine.

Gaia      fb2b8e25e8095a5db49b5eb68c74b49f180605d4    
Gecko     1949f0e7ea2f542e91573f084639ee6decf3f0b2    
BuildID   20140423110312                  
Version   28.0                            
ro.build.version.incremental=eng.enpei.20140226.104   
420
Flags: needinfo?(echang)
Keywords: qawanted
Seems like this is a basic use case for DSDS on Tarako not working here. STR is relatively straightforward as well - enable data connection for SIM2, connect to wifi, disconnect later - which should result in a data connection being reestablished, but that's not happening here...
blocking-b2g: --- → 1.3T?
blocking-b2g: 1.3T? → 1.3T+
Component: General → RIL
Hi Peipei:
 Could you please enable ril releated log for us to check?

STR to enable log:
1 adb pull /system/b2g/defaults/pref/user.js /tmp
2 Modify the value of ril.debugging.enabled to true.
      ie: pref("ril.debugging.enabled", true);
3 adb remount
3 adb push /tmp/user.js /system/b2g/defaults/pref/
4 adb reboot


I only see below which means RIL log is disabled.

wifi_data_2.log:254: 04-22 18:30:10.980    84    84 I Gecko   : -*- RadioInterfaceLayer: 2 interfaces
wifi_data_2.log:1055: 04-22 18:30:23.580    84    84 I Gecko   : -*- RadioInterface[0]: _lastKnownHomeNetwork: 460-01
wifi_data_2.log:1064: 04-22 18:30:25.050    84    84 I Gecko   : -*- RadioInterface[1]: _lastKnownHomeNetwork: 460-01
wifi_data_2.log:1083: 04-22 18:30:27.840    84    84 I Gecko   : -*- RadioInterface[1]: _lastKnownHomeNetwork: 460-01
wifi_data_2.log:1152: 04-22 18:30:40.090    84    84 I Gecko   : -*- RadioInterface[1]: _lastKnownHomeNetwork: 460-01
wifi_data_2.log:1153: 04-22 18:30:40.160    84    84 I Gecko   : -*- RadioInterface[0]: _lastKnownHomeNetwork: 460-01
Found 6 matches for "radiointerface".
Flags: needinfo?(pcheng)
Add Vincent to be aware of this issue.
Attached file adb logcat — 
Please see the new log. Test starts: 04-24 03:59:27.480
Attachment #8410175 - Attachment is obsolete: true
Flags: needinfo?(pcheng)
Per peipei's time stamp, it looks wifi is sitll alive that result in not data connection setup request. 


04-24 04:00:30.380 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
04-24 04:00:35.260 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
04-24 04:00:38.380 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
04-24 04:00:44.850 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
04-24 04:00:53.570 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
04-24 04:00:59.280 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
04-24 04:01:08.380 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
04-24 04:01:26.410 I/Gecko   (   84): -*- RadioInterface[1]: Don't connect data call when Wifi is connected.
More details:
After disable wifi, WIFI status on notification tray bar is disabled and data connection status on tray bar is enabled. 
However, the data connection icon on SIM2 does not show up on status bar. Also I could not access any website using Browser.
Hi Xinhe,

In normal case, after WIFI driver receive a TERMINATE command, wpa_supplicant can do status changing like the following log.
=========================================================================================================
04-23 13:06:22.948    84   309 W WifiHW  : wifi_command: TERMINATE
04-23 13:06:22.948   770   770 D wpa_supplicant: wpa_driver_nl80211_disconnect(addr=08:60:6e:22:ae:80 reason_code=3)
...
04-23 13:06:23.208   770   770 D wpa_supplicant:    addr=08:60:6e:22:ae:80
04-23 13:06:23.228    84   309 D DHCP    : socket() failed: Address family not supported by protocol
04-23 13:06:23.248   770   770 D wpa_supplicant: wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
04-23 13:06:23.248   770   770 D wpa_supplicant: netlink: Operstate: linkmode=-1, operstate=5
04-23 13:06:23.258   770   770 D wpa_supplicant: EAPOL: External notification - portEnabled=0
04-23 13:06:23.258   770   770 D wpa_supplicant: EAPOL: SUPP_PAE entering state DISCONNECTED
...
===========================================================================================================

However, from https://bugzilla.mozilla.org/attachment.cgi?id=8411546, wpa_supplicant doesn't do status changing.
============================================================================================================
04-24 04:00:42.590 W/WifiHW  (   84): wifi_command: TERMINATE
04-24 04:00:42.590 D/wpa_supplicant(  505): wpa_driver_nl80211_disconnect(addr=00:24:6c:08:99:d0 reason_code=3)
...
04-24 04:00:42.780 D/wpa_supplicant(  505):    addr=00:24:6c:08:99:d0
04-24 04:00:42.790 D/DHCP    (   84): failed to set prefixLength 0: Cannot assign requested address
04-24 04:00:42.820 D/wpa_supplicant(  505): wpa_driver_nl80211_set_operstate: operstate 1->0 (DORMANT)
...
============================================================================================================
Can you please check if there are something wrong?
Flags: needinfo?(xinhe.yan)
PeiPei, can you please also enable wifi log in gecko? sorry not to mention this before.
Flags: needinfo?(pcheng)
Assignee: nobody → kchang
It seems WIFI has problem. I tried to enable WIFI-> diable WIFI -> enable WIFI fr several times,　WIFI cannot be turned on. It sounds like ug 999388. I guess this is similiar to this case. 
I will try to reproduce the SIM data connection case and attach log later.
Flags: needinfo?(pcheng)
Whiteboard: [ETA: 4/29]
Attached is the log with pref('wifi.debugging.enabled', true).

Test starts: 04-24 11:09:25.470
I think the root cause should be Bug 999388. Not sure if you could help to apply the patch in Bug 999388 and verify again ?
According to log, https://bugzilla.mozilla.org/attachment.cgi?id=8411729.
I think there are something wrong in RILC or modem.
1. RILC or modem takes more than 7s to finish the procedure of deactivating data call.
04-24 11:10:02.300 I/Gecko   (   84): -*- RadioInterface[1]: Disconnect data call when Wifi is connected.
04-24 11:10:02.300 I/Gecko   (   84): -*- RILNetworkInterface[1:3]: Going to disconnet data connection 1
04-24 11:10:02.310 I/Gecko   (   84): RIL Worker: [1] Received chrome message {"cid":"1","reason":0,"rilMessageClientId":1,"rilMessageToken":33,"rilMessageType":"deactivateDataCall"}
...
04-24 11:10:10.530 I/Gecko   (   84): RIL Worker: [1] Handling parcel as REQUEST_DEACTIVATE_DATA_CALL
04-24 11:10:10.530 I/Gecko   (   84): RIL Worker: Next parcel size unknown, going to sleep.
04-24 11:10:10.540 I/Gecko   (   84): -*- RadioInterface[1]: Received message from worker: {"status":0,"suggestedRetryTime":-1,"cid":"1","active":1,"type":"IP","ifname":"veth0","ipaddr":"10.7.185.109","dns":["123.123.123.123","123.123.123.124"],"gw":"10.7.185.109","state":-1,"radioTech":2,"apn":"3gnet","chappap":3,"pdptype":"IP","rilMessageType":"datacallstatechange","rilMessageClientId":1}

2. Afterwords, the procedure of setting up data call receives datacallerror. And it is never able to recover... 
04-24 11:11:01.000 I/Gecko   (   84): RIL Worker: [1] Handling parcel as REQUEST_SETUP_DATA_CALL
04-24 11:11:01.000 I/Gecko   (   84): RIL Worker: Next parcel size unknown, going to sleep.
04-24 11:11:01.000 I/Gecko   (   84): -*- RadioInterface[1]: Received message from worker: {"radioTech":2,"apn":"3gnet","chappap":3,"pdptype":"IP","rilMessageClientId":1,"rilMessageType":"datacallerror","rilRequestType":27,"rilRequestError":2,"errorMsg":"GenericFailure"}
04-24 11:11:01.000 I/Gecko   (  440): -*- RILContentHelper: Received message 'RIL:DataError': {"clientId":1,"data":{"radioTech":2,"apn":"3gnet","chappap":3,"pdptype":"IP","rilMessageClientId":1,"rilMessageType":"datacallerror","rilRequestType":27,"rilRequestError":2,"errorMsg":"GenericFailure"}}
04-24 11:11:01.000 I/Gecko   (   84): -*- RILNetworkInterface[1:1]: Data call error on APN: 3gnet
04-24 11:11:01.010 I/Gecko   (   84): -*- RILNetworkInterface[1:1]: Data call - APN Connection Retry Timer (secs-counter): 395-8
04-24 11:11:01.010 I/Gecko   (   84): -*- RILContentHelper: Received message 'RIL:DataError': {"clientId":1,"data":{"radioTech":2,"apn":"3gnet","chappap":3,"pdptype":"IP","rilMessageClientId":1,"rilMessageType":"datacallerror","rilRequestType":27,"rilRequestError":2,"errorMsg":"GenericFailure"}}

While analyzing the log, I found the other issue and filed bug 1001275 for tracking it. The issue is that we should not setup data call during disconnecting stage. Because bug 1001275 is always happened for all platforms and the procedure of setting up data call works okay now, I don't think it is the root cause of this bug. Reassign this bug to partner for fixing error of setting up data call. And we will focus on fixing bug 1001275.
Assignee: kchang → sam.hua
Component: RIL → Vendcom
Flags: needinfo?(xinhe.yan)
Whiteboard: [ETA: 4/29] → [ETA: 4/29] [POVB]
(In reply to Vincent Chang[:vchang] from comment #14)
> I think the root cause should be Bug 999388. Not sure if you could help to
> apply the patch in Bug 999388 and verify again ?
This bug can be reproduce after apply patch in Bug 999388.
Whiteboard: [ETA: 4/29] [POVB] → [ETA: 4/29] [POVB][sprd303780]
Assignee: sam.hua → xinhe.yan
Please help to reproduce this issue after we land this patch.
We can't reproduce it now.

hardware/libhardware_legacy

commit 6e5aa4d4e5b5ba66ce3db24806a4b4017560801e
Author: Xinhe Yan <xinhe.yan@spreadtrum.com>
Date:   Sat May 3 14:54:30 2014 +0800

    Bug #305892 sleep one second to wait gecko receive CTRL-EVENT-TERMINATING
    
    [bug number  ] 305892
    [root cause  ]
    [changes     ]
    [side effects] unknown
    [self test   ] sp6821a
    [reviewers   ]
    
    Change-Id: I7dd0a01d02cf9a2dcac26c7fb33b9910aa23ff88
I'm unable to reproduce this issue following original reporter's repro steps. After turning off Wifi, data connection correctly resumed for Sim2.

Tested on:
Device: Tarako 1.3T MOZ
BuildID: 20140505173556
Gaia: 48372ff88c712468a77a6f14a97f9978ee56eade
Gecko: 78015cc18d1f
Version: 28.1
Firmware Version: sp6821a_gonk4.0_4-29
Keywords: qawanted
Status: NEW → RESOLVED
Closed: 6 years ago
Resolution: --- → FIXED
Verified fixed on the Tarako v1.3T MOZ ril.

Environmental Variables:
Device: Tarako 1.3T
BuildID: 20140602014001
Gaia: 335486c42498fa7a93c21e4d6121199728602ab8
Gecko: 55e4d83019e5
Version: 28.1
Firmware Version: SP6821a-Gonk-4.0-4-29

Data reenables as expected.
Status: RESOLVED → VERIFIED
status-b2g-v1.3T: fixed → verified
You need to log in before you can comment on or make changes to this bug.