Analysis of Nexus One’s 3G Issue

I have been try to figure out Nexus One’s 3G conductibility issues I have been experiencing.

Observation: Occasionally, data connection is disrupted randomly, causing application trying to connect to network reports timeout. This continues for few seconds to few minutes, depending on network access being attempted. (to the device to be able to recover, data transmission needs to cease completely.) Up arrow (send) indicator is lit while no activity is observed in down arrow. Data mode stays as “UMTS” while this is observed.

Hypothesis: The system is having problem transitioning to HSDPA from UMTS or PDP (Packet Data Protocol) context may be failing.

The following experiments are conducted. They are conducted after resetting the device to factory default.

Experiment 1: Radio band

I modified radio band to USA and other settings.

Result:

Setting any region in radio band did not eliminate the issue.

Experiment 2: APN reset

I have reset APN setting to factory default.

Result:

It initially thought to have improved the issue, however did not eliminated issue. Perception of improved connectivity may have came from randomness of the issue.

Experiment 3: Keeping alive using PING packet

Using ConnectBot, I have gone into console and set it to send out ICMP echo (ping) packet every five second.

Result:

This substantially increased availability of data by fixating phone data mode to HSDPA. However, this may be violation of T-mobile’s term of use, and is not deemed to be permanent solution.

Experiment 4: Analysis of the log

FRF72 allowed extraction of radio log, and analysis of the log could be conducted.

Result:

It was found that when the device is affected by this issue, the following pattern is observed in the log.

Whole lifecycle of the issue would leave such log as the following. (in the below, portion highlighted in red is logged during time of outage, and blue when the connection is reestablished.)

06-21 05:01:01.810 D/RILJ (162)[0797]> REQUEST_SET_LOCATION_UPDATES: true
06-21 05:01:01.830 D/RILJ (162)[0797]< REQUEST_SET_LOCATION_UPDATES
06-21 05:01:01.830 D/RILJ (162)[0798]> REGISTRATION_STATE
06-21 05:01:01.850 D/RILJ (162)[0798]< REGISTRATION_STATE {1, A1B5, 01A85AC1, 3, null, null, null, null, null, null, null, null, null, null}
06-21 05:01:01.850 D/RILJ (162)[0799]> REQUEST_SET_LOCATION_UPDATES: false
06-21 05:01:01.860 D/RILJ (162)[0799]< REQUEST_SET_LOCATION_UPDATES
06-21 05:01:01.940 D/RILJ (162)[0800]> REQUEST_GET_NEIGHBORING_CELL_IDS
06-21 05:01:01.950 D/RILJ (162)[0800]< REQUEST_GET_NEIGHBORING_CELL_IDS
06-21 05:01:07.340 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:07.340 D/RILJ (162)[0801]> DATA_CALL_LIST
06-21 05:01:07.350 D/RILJ (162)[0801]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:07.350 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=2999942 obj=android.os.AsyncResult@449eb398 }
06-21 05:01:12.350 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:12.350 D/RILJ (162)[0802]> DATA_CALL_LIST
06-21 05:01:12.350 D/RILJ (162)[0802]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:12.350 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3004945 obj=android.os.AsyncResult@449bba38 }
06-21 05:01:17.350 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:17.350 D/RILJ (162)[0803]> DATA_CALL_LIST
06-21 05:01:17.360 D/RILJ (162)[0803]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:17.360 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3009954 obj=android.os.AsyncResult@449765f8 }
06-21 05:01:22.360 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:22.360 D/RILJ (162)[0804]> DATA_CALL_LIST
06-21 05:01:22.360 D/RILJ (162)[0804]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:22.370 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3014959 obj=android.os.AsyncResult@449ecb80 }
06-21 05:01:27.367 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:27.367 D/RILJ (162)[0805]> DATA_CALL_LIST
06-21 05:01:27.370 D/RILJ (162)[0805]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:27.370 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3019965 obj=android.os.AsyncResult@44a3e798 }
06-21 05:01:32.373 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:32.373 D/RILJ (162)[0806]> DATA_CALL_LIST
06-21 05:01:32.380 D/RILJ (162)[0806]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:32.380 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3024970 obj=android.os.AsyncResult@44a389b0 }
06-21 05:01:37.380 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:37.380 D/RILJ (162)[0807]> DATA_CALL_LIST
06-21 05:01:37.390 D/RILJ (162)[0807]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:37.390 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3029985 obj=android.os.AsyncResult@449f31a8 }
06-21 05:01:42.400 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:42.400 D/RILJ (162)[0808]> DATA_CALL_LIST
06-21 05:01:42.400 D/RILJ (162)[0808]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:42.400 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3034998 obj=android.os.AsyncResult@449b8908 }
06-21 05:01:47.400 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:47.400 D/RILJ (162)[0809]> DATA_CALL_LIST
06-21 05:01:47.410 D/RILJ (162)[0809]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:47.410 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3040003 obj=android.os.AsyncResult@449d1680 }
06-21 05:01:51.930 D/RILJ (162)[0810]> REQUEST_SET_LOCATION_UPDATES: true
06-21 05:01:51.990 D/RILJ (162)[0810]< REQUEST_SET_LOCATION_UPDATES
06-21 05:01:51.990 D/RILJ (162)[0811]> REGISTRATION_STATE
06-21 05:01:52.020 D/RILJ (162)[0811]< REGISTRATION_STATE {1, A1B5, 01A85AC1, 3, null, null, null, null, null, null, null, null, null, null}
06-21 05:01:52.020 D/RILJ (162)[0812]> REQUEST_SET_LOCATION_UPDATES: false
06-21 05:01:52.030 D/RILJ (162)[0813]> REQUEST_GET_NEIGHBORING_CELL_IDS
06-21 05:01:52.030 D/RILJ (162)[0812]< REQUEST_SET_LOCATION_UPDATES
06-21 05:01:52.040 D/RILJ (162)[0813]< REQUEST_GET_NEIGHBORING_CELL_IDS
06-21 05:01:52.400 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:52.400 D/RILJ (162)[0814]> DATA_CALL_LIST
06-21 05:01:52.410 D/RILJ (162)[0814]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:52.410 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3045005 obj=android.os.AsyncResult@44a1a028 }
06-21 05:01:57.410 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:01:57.410 D/RILJ (162)[0815]> DATA_CALL_LIST
06-21 05:01:57.410 D/RILJ (162)[0815]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:01:57.410 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3050009 obj=android.os.AsyncResult@44a107b8 }
06-21 05:02:02.420 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:02:02.420 D/RILJ (162)[0816]> DATA_CALL_LIST
06-21 05:02:02.430 D/RILJ (162)[0816]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:02:02.430 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3055026 obj=android.os.AsyncResult@449f9508 }
06-21 05:02:07.430 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:02:07.430 D/RILJ (162)[0817]> DATA_CALL_LIST
06-21 05:02:07.430 D/RILJ (162)[0817]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:02:07.440 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3060029 obj=android.os.AsyncResult@44972458 }
06-21 05:02:12.430 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:02:12.430 D/RILJ (162)[0818]> DATA_CALL_LIST
06-21 05:02:12.440 D/RILJ (162)[0818]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:02:12.440 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3065033 obj=android.os.AsyncResult@4495b7b8 }
06-21 05:02:17.441 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:02:17.441 D/RILJ (162)[0819]> DATA_CALL_LIST
06-21 05:02:17.441 D/RILJ (162)[0819]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:02:17.450 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3070039 obj=android.os.AsyncResult@44997de8 }
06-21 05:02:22.440 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:02:22.440 D/RILJ (162)[0820]> DATA_CALL_LIST
06-21 05:02:22.450 D/RILJ (162)[0820]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:02:22.450 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3075043 obj=android.os.AsyncResult@449f0108 }
06-21 05:02:27.451 D/GSM (162)[GsmDataConnectionTracker] no DATAIN in a while; polling PDP
06-21 05:02:27.451 D/RILJ (162)[0821]> DATA_CALL_LIST
06-21 05:02:27.451 D/RILJ (162)[0821]< DATA_CALL_LIST [DataCallState: { cid: 1, active: 2, type: IP, apn: epc.tmobile.com, address: 25.128.84.145 }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }, DataCallState: { cid: -1, active: 0, type: , apn: , address: }]
06-21 05:02:27.451 D/GSM (162)GSMDataConnTrack handleMessage { what=11 when=3080049 obj=android.os.AsyncResult@449e72c0 }
06-21 05:02:27.640 D/RILJ (162)[UNSL]< UNSOL_RESPONSE_NETWORK_STATE_CHANGED
06-21 05:02:27.640 D/RILJ (162)[0822]> OPERATOR
06-21 05:02:27.640 D/RILJ (162)[0823]> GPRS_REGISTRATION_STATE
06-21 05:02:27.640 D/RILJ (162)[0824]> REGISTRATION_STATE
06-21 05:02:27.650 D/RILJ (162)[0822]< OPERATOR {T-Mobile, T-Mobile, 310260} 06-21 05:02:27.650 D/RILJ (162)[0825]> QUERY_NETWORK_SELECTION_MODE
06-21 05:02:27.670 D/RILJ (162)[0823]< GPRS_REGISTRATION_STATE {1, null, null, 9}
06-21 05:02:27.690 D/RILJ (162)[0824]< REGISTRATION_STATE {1, A1B5, 01A85AC1, 9, null, null, null, null, null, null, null, null, null, null}
06-21 05:02:27.700 D/RILJ (162)[0825]< QUERY_NETWORK_SELECTION_MODE {0}
06-21 05:02:27.700 D/GSM (162)Poll ServiceState done: oldSS=[0 home T-Mobile T-Mobile 310260 UMTS CSS not supported -1 -1RoamInd: -1DefRoamInd: -1EmergOnly: false] newSS=[0 home T-Mobile T-Mobile 310260 HSDPA CSS not supported -1 -1RoamInd: -1DefRoamInd: -1EmergOnly: false] oldGprs=0 newGprs=0 oldType=UMTS newType=HSDPA
06-21 05:02:27.710 D/GSM (162)RAT switched UMTS -> HSDPA at cell 27810497

Further analysis of the log and the sourcecode revealed that this is emitted by Android sourcecode:
GsmDataConnectionTracker.java

Line 899 emits this error when WatchDog determines PDP context to be down when excessive number of outgoing packets are detected while there is no incoming packet.

Conclusion:

While it is still high speculative, the issue may be caused by failure of obtaining PDP context. Issue may be caused by radio not properly recovering its PDP context when it is lost. It is worthwhile to note that the code never progresses to line 909 to display recovery attempt.

Currently, this issue is discussed in the forum at AndroidSPIN and is being forwarded to HTC as well.