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.

Working Around Nexus One’s 3G Issues

There seems to be several issue regarding 3G connection issue on Nexus One.

Issue range from fluctuation of signal strength depending on where you hold your phone, and others.

One issue I am experiencing, which some other people report is the fact that Nexus One causes network error while up arrow indicator was staying on.

This has been reported on several of help forums.

Investigating issue myself, it because evident that this problem was happening when the device is transitioning from UMTS to HSDPA.

I have observed that normally, the device claim it is on UMTS connection. But at the moment that something try to access the network, this mode changes to HSDPA. After few seconds of network inactivity, this mode turns back to UMTS.

Looking at pattern, there are quite common chance that this transition do not go smooth, and the device would stuck with UMTS, unable to send or receive data. Therefore, data is constantly resent, eventually timing out causing error. Problem is that timeout can get very long when applications are trying to gain access to the network connection, as it appears to be only chance it can reset is when the application attempts to transition to HSDPA from UMTS, after connection attempt is ceased. (Note this problem do not happen if you are on 2G (EDGE/GPRS) connection. Also there were some story that some people have their phone in HSDPA mode permanently. (perhaps they have very strong 3G signal?)

I found simple workaround to this issue. My idea was, if this is caused by failure of transition from UMTS to HSDPA, why not just force the device to be on HSDPA mode?

I downloaded the piece of program called ConnectBot, which is terminal emulator program. There is way to connect to local console using program. You’d login to your local console, then type in the following.

ping -i 5 1.1.1.1 &

Where 1.1.1.1 is some IP address. This particular command line will send out ping packet every five seconds. Now this IP address doesn’t have to be reachable. It is actually beneficial if it is not, as you only need to send out some packet and you don’t care about any reply. After you type in this command line (do not forget “&”) press enter, and then open up a menu and disconnect. This ping command will be running in background.

Alternatively you could create text file containing the command line above, then execute using the following command.

sh ./script &

Because it is merely running the program in the background, if you restart your phone, you will do this process again.

Trying this, now my phone stays on HSDPA all the time, and seems to be stable now. I had some concern about impact on battery life this may cause, but it seems to be minimal.

Please do note that this may potentially violate T-mobile’s term as described below

(e) running software or other devices that maintain continuously active Internet connections when a computer’s connection would otherwise be idle, or “keep alive” functions. For example, you cannot use a Data Plan for Web broadcasting, or for the operation of servers, telemetry devices and/or supervisory control and data acquisition devices.

Although purpose of this workaround is not to activate connection the internet, they may point out that by doing this, we are still shooting out ICMP packet though impact to infrastructure should be very minimal.