Hi Henrik,
Well, I'm getting pretty close. The ppp connections starts and stops
gracefully. The radio log looks pretty clean, but I just cannot get
the browser to start. It often pops up a window saying unable to find
web page, or "Data connectivity problem". Here is the end of the log
when I tried starting the browser. Any suggestions on where to
look?
Thanks Mike
D/dalvikvm( 977): GC freed 3969 objects / 288312 bytes in 45ms
D/KeyguardViewMediator( 846): wakeWhenReadyLocked(82)
D/KeyguardViewMediator( 846): handleWakeWhenReady(82)
D/KeyguardViewMediator( 846): pokeWakelock(5000)
E/power ( 846): Failed setting last user activity: g_error=0
D/KeyguardViewMediator( 846): pokeWakelock(5000)
I/ActivityManager( 846): Start proc com.android.inputmethod.latin for
service com.android.inputmethod.latin/.LatinIME: pid=1712 uid=10001
gids={3003, 1015}
I/ARMAssembler( 846): generated
scanline__00000077:03545404_00000A04_00000000 [ 29 ipp] (51 ins) at
[0x213368:0x213434] in 244140 ns
D/dalvikvm( 1712): Trying to load lib /system/lib/libjni_latinime.so
0x49ba6db8
D/dalvikvm( 1712): Added shared lib /system/lib/libjni_latinime.so
0x49ba6db8
I/WindowManager( 846): Checking dispatch to: Window{49cb3a58 Keyguard
paused=false}
I/WindowManager( 846): Not visible!
I/WindowManager( 846): Checking dispatch to: Window{49cb1370
StatusBar paused=false}
I/WindowManager( 846): Checking dispatch to: Window{49d48a50
StatusBarExpanded paused=false}
I/WindowManager( 846): Not visible!
I/WindowManager( 846): Checking dispatch to: Window{49d13618
TrackingView paused=false}
I/WindowManager( 846): Not visible!
I/WindowManager( 846): Checking dispatch to: Window{49bb7b28
com.android.launcher/com.android.launcher.Launcher paused=false}
D/AlarmManagerService( 846): Kernel timezone updated to 300 minutes
west of GMT
D/SystemClock( 896): Setting time of day to sec=1274801005
I/ActivityManager( 846): Stopping service:
com.android.calendar/.AlertService
D/dalvikvm( 1001): GC freed 2137 objects / 141664 bytes in 129ms
D/AlarmManagerService( 846): Kernel timezone updated to 300 minutes
west of GMT
D/SystemClock( 896): Setting time of day to sec=1274801005
I/WindowManager( 846): Checking dispatch to: Window{49cb3a58 Keyguard
paused=false}
I/WindowManager( 846): Not visible!
I/WindowManager( 846): Checking dispatch to: Window{49cb1370
StatusBar paused=false}
I/WindowManager( 846): Checking dispatch to: Window{49d48a50
StatusBarExpanded paused=false}
I/WindowManager( 846): Not visible!
I/WindowManager( 846): Checking dispatch to: Window{49d13618
TrackingView paused=false}
I/WindowManager( 846): Not visible!
I/WindowManager( 846): Checking dispatch to: Window{49bb7b28
com.android.launcher/com.android.launcher.Launcher paused=false}
I/ActivityManager( 846): Stopping service:
com.android.calendar/.AlertService
I/ActivityManager( 846): Starting activity: Intent
{ act=android.intent.action.MAIN
cat=[android.intent.category.LAUNCHER] flg=0x10200000
cmp=com.android.browser/.BrowserActivity }
I/ActivityManager( 846): Start proc com.android.browser for activity
com.android.browser/.BrowserActivity: pid=1733 uid=10010 gids={3003}
D/installd( 779): DexInv: --- BEGIN '/system/app/Browser.apk' ---
D/dalvikvm( 1747): DexOpt: load 98ms, verify 462ms, opt 7ms
D/installd( 779): DexInv: --- END '/system/app/Browser.apk' (success)
---
I/ActivityThread( 1733): Publishing provider browser:
com.android.browser.BrowserProvider
E/ActivityThread( 1733): Failed to find provider info for
com.google.settings
D/ ( 1733): unable to unlink '/data/data/com.android.browser/
shared_prefs/com.android.browser_preferences.xml.bak': No such file or
directory (errno=2)
W/ActivityManager( 846): Unable to start service Intent
{ cmp=com.google.android.googleapps/.GoogleLoginService }: not found
I/ARMAssembler( 846): generated
scanline__00000077:03515104_00000000_00000000 [ 27 ipp] (41 ins) at
[0x287a10:0x287ab4] in 213623 ns
I/ARMAssembler( 846): generated
scanline__00000077:03515104_00001001_00000000 [ 64 ipp] (84 ins) at
[0x287b18:0x287c68] in 244140 ns
D/dalvikvm( 1733): GC freed 3113 objects / 274848 bytes in 101ms
D/dalvikvm( 846): GC freed 15034 objects / 713720 bytes in 72ms
D/dalvikvm( 910): GC freed 1650 objects / 85608 bytes in 47ms
D/dalvikvm( 846): GC freed 18004 objects / 854480 bytes in 65ms
D/dalvikvm( 846): GC freed 16651 objects / 789576 bytes in 64ms
E/power ( 846): Failed setting last user activity: g_error=0
W/ActivityManager( 846): Unable to start service Intent
{ act=android.accounts.IAccountsService
cmp=com.google.android.googleapps/.GoogleLoginService }: not found
E/LockPatternKeyguardView( 846): Failed to bind to GLS while checking
for account
D/dalvikvm( 846): GC freed 634 objects / 26968 bytes in 51ms
D/KeyguardViewMediator( 846): wakeWhenReadyLocked(82)
D/KeyguardViewMediator( 846): handleWakeWhenReady(82)
D/KeyguardViewMediator( 846): pokeWakelock(5000)
E/power ( 846): Failed setting last user activity: g_error=0
I/ActivityManager( 846): Displayed activity
com.android.browser/.BrowserActivity: 63377 ms (total 63377 ms)
W/KeyCharacterMap( 846): No keyboard for id 0
W/KeyCharacterMap( 846): Using default keymap: /system/usr/keychars/
qwerty.kcm.bin
D/KeyguardViewMediator( 846): pokeWakelock(5000)
W/InputManagerService( 846): Window already focused, ignoring focus
gain of: com.android.internal.view.IInputMethodClient$Stub
$Proxy@49bd37c8
D/dalvikvm( 846): GC freed 15385 objects / 731184 bytes in 63ms
D/dalvikvm( 846): GC freed 23556 objects / 1114880 bytes in 71ms
E/power ( 846): Failed setting last user activity: g_error=0
W/ActivityManager( 846): Unable to start service Intent
{ act=android.accounts.IAccountsService
cmp=com.google.android.googleapps/.GoogleLoginService }: not found
E/LockPatternKeyguardView( 846): Failed to bind to GLS while checking
for account
D/dalvikvm( 846): GC freed 4595 objects / 428736 bytes in 67ms
E/browser ( 1733): onReceivedError -7
http://www.google.com/m?client=ms-android-google
The server failed to communicate. Try again later.
E/OpenSSLSocketImpl( 1733): Unknown error 5 during connect
E/Gears-J ( 1733): Connection IO exception
E/Gears-J ( 1733): java.io.IOException: SSL handshake failure: I/O
error during system call, Unknown error: 0
E/Gears-J ( 1733): at
org.apache.harmony.xnet.provider.jsse.OpenSSLSocketImpl.nativeconnect(Native
Method)
E/Gears-J ( 1733): at
org.apache.harmony.xnet.provider.jsse.OpenSSLSocketImpl.startHandshake(OpenSSLSocketImpl.java:
305)
E/Gears-J ( 1733): at
org.apache.http.conn.ssl.AbstractVerifier.verify(AbstractVerifier.java:
92)
E/Gears-J ( 1733): at
org.apache.http.conn.ssl.SSLSocketFactory.connectSocket(SSLSocketFactory.java:
321)
E/Gears-J ( 1733): at
org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:
129)
E/Gears-J ( 1733): at
org.apache.http.impl.conn.AbstractPoolEntry.open(AbstractPoolEntry.java:
164)
E/Gears-J ( 1733): at
org.apache.http.impl.conn.AbstractPooledConnAdapter.open(AbstractPooledConnAdapter.java:
119)
E/Gears-J ( 1733): at
org.apache.http.impl.client.DefaultRequestDirector.execute(DefaultRequestDirector.java:
348)
E/Gears-J ( 1733): at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:
555)
E/Gears-J ( 1733): at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:
487)
E/Gears-J ( 1733): at
org.apache.http.impl.client.AbstractHttpClient.execute(AbstractHttpClient.java:
465)
E/Gears-J ( 1733): at
android.webkit.gears.ApacheHttpRequestAndroid
$Connection.run(ApacheHttpRequestAndroid.java:180)
E/Gears-J ( 1733): at java.lang.Thread.run(Thread.java:1060)
D/KeyguardViewMediator( 846): wakeWhenReadyLocked(82)
D/KeyguardViewMediator( 846): handleWakeWhenReady(82)
D/KeyguardViewMediator( 846): pokeWakelock(5000)
E/power ( 846): Failed setting last user activity: g_error=0
W/KeyCharacterMap( 846): No keyboard for id 0
W/KeyCharacterMap( 846): Using default keymap: /system/usr/keychars/
qwerty.kcm.bin
D/KeyguardViewMediator( 846): pokeWakelock(5000)
E/ActivityThread( 896): Failed to find provider info for
android.server.checkin
W/Checkin ( 896): Can't update stat PHONE_RADIO_RESETS:
java.lang.IllegalArgumentException: Unknown URL content://android.server.checkin/stats
I/ActivityManager( 846): Stopping service:
com.android.mms/.transaction.SmsReceiverService
I/ActivityManager( 846): Stopping service:
com.android.mms/.transaction.SmsReceiverService
D/dalvikvm( 846): GC freed 21575 objects / 1007240 bytes in 71ms
On May 21, 2:52 am, Uhrenfeldt Henrik <
henrik.uhrenfe...@ixonos.com>
wrote:
> Hi Mike,
>
> Hehe... I had the same feeling.
>
> My DEACTIVATE does not work 100% smooth, but it works. I basically set AT+CGACT=0,1 and wait for PPPD to die from natural causes. As far as I remember, it does in fact call ip-down. I do not attempt to stop the service manually (via init.svc.pppd_gprs), neither do I care about the untracked pid (which I think I get as well).
>
> Regarding breaking out ofdatamode, my modem automatically terminates the PPPconnectionwhen it receives the AT+CGACT=0,1, so I am not doing anything like the '+++'...
>
> One thing though - I cannot seem to get the exit code from pppd properly, but at some point I gave up and decided I could live without it. Since I was able to setup thedataconnectionseveral times in a row, I concluded it was good enough :-)
>
> - Henrik
>
> -----Original Message-----
> From: M&M stich [mailto:
mstic...@gmail.com]
> Sent: 20. maj 2010 22:26
> To: Uhrenfeldt Henrik
>
> Cc: android-porting
> Subject: Re:Dataconnectionvia cell modem (GPRS)
>
> Hi Henrik!
> @#$%^^!! This is driving me nuts.
>
> Ok, I lengthened the timeout, takes around 14 Sec for me. I also see the DEACTIVATE due to APN changed. But the deactivate does not work.
>
> Looks like ip-down does not get called. If I manually do a stop on the service, it does not get called. If I kill pid from the console, then it does get called. I'm relying on it to set the same property I use to check startup to "no" instead of "yes". I suppose I could use the init.svc.pppd_gprs property instead, but I thought ip-down should get called. By the way, the shell that ran ip-up does not go away after it runs. When I stop pppd_gprs, I get an "untracked pid exited" from it.
>
> BUT, the chat disconnect script is not running correctly either, it seems. It needs to do the '+++' to break out ofdatamode. The modem requires 1 sec before and 1 sec after of quiet time for this to work. I set verbose on the chat command, but it did not show me anything. I may need to figure out how to trace it.
> Thanks
> Mike
>
> On Thu, May 20, 2010 at 10:29 AM, Uhrenfeldt Henrik <
henrik.uhrenfe...@ixonos.com> wrote:
>
> Hi Mike!
>
> I bet 2 seconds is not near enough.. I have a timeout of 15 seconds to wait for the PPP to get up properly - in average it takes around 7-8 seconds. Then probably what goes wrong next is the fact that the needed properties were set in the last run, so your SETUP_DATA_CALL finishes quickly, but meanwhile you may have confused the modem with another AT+CGDCONT..
>
> You have to get the first attempt to work and be sure that there are no race conditions with setting/reading properties. For example - if you set your custom property to something like "initing" in the beginning of the pppd service and wait for it to become "up", the next time you run SETUP_DATA_CALL, it will be "up" until the service is really running and setting it to "initing" - unless you do some kludgy waiting in SETUP_DATA_CALL before initially checking state of your property. This had me tweaking for some time.
>
> To get all this running properly, I also had to implement DEACTIVATE_DATA_CALL in which I send an "AT+CGACT=0,1" and then I wait for pppd service to exit (yet another property to check for). In our setup, Android always sets up theconnectiontwice (due to some weirdness with a list of APNs changing in higher layers), so we need to have a reliable shutdown as well - sigh..
>
> Regarding your timeout on the AT channel there is not much to say else than it seems the modem is somehow in a state where it won't answer. This is of course critical for the RIL and it has no choice other than attempting to restart. Hopefully it is caused by PDP context confusion or some other invalid chain of commands caused by thedatasetup stuff.
>
> - Henrik
> ---
> Henrik Uhrenfeldt
> Chief Software Engineer
> Ixonos Denmark ApS
> Niels Jernes Vej 10,
> DK-9220 Aalborg Ø, Denmark
> mobile
+45 4030 2607
> email:
henrik.uhrenfe...@ixonos.com
> Subject: Re:Dataconnectionvia cell modem (GPRS)
>
> Hi Henrik,
> ip-up sets a custom property last (only does some logging after that) that triggers the ril to send a response. The ril waits 2 sec for the property, then times out and returns an error. Android then tries again shortly thereafter, and the ril does not have to wait at all, everything is setup.
>
> Now,when I try and start the browser, it somehow causes a timeout on the signal strength request and cause the radio to crash. This is a new behavior. Here is the end of the radio log, showing thedatacall being set up as described. PDPconnection seems to have the dns correctly. Also shows the at channel timeout somehow caused by the browser trying to start. It does restart successfully eventually.
> Thanks Mike
> ---------------------------------------------------
> :::::
> D/GSM ( 955): SIMRecords: record load complete
> D/GSM ( 955): [GsmSimCard] Broadcasting intent SIM_STATE_CHANGED_ACTION LOADED reason null
> D/GSM ( 955): Get PreferredAPN
> D/GSM ( 955): [GsmDataConnectionTracker] ***trySetupData due to simLoaded
> D/GSM ( 955): [DSAC DEB] trySetupData with mIsPsRestricted=false
> I/GSM ( 955): Preferred APN:310410:310410:ATT, 1, 310410, wap.cingular, null, null, null, null, null, *
> I/GSM ( 955): Waiting APN set to preferred APN
> D/GSM ( 955): [GsmDataConnectionTracker] Create from allApns : [ATT, 1, 310410, wap.cingular, null, null, null, null, null, *]
> D/GSM ( 955): [GsmDataConnectionTracker] Setup watingApns : [ATT, 1, 310410, wap.cingular, null, null, null, null, null, *]
> D/GSM ( 955): [PdpConnection] DataConnection.getState()
> D/GSM ( 955): [PdpConnection] Connecting to carrier: 'ATT' APN: 'wap.cingular' proxy: 'null' port: 'null
> D/RILJ ( 955): [0057]> SETUP_DATA_CALL wap.cingular
> D/RIL ( 863): onRequest: SETUP_DATA_CALL
> D/RIL ( 863): requestingdataconnectionto APN 'wap.cingular'
> D/RIL ( 863): ---- Initial running status : len : 2 Status: no
> D/RIL ( 863): ---- Starting service pppd_gprs -----
> D/RIL ( 863): --- Initial Response is : 1 ; gprs ; 000.000.000.000
> D/RIL ( 863): ---- starting wait for property -----, len : 2 Status: no
> D/GSM ( 955): [GsmDataConnectionTracker] setState: INITING
> D/RIL ( 863): ---- PPPD failed to start: status = no , length = 2 , retry = 0
> D/RILJ ( 955): [0057]< SETUP_DATA_CALL error: com.android.internal.telephony.CommandException: GENERIC_FAILURE
> D/GSM ( 955): [PdpConnection] DataConnection.handleMessage()
> E/GSM ( 955): PDP Context Init failed com.android.internal.telephony.CommandException: GENERIC_FAILURE
> D/RILJ ( 955): [0058]> LAST_DATA_CALL_FAIL_CAUSE
> D/RIL ( 863): onRequest: LAST_DATA_CALL_FAIL_CAUSE
> D/RILJ ( 955): [0058]< LAST_DATA_CALL_FAIL_CAUSE error: com.android.internal.telephony.CommandException: REQUEST_NOT_SUPPORTED
> D/GSM ( 955): [PdpConnection] DataConnection.handleMessage()
> D/GSM ( 955): [PdpConnection] Notify PDP fail at 1274367573216 due to UnknownDataError
> D/GSM ( 955): [GsmDataConnectionTracker] PDP setup failed UnknownDataError
> D/GSM ( 955): [GsmDataConnectionTracker] setState: FAILED
> D/GSM ( 955): PDP activate failed. Scheduling next attempt for 5s
> D/GSM ( 955): NOT Posting GPRS Unavailable notification -- likely transient error
> D/GSM ( 955): GPRS reconnect alarm. Previous state was FAILED
> D/GSM ( 955): [GsmDataConnectionTracker] Clean upconnectiondue to simLoaded
> D/GSM ( 955): [GsmDataConnectionTracker] setState: DISCONNECTING
> D/GSM ( 955): [PdpConnection] DataConnection.clearSettings()
> D/GSM ( 955): [DataConnection] Stop poll NetStat
> D/GSM ( 955): [GsmDataConnectionTracker] setState: IDLE
> D/GSM ( 955): [GsmDataConnectionTracker] ***trySetupData due to (unspecified)
> D/GSM ( 955): [DSAC DEB] trySetupData with mIsPsRestricted=false
> I/GSM ( 955): Preferred APN:310410:310410:ATT, 1, 310410, wap.cingular, null, null, null, null, null, *
> I/GSM ( 955): Waiting APN set to preferred APN
> D/GSM ( 955): [GsmDataConnectionTracker] Create from allApns : [ATT, 1, 310410, wap.cingular, null, null, null, null, null, *]
> D/GSM ( 955): [GsmDataConnectionTracker] Setup watingApns : [ATT, 1, 310410, wap.cingular, null, null, null, null, null, *]
> D/GSM ( 955): [PdpConnection] DataConnection.getState()
> D/GSM ( 955): [PdpConnection] Connecting to carrier: 'ATT' APN: 'wap.cingular' proxy: 'null' port: 'null
> D/RILJ ( 955): [0059]> SETUP_DATA_CALL wap.cingular
> D/RIL ( 863): onRequest: SETUP_DATA_CALL
> D/RIL ( 863): requestingdataconnectionto APN 'wap.cingular'
> D/RIL ( 863): ---- Initial running status : len : 3 Status: yes
> D/RIL ( 863): ---- Starting service pppd_gprs -----
> D/RIL ( 863): --- Initial Response is : 1 ; gprs ; 000.000.000.000
> D/RIL ( 863): ---- starting wait for property -----, len : 3 Status: yes
> D/RIL ( 863): --- PPPD started successfully; status : yes Lengthe: 3, Retry count : 200
> D/RIL ( 863): ---- Local IP read as : 10.129.140.89 length : 13 -----
> D/RIL
>
> ...
>
> read more »