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 the connection twice (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 the data setup 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: Data connection via 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 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
