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 the data call 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): requesting data connection to 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
Unknown Data Error
D/GSM ( 955): [GsmDataConnectionTracker] PDP setup failed Unknown Data
Error
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 up connection due 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): requesting data connection to 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 ( 863): ----- response[2] ip addr : 10.129.140.89
D/RIL ( 863): --- Returning from setup data call ---
D/RILJ ( 955): [0059]< SETUP_DATA_CALL {1, gprs, 10.129.140.89}
D/GSM ( 955): [GsmDataConnectionTracker] setState: INITING
D/GSM ( 955): [PdpConnection] DataConnection.handleMessage()
D/GSM ( 955): [PdpConnection] interface=gprs ipAddress=10.129.140.89
gateway=192.168.202.0 DNS1= DNS2=172.16.7.167
D/GSM ( 955): [PdpConnection] Notify PDP success at 1274367578330
D/GSM ( 955): [PdpConnection] PDP setup on cid = 1
D/GSM ( 955): [GsmDataConnectionTracker] setState: CONNECTED
D/GSM ( 955): [DataConnection] Start poll NetStat
D/RILJ ( 955): [0060]> SIGNAL_STRENGTH
D/RIL ( 863): onRequest: SIGNAL_STRENGTH
D/AT ( 863): AT> AT+CSQ
D/AT ( 863): AT< +CSQ: 22,0
D/AT ( 863): AT< OK
D/RILJ ( 955): [0060]< SIGNAL_STRENGTH {22, 0, 0, 0, 0, 0, 0}
D/RILJ ( 955): [0061]> SIGNAL_STRENGTH
D/RIL ( 863): onRequest: SIGNAL_STRENGTH
D/AT ( 863): AT> AT+CSQ
D/AT ( 863): AT< +CSQ: 22,0
D/AT ( 863): AT< OK
D/RILJ ( 955): [0061]< SIGNAL_STRENGTH {22, 0, 0, 0, 0, 0, 0}
D/RILJ ( 955): [0062]> SIGNAL_STRENGTH
D/RIL ( 863): onRequest: SIGNAL_STRENGTH
D/AT ( 863): AT> AT+CSQ
D/RILJ ( 955): WAKE_LOCK_TIMEOUT mReqPending=0 mRequestList=1
D/RILJ ( 955): 0: [62] SIGNAL_STRENGTH
I/RIL ( 863): AT channel timeout; closing
E/RIL ( 863): requestSignalStrength must never return an error when
radio is on
E/RILC ( 863): RIL_onRequestComplete: invalid RIL_Token
I/RIL ( 863): Re-opening after close
D/AT ( 863): AT> ATE0Q0V1
D/RILB ( 955): Notifying: radio not available
D/RILB ( 955): Notifying: radio off or not available
D/RILJ ( 955): [UNSL]< UNSOL_RESPONSE_RADIO_STATE_CHANGED
RADIO_UNAVAILABLE
D/RILJ ( 955): [0062]< SIGNAL_STRENGTH error:
com.android.internal.telephony.CommandException: GENERIC_FAILURE
D/RILB ( 955): Notifying: radio available
D/RILJ ( 955): [0063]> SCREEN_STATE: true
D/RILJ ( 955): [0064]> RADIO_POWER
D/RILJ ( 955): [UNSL]< UNSOL_RESPONSE_RADIO_STATE_CHANGED RADIO_OFF
E/GSM ( 955): Wrong network type: 0
E/GSM ( 955): Wrong network type: 0
D/GSM ( 955): Poll ServiceState done: oldSS=[0 home AT&T AT&T 310410
Unknown CSS not supported -1 -1RoamInd: -1DefRoamInd: -1] newSS=[3 home null
null null Unknown CSS not supported -1 -1RoamInd: -1DefRoamInd: -1]
oldGprs=0 newGprs=0 oldType=unknown newType=unknown
D/RILJ ( 955): [0065]> GET_CURRENT_CALLS
D/GSM ( 955): [GsmDataConnectionTracker] Radio is off and clean up all
connection
D/GSM ( 955): [GsmDataConnectionTracker] Clean up connection due to
radioTurnedOff
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): [GsmSimCard] Broadcasting intent SIM_STATE_CHANGED_ACTION
NOT_READY reason null
D/RILJ ( 955): [0066]> RADIO_POWER
E/GSM ( 955): Wrong network type: 0
E/GSM ( 955): Wrong network type: 0
D/GSM ( 955): Poll ServiceState done: oldSS=[3 home null null null
Unknown CSS not supported -1 -1RoamInd: -1DefRoamInd: -1] newSS=[3 home null
null null Unknown CSS not supported -1 -1RoamInd: -1DefRoamInd: -1]
oldGprs=0 newGprs=0 oldType=unknown newType=unknown
D/RILJ ( 955): [0067]> BASEBAND_VERSION
D/RILJ ( 955): [0068]> GET_IMEI
D/RILJ ( 955): [0069]> GET_IMEISV
D/AT ( 863): AT> ATE0Q0V1
D/AT ( 863): AT> ATE0Q0V1
::::
--------------------------------------
On Thu, May 20, 2010 at 6:17 AM, Uhrenfeldt Henrik <
henrik.uhrenfe...@ixonos.com> wrote:
> Hi Mike,
>
> Maybe you're experiencing a race condition. If your RIL call completes the
> instant local-ip is set, upper layers in Android may conclude that
> net.grps.dns1, etc. is not set (because the shell script was suspended by
> the lowlevel RIL process). Try making sure that the local-ip property is set
> as the very last thing.
>
> Or just to check for race conditions, add a half second delay or so before
> completing SETUP_DATA_CALL.
>
> - Henrik
>
> -----Original Message-----
> From: M&M stich [mailto:mstic...@gmail.com]
> Sent: 19. maj 2010 21:41
> To: Uhrenfeldt Henrik
> Cc: android-porting
> Subject: Re: Data connection via cell modem (GPRS)
>
> Hi Henrik
> First response element is "1", the context ID (CID) of the modem.
> Second is "gprs", since we found places in the RIL.java where is uses this
> for the center element of the properties, i.e. net.gprs.dns1 and others.
> Third is the local-ip
>
> Ping does work, including with DNS, i.e. ping www.google.com
>
> Logcat from the radio looks normal, no errors. As you say, I think the
> issue is in Android somewhere, not the radio layers. I think we may be
> telling it something wrong. E.g. the apn-conf.xml file says 0.0.0.0 for the
> IP, with make sense since it doesn't know what the IP will be (DHCP, right?)
> but I see that in the radio log as part of a response right after setting up
> the data call. That is not part of the response, and later in the log the
> other IP's show up properly. Or there is some other setting not quite
> right.
>
> The main logcat shows some errors with sites not found, trying to track
> those down now, but they are from deep within Android.
>
> Mike
>
>
> On Wed, May 19, 2010 at 1:46 PM, Uhrenfeldt Henrik <
> henrik.uhrenfe...@ixonos.com> wrote:
>
>
> Hi Mike!
>
> Yes, it is local-ip that needs to be passed back. What is in the
> other elements of response[]?
>
> Output from logcat -b radio would be useful here - it tells
> something about what Android thinks is its connection.
>
> Also, if you have an ip and can ping stuff from the shell, your apn
> is correct and the issue is Android only. Maybe test this?
>
> - Henrik
>
> --- Oprindelig besked ---
> Fra: "M&M stich" <mstic...@gmail.com>
> Emne: Re: Data connection via cell modem (GPRS)
> Dato: 19. maj 2010
> Klokkeslæt: 20:1635
>
> Hi Henrik,
> Thanks much for your help. Got the data call up and running, seems
> stable. Seems like you just can't put the response[2] pointer into the
> property_get call for some reason. Thought I had it initialized large enough
> also. Oh well.
>
> Now the web browser seems to hang, log msgs indicate it gets no
> response when searching for a web site. Looking into apn settings, and if
> we have the ip address correct. You did say the local-ip should be passed
> back in the response to setup_data_call, correct? Not the remote-ip?
> Actually neither seems to work at this point.
>
> Mike
>
>
> On Tue, May 18, 2010 at 2:19 AM, Uhrenfeldt Henrik <
> henrik.uhrenfe...@ixonos.com> wrote:
>
>
> Hi Mike,
>
> I suspect I have had the same problems. I can see that I use
> a two-step solution to ensure that the string containing the IP is
> sufficiently big and does not get overwritten when the function exits (as
> would normally be the case with variables local to a function).
>
> static char address_ip[PROPERTY_VALUE_MAX];
>
> err = property_get("net.gprs.local-ip", address_ip ,"");
> response[2] = address_ip;
>
> I suppose that property_get writes more into the response[2]
> char* than initially allocated, OR response[2]'s area on the stack is used
> for something else immediately after the function exits...
>
>
> - Henrik
>
> -----Original Message-----
> From: M&M stich [mailto:mstic...@gmail.com]
>
> Sent: 17. maj 2010 22:50
> To: Uhrenfeldt Henrik; android-porting
> Subject: Re: Data connection via cell modem (GPRS)
>
> Hi Henrik,
> Removing all variables from the LOGD calls did not change
> anything.
>
> After multiple experiments with the placement of LOGD's, I
> believe it is crashing whenever property_get is executed. Can never get by
> that:
>
> len = property_get("net.gprs.local-ip",response[2],
> NULL);
>
> I printed out response[0], [1], and [2], before this call
> and they look correct..
> Mike
>
>
> On Mon, May 17, 2010 at 8:06 AM, Uhrenfeldt Henrik <
> henrik.uhrenfe...@ixonos.com> wrote:
>
>
> Hi Mike,
>
> I still think the RIL crashes if you get the two
> lines:
>
>
> E/RILJ ( 929): Hit EOS reading message
> length
> I/RILJ ( 929): Disconnected from 'rild'
> socket
>
>
> The log message is confusing because the java process
> somehow finishes its ongoing function call through JNI when the lowlevel RIL
> crashes. If changing the invalid index did not do the trick, then we have to
> look for something else. Try modifying your debug line not to reference any
> variables at all - we need to make sure that RIL does not crash..
>
> Regarding the setting of local-ip in ip-down, I
> thought about the very same thing, but you end up in trouble waiting for
> local-ip being set if fx. ppp fails to initialize (this happens in my setup
> from time to time). In that case you need to wait for both ppp exit code AND
> local-ip. Thus I ended up making one single property which was being set
> from both ppp-init script (after PPP exit) as well as ip-up and ip-down.
>
>
> - Henrik
>
> -----Original Message-----
> From: M&M stich [mailto:mstic...@gmail.com]
>
> Sent: 17. maj 2010 14:57
> To: Uhrenfeldt Henrik; android-porting
> Subject: Re: Data connection via cell modem (GPRS)
>
> Yes, I noticed that shortly after I sent the message.
> Fixing it did not change anything.
>
> It appears that readRilMessage in RIL.java is
> executing before the response is sent. I don't understand why this should
> happen.
>
> I was going to clear the net.gprs.local-ip property
> in the ip-down script so that it would work multiple times. Then it could
> be reset in the ip-up script like it currently is. Would that not work
> similarly to another property?
>
> Thanks much for the help.
> Mike
>
>
> On Mon, May 17, 2010 at 2:27 AM, Uhrenfeldt Henrik <
> henrik.uhrenfe...@ixonos.com> wrote:
>
>
> Hi Stich,
>
> Please keep the list on copy - then everybody
> will learn from this :-)
>
> Anyway, I think your problem is in the line:
>
>
> LOGD(" --- PPPD started successfully; IP local
> : %s Retry count : %d",response[3],retry);
>
>
> In fact response[] is only three elements big,
> and you refer to index 3 instead of 2. I bet the code successfully exits the
> loop and attempts to execute the debug print, hits a NULL pointer and the
> low-level part of RIL crashes. This is confirmed by the debug lines
>
>
> E/RILJ ( 929): Hit EOS reading message
> length
> I/RILJ ( 929): Disconnected from 'rild'
> socket
>
>
> I have crashed the low-level RIL many times,
> and every time I get this message :-)
>
> I bet that if you change response[3] to
> response[2] it will be working. That being said this will work only once,
> since next time you attempt connection, local-ip will be set already. I
> introduced yet another property which I set to a kind of state information
> (ie. down/initializing/up). Again this synchronization through properties
> really is the worst part of this setup, and I have been able to stabilize it
> 100%...
>
> - Henrik
>
>
> -----Original Message-----
> From: M&M stich [mailto:mstic...@gmail.com]
> Sent: 14. maj 2010 21:44
> To: Robert Greenwalt; Uhrenfeldt Henrik
> Subject: Data connection via cell modem (GPRS)
>
> Made some progress. When SETUP_DATA_CALL is
> called, my ril starts the pppd via ctl.start, and that seems to work. The
> deamon does seem to start and the associated properties seem to be set.
> (Doing a "start service" from the console works) I've put log messages at
> each step, when it starts, when it waits for the local-ip property to be set
> (which is set in ip-up), when that completes, and when it does the
> RilRequestComplete call.
>
> It never gets to the end. RIL.java seems to
> think it has a response before the request completes, then errors out
> because it reached "EOS" Here is a snippet of the radio logcat. Messages
> that have "---" are ones I put in the reference-ril in the SETUP_DATA_CALL.
> There should be the 4 mentioned above. It never finishes the wait for the
> local-ip property.
>
> I can't figure out why RIL.java thinks it
> should go read a response before there has been a reply to the request.
> Thanks.
> Mike
>
> ------------------------------------------------------------------
> D/GSM ( 929): [GsmSimCard] Broadcasting
> intent SIM_STATE_CHANGED_ACTION LOADED reason null
> D/GSM ( 929): Get PreferredAPN
> D/GSM ( 929): [GsmDataConnectionTracker]
> ***trySetupData due to simLoaded
> D/GSM ( 929): [DSAC DEB] trySetupData
> with mIsPsRestricted=false
> D/GSM ( 929): [GsmDataConnectionTracker]
> Create from allApns : [ATT, 1, 310410, wap.cingular,
> wireless.cingular.com, http://mmsc.cingular.com, null, null, 80, *]
> D/GSM ( 929): [GsmDataConnectionTracker]
> Setup watingApns : [ATT, 1, 310410, wap.cingular, wireless.cingular.com,
> http://mmsc.cingular.com, null, null, 80, *]
> D/GSM ( 929): [PdpConnection]
> DataConnection.getState()
> D/GSM ( 929): [PdpConnection] Connecting
> to carrier: 'ATT' APN: 'wap.cingular' proxy: ' wireless.cingular.com'
> port: '80
> D/RILJ ( 929): [0060]> SETUP_DATA_CALL
> wap.cingular
> D/RIL ( 811): onRequest: SETUP_DATA_CALL
> D/RIL ( 811): requesting data connection
> to APN 'wap.cingular'
> D/RIL ( 811): ---- Starting service
> pppd_gprs -----
> D/RIL ( 811): ---- starting wait for
> property ----- prop set return code is 0
> D/GSM ( 929): [GsmDataConnectionTracker]
> setState: INITING
> E/RILJ ( 929): Hit EOS reading message
> length
> I/RILJ ( 929): Disconnected from 'rild'
> socket
>
> Here is the code:
> err =
> property_set("ctl.start","pppd_gprs"); // Tell init to start the
> pppd_gprs service
> LOGD(" ---- Starting service pppd_gprs
> ----- ");
> if(err<0)
> {
> LOGD("#### error in starting
> service pppd_gprs; err : %d",err);
> goto error;
> }
> retry = 100;
> LOGD(" ---- starting wait for property
> ----- prop set return code is %d",err);
>
> while((property_get("net.gprs.local-ip",response[2], "") <= 0) && --retry)
> {
> usleep(5*1000); // sleep 5ms
> }
>
> LOGD(" --- PPPD started successfully;
> IP local : %s Retry count : %d",response[3],retry);
> ......
> LOGD(" --- Returning from setup data call,
> response length is %d",sizeof(response));
> RIL_onRequestComplete(t, RIL_E_SUCCESS,
> response, sizeof(response));
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
>
--
unsubscribe: android-porting+unsubscr...@googlegroups.com
website: http://groups.google.com/group/android-porting
