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 <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 > http://www.ixonos.com > > -----Original Message----- > From: M&M stich [mailto:mstic...@gmail.com] > > 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: android-porting+unsubscr...@googlegroups.com website: http://groups.google.com/group/android-porting