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
$pr...@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 <[email protected]>
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:[email protected]]
> 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
> <[email protected]> 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: [email protected]
> http://www.ixonos.com
>
> -----Original Message-----
> From: M&M stich [mailto:[email protected]]
>
> Sent: 20. maj 2010 17:08
> To: Uhrenfeldt Henrik
> Cc: android-porting
> 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 »
--
unsubscribe: [email protected]
website: http://groups.google.com/group/android-porting
