Polling CLCC error handling on Option modem (GTA04)

Polling CLCC error handling on Option modem (GTA04)

[Radek Polak]

[-- Attachment #1: Type: text/plain, Size: 1619 bytes --]

Hi,
first of all QtMoko [1] now supports ofono as another telephony backend [2]. We 
have also autogenerated qt bindings [3] which can be interesting also for 
other projects.

But now the problem that has already been discussed. If you make call to GTA04 
with ofono running, it starts CLCC polling. After you hangup sometimes 
everything is ok and the call disappears:

fonod[1027]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
ofonod[1027]: App: > AT+CLCC\r
ofonod[1027]: App: < \r\nOK\r\n
ofonod[1027]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection 
event for id: 1, reason: 2
ofonod[1027]: App: < \r\n_OSIGQ: 18,0\r\n
ofonod[1027]: src/network.c:ofono_netreg_strength_notify() strength 58
ofonod[1027]: App: > AT+CLCC\r
ofonod[1027]: App: < \r\nOK\r\n

but sometimes the modem returns error:

ofonod[1027]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
ofonod[1027]: App: > AT+CLCC\r
ofonod[1027]: App: < \r\n+CME ERROR: 100\r\n
ofonod[1027]: We are polling CLCC and received an error
ofonod[1027]: All bets are off for call management

and ofono never reports that the call is removed. The result is that GUI shows 
dialed call forever.

I know that modem should not return error, but it would be nice to have@
least some workaround. E.g. assume remote hangup or missed call.

Or anyone has better ideas?

Regards

Radek


[1] http://qtmoko.org
[2] 
https://github.com/radekp/qtmoko/tree/master/src/server/phone/telephony/phoneserver/ofonoservice
[3] https://github.com/radekp/qtmoko/tree/master/src/libraries/qofono

Re: Polling CLCC error handling on Option modem (GTA04)

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 2424 bytes --]

Hi Radek,

On 03/06/2012 02:47 PM, Radek Polak wrote:
> Hi,
> first of all QtMoko [1] now supports ofono as another telephony backend [2]. We 
> have also autogenerated qt bindings [3] which can be interesting also for 
> other projects.
> 

Nice.

> But now the problem that has already been discussed. If you make call to GTA04 
> with ofono running, it starts CLCC polling. After you hangup sometimes 
> everything is ok and the call disappears:
> 
> fonod[1027]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
> ofonod[1027]: App: > AT+CLCC\r
> ofonod[1027]: App: < \r\nOK\r\n
> ofonod[1027]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection 
> event for id: 1, reason: 2
> ofonod[1027]: App: < \r\n_OSIGQ: 18,0\r\n
> ofonod[1027]: src/network.c:ofono_netreg_strength_notify() strength 58
> ofonod[1027]: App: > AT+CLCC\r
> ofonod[1027]: App: < \r\nOK\r\n
> 
> but sometimes the modem returns error:
> 
> ofonod[1027]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
> ofonod[1027]: App: > AT+CLCC\r
> ofonod[1027]: App: < \r\n+CME ERROR: 100\r\n
> ofonod[1027]: We are polling CLCC and received an error
> ofonod[1027]: All bets are off for call management
> 
> and ofono never reports that the call is removed. The result is that GUI shows 
> dialed call forever.
> 
> I know that modem should not return error, but it would be nice to have at 
> least some workaround. E.g. assume remote hangup or missed call.

My standard reply for such modems is to talk to your vendor and demand
the firmware to be fixed.  If this isn't possible, then please perform
these steps:
	window.open();
	window.throw(modem);
	window.close();

:)

It seriously might be easier to get another modem than trying to work
around such nasty bugs in the modem firmware.  You will never be able to
hit any sort of power consumption targets with CLCC polling anyway.
Such behavior from the modem firmware is not acceptable, even the old
Calypso modem in the Freerunner was better here.

> 
> Or anyone has better ideas?
> 

You can always try ignoring CME ERROR 100 and re-try the CLCC poll.
Maybe the modem is in a transitional period (e.g. call being released)
and it can't answer the CLCC properly.  In other words, there's a bug
related to timing of call state changes & CLCC implementation in the
modem firmware.

Regards,
-Denis

Re: Polling CLCC error handling on Option modem (GTA04)

[Neil Jerram]

[-- Attachment #1: Type: text/plain, Size: 759 bytes --]

Denis Kenzior <denkenz@gmail.com> writes:

> You will never be able to
> hit any sort of power consumption targets with CLCC polling anyway.

I think we do still have another possible line of investigation here.
Neil Brown reported that the modem does generate NO CARRIER on one of
its serial ports - just not the one that is expected.  So perhaps that
can be understood and used, and then the CLCC polling could be switched
off.

Denis, I looked at the oFono code to try to see where CLCC polling is
enabled for an active call, and in fact I couldn't see (in
plugins/atmodem/voicecall.c, which I think is the relevant code) what
could cause oFono _not_ to do CLCC polling.  It looks unconditional
there - is that right?

Regards,
    Neil

Re: Polling CLCC error handling on Option modem (GTA04)

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 2063 bytes --]

Hi Neil,

On 03/06/2012 04:37 PM, Neil Jerram wrote:
> Denis Kenzior <denkenz@gmail.com> writes:
> 
>> You will never be able to
>> hit any sort of power consumption targets with CLCC polling anyway.
> 
> I think we do still have another possible line of investigation here.
> Neil Brown reported that the modem does generate NO CARRIER on one of
> its serial ports - just not the one that is expected.  So perhaps that
> can be understood and used, and then the CLCC polling could be switched
> off.

That would certainly help the situation some, but CLCC polling can not
be completely turned off.  The 'generic' 27.007 based voicecall driver
in oFono was written to minimize polling if possible.  The underlying
assumption is that a 'NO CARRIER' is sent whenever a call (held /
active) is disconnected.  The other times we need to poll are limited,
usually after an action we have taken (e.g. CHLD) or certain call
detection situations.

The only times we need to poll periodically is to detect state
transitions when a call is not under 'our control'.  E.g. dialing ->
alerting, alerting -> active, waiting -> disconnected, dialing /
alerting -> disconnected, etc.

> 
> Denis, I looked at the oFono code to try to see where CLCC polling is
> enabled for an active call, and in fact I couldn't see (in
> plugins/atmodem/voicecall.c, which I think is the relevant code) what
> could cause oFono _not_ to do CLCC polling.  It looks unconditional
> there - is that right?

This particular chunk causes it to poll unconditionally (the
OFONO_VENDOR_QUALCOMM_MSM is set by the hso modem driver):

                switch (vd->vendor) {
                case OFONO_VENDOR_QUALCOMM_MSM:
                        poll_again = TRUE;
                        break;

This was added by Marcel because the 'NO CARRIER' notification never
came.  See commit 9e26e29f.  If someone can fix this by e.g. using a
slave GAtChat with the additional magical unsolicited notification tty,
then that quirk can be removed.

Regards,
-Denis

Re: Polling CLCC error handling on Option modem (GTA04)

[Radek Polak]

[-- Attachment #1: Type: text/plain, Size: 1019 bytes --]

On Monday 05 March 2012 20:26:29 Denis Kenzior wrote:

> You can always try ignoring CME ERROR 100 and re-try the CLCC poll.
> Maybe the modem is in a transitional period (e.g. call being released)
> and it can't answer the CLCC properly.  In other words, there's a bug
> related to timing of call state changes & CLCC implementation in the
> modem firmware.

Yes, it is definitely timing bug. Attached is patch that continues CLCC polling 
even after error assuming that CLCC will start working again. It works fine for 
me (see log below). It would be nice to get this in ofono git.

ofonod[1188]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
ofonod[1188]: App: > AT+CLCC\r
ofonod[1188]: App: < \r\n+CME ERROR: 100\r\n
ofonod[1188]: We are polling CLCC and received an error, retrying...
ofonod[1188]: App: > AT+CLCC\r
ofonod[1188]: App: < \r\nOK\r\n
ofonod[1188]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection 
event for id: 1, reason: 2


Regards

Radek

[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: continue_clcc_after_error.patch --]
[-- Type: text/x-patch, Size: 598 bytes --]

diff --git a/drivers/atmodem/voicecall.c b/drivers/atmodem/voicecall.c
index d07052c..324ea4b 100644
--- a/drivers/atmodem/voicecall.c
+++ b/drivers/atmodem/voicecall.c
@@ -147,8 +147,9 @@ static void clcc_poll_cb(gboolean ok, GAtResult *result, gpointer user_data)
 	gboolean poll_again = FALSE;
 
 	if (!ok) {
-		ofono_error("We are polling CLCC and received an error");
-		ofono_error("All bets are off for call management");
+		ofono_error("We are polling CLCC and received an error, retrying...");
+		vd->clcc_source = g_timeout_add(POLL_CLCC_INTERVAL,
+						poll_clcc, vc);
 		return;
 	}
 

Re: Polling CLCC error handling on Option modem (GTA04)

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 809 bytes --]

Hi Radek,

On 03/07/2012 04:36 AM, Radek Polak wrote:
> On Monday 05 March 2012 20:26:29 Denis Kenzior wrote:
> 
>> You can always try ignoring CME ERROR 100 and re-try the CLCC poll.
>> Maybe the modem is in a transitional period (e.g. call being released)
>> and it can't answer the CLCC properly.  In other words, there's a bug
>> related to timing of call state changes & CLCC implementation in the
>> modem firmware.
> 
> Yes, it is definitely timing bug. Attached is patch that continues CLCC polling 
> even after error assuming that CLCC will start working again. It works fine for 
> me (see log below). It would be nice to get this in ofono git.
> 

I pushed my own version of this patch that is a little bit more
paranoid.  git show ebac438d for more details.

Regards,
-Denis

Re: Polling CLCC error handling on Option modem (GTA04)

[Radek Polak]

[-- Attachment #1: Type: text/plain, Size: 739 bytes --]

On Tuesday 06 March 2012 16:13:58 Denis Kenzior wrote:

> I pushed my own version of this patch that is a little bit more
> paranoid.  git show ebac438d for more details.

Great, thanks! It works nice:

ofonod[1217]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
ofonod[1217]: App: < \r\n_OSIGQ: 17,0\r\n
ofonod[1217]: src/network.c:ofono_netreg_strength_notify() strength 54
ofonod[1217]: App: > AT+CLCC\r
ofonod[1217]: App: < \r\n+CME ERROR: 100\r\n
ofonod[1217]: App: > AT+CLCC\r
ofonod[1217]: App: < \r\nOK\r\n
ofonod[1217]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection 
event for id: 1, reason: 2
ofonod[1217]: App: > AT+CLCC\r
ofonod[1217]: App: < \r\nOK\r\n

Regards

Radek

Re: [Gta04-owner] Polling CLCC error handling on Option modem (GTA04)

[Matthias Apitz]

[-- Attachment #1: Type: text/plain, Size: 1450 bytes --]

El día Wednesday, March 07, 2012 a las 11:36:24AM +0100, Radek Polak escribió:

> On Monday 05 March 2012 20:26:29 Denis Kenzior wrote:
> 
> > You can always try ignoring CME ERROR 100 and re-try the CLCC poll.
> > Maybe the modem is in a transitional period (e.g. call being released)
> > and it can't answer the CLCC properly.  In other words, there's a bug
> > related to timing of call state changes & CLCC implementation in the
> > modem firmware.
> 
> Yes, it is definitely timing bug. Attached is patch that continues CLCC polling 
> even after error assuming that CLCC will start working again. It works fine for 
> me (see log below). It would be nice to get this in ofono git.
> 
> ofonod[1188]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
> ofonod[1188]: App: > AT+CLCC\r
> ofonod[1188]: App: < \r\n+CME ERROR: 100\r\n
> ofonod[1188]: We are polling CLCC and received an error, retrying...
> ofonod[1188]: App: > AT+CLCC\r
> ofonod[1188]: App: < \r\nOK\r\n
> ofonod[1188]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection 
> event for id: 1, reason: 2

I'm wondering if this ofonod log has no timestamps in the log lines? Or
is this something to be configured?

	matthias
-- 
Matthias Apitz
e <guru@unixarea.de> - w http://www.unixarea.de/
UNIX since V7 on PDP-11, UNIX on mainframe since ESER 1055 (IBM /370)
UNIX on x86 since SVR4.2 UnixWare 2.1.2, FreeBSD since 2.2.5

Re: [Gta04-owner] Polling CLCC error handling on Option modem (GTA04)

[Neil Jerram]

[-- Attachment #1: Type: text/plain, Size: 737 bytes --]

Matthias Apitz <guru@unixarea.de> writes:

>> ofonod[1188]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
>> ofonod[1188]: App: > AT+CLCC\r
>> ofonod[1188]: App: < \r\n+CME ERROR: 100\r\n
>> ofonod[1188]: We are polling CLCC and received an error, retrying...
>> ofonod[1188]: App: > AT+CLCC\r
>> ofonod[1188]: App: < \r\nOK\r\n
>> ofonod[1188]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection 
>> event for id: 1, reason: 2
>
> I'm wondering if this ofonod log has no timestamps in the log lines? Or
> is this something to be configured?

oFono does its logging by calling syslog, so maybe the absence of
timestamps is to do with how syslog is configured on Radek's phone.

      Neil

Re: [Gta04-owner] Polling CLCC error handling on Option modem (GTA04)

[Marcel Holtmann]

[-- Attachment #1: Type: text/plain, Size: 1236 bytes --]

Hi Matthias,

> > > You can always try ignoring CME ERROR 100 and re-try the CLCC poll.
> > > Maybe the modem is in a transitional period (e.g. call being released)
> > > and it can't answer the CLCC properly.  In other words, there's a bug
> > > related to timing of call state changes & CLCC implementation in the
> > > modem firmware.
> > 
> > Yes, it is definitely timing bug. Attached is patch that continues CLCC polling 
> > even after error assuming that CLCC will start working again. It works fine for 
> > me (see log below). It would be nice to get this in ofono git.
> > 
> > ofonod[1188]: App: < \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
> > ofonod[1188]: App: > AT+CLCC\r
> > ofonod[1188]: App: < \r\n+CME ERROR: 100\r\n
> > ofonod[1188]: We are polling CLCC and received an error, retrying...
> > ofonod[1188]: App: > AT+CLCC\r
> > ofonod[1188]: App: < \r\nOK\r\n
> > ofonod[1188]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection 
> > event for id: 1, reason: 2
> 
> I'm wondering if this ofonod log has no timestamps in the log lines? Or
> is this something to be configured?

the output also goes to syslog and there you have timestamps.

Regards

Marcel

Re: Polling CLCC error handling on Option modem (GTA04)

[Jean-Christian de Rivaz]

[-- Attachment #1: Type: text/plain, Size: 2101 bytes --]

Le 06. 03. 12 21:47, Radek Polak a écrit :
> Hi,
> first of all QtMoko [1] now supports ofono as another telephony backend [2]. We
> have also autogenerated qt bindings [3] which can be interesting also for
> other projects.
>
> But now the problem that has already been discussed. If you make call to GTA04
> with ofono running, it starts CLCC polling. After you hangup sometimes
> everything is ok and the call disappears:
>
> fonod[1027]: App:<  \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
> ofonod[1027]: App:>  AT+CLCC\r
> ofonod[1027]: App:<  \r\nOK\r\n
> ofonod[1027]: src/voicecall.c:ofono_voicecall_disconnected() Got disconnection
> event for id: 1, reason: 2
> ofonod[1027]: App:<  \r\n_OSIGQ: 18,0\r\n
> ofonod[1027]: src/network.c:ofono_netreg_strength_notify() strength 58
> ofonod[1027]: App:>  AT+CLCC\r
> ofonod[1027]: App:<  \r\nOK\r\n
>
> but sometimes the modem returns error:
>
> ofonod[1027]: App:<  \r\n+CLCC: 1,1,4,0,0,"+420608828973",145\r\n\r\nOK\r\n
> ofonod[1027]: App:>  AT+CLCC\r
> ofonod[1027]: App:<  \r\n+CME ERROR: 100\r\n
> ofonod[1027]: We are polling CLCC and received an error
> ofonod[1027]: All bets are off for call management
>
> and ofono never reports that the call is removed. The result is that GUI shows
> dialed call forever.
>
> I know that modem should not return error, but it would be nice to have at
> least some workaround. E.g. assume remote hangup or missed call.
>
> Or anyone has better ideas?

I have the feeling that this problem is common to many modems based on 
some Qualcomm chipset/firmware. A workaround will be a good idea to 
solve this issue, because throwing all those modems out of the window 
might be a genocide.

I observed on a SIMCOM modem that show the same issue, that the CLCC 
error is temporary. It seem to occurs when the CLCC command is proceeded 
by the modem at the same time that something change in the calling 
state. The next CLCC command will return the expected result. Can you 
observe that same behavior on your modem ?

Regards,

Jean-Christian

Re: Polling CLCC error handling on Option modem (GTA04)

[Radek Polak]

[-- Attachment #1: Type: text/plain, Size: 610 bytes --]

On Thursday 08 March 2012 21:54:59 Jean-Christian de Rivaz wrote:

> I observed on a SIMCOM modem that show the same issue, that the CLCC
> error is temporary. It seem to occurs when the CLCC command is proceeded
> by the modem at the same time that something change in the calling
> state. The next CLCC command will return the expected result. Can you
> observe that same behavior on your modem ?

Hi,
yes i do. In fact the workaround is now in oFono GIT [1].

Regards

Radek

[1] 
http://git.kernel.org/?p=network/ofono/ofono.git;a=commitdiff;h=ebac438d9325c34bfe22322c6234e25c86e125d7

Re: [Gta04-owner] Polling CLCC error handling on Option modem (GTA04)

[Radek Polak]

[-- Attachment #1: Type: text/plain, Size: 1525 bytes --]

On Tuesday 06 March 2012 20:17:32 Dr. H. Nikolaus Schaller wrote:

> @Radek: is it possible to manually contact the AT interface in this state
> and try if it is still operational and another AT+CLCC would succeed?

It seems after few errors it starts working again - if i understand it right 
(see log below). Btw the probability of +CME ERROR increases with smaller CLCC 
interval.

So ingoring the error and trying again is the way to go for us?

Regards

Radek

AtChat :  F : "+CLCC: 1,1,4,0,0,"+420608828973",145" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "+CLCC: 1,1,4,0,0,"+420608828973",145" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "+CLCC: 1,1,4,0,0,"+420608828973",145" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "+CLCC: 1,1,4,0,0,"+420608828973",145" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "+CME ERROR: 100" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "+CME ERROR: 100" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "+CME ERROR: 100" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "+CME ERROR: 100" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK" 
AtChat :  T : "AT+CLCC" 
AtChat :  F : "OK"

Re: [Gta04-owner] Polling CLCC error handling on Option modem (GTA04)

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 924 bytes --]

Hi Radek,

On 03/06/2012 03:30 PM, Radek Polak wrote:
> On Tuesday 06 March 2012 20:17:32 Dr. H. Nikolaus Schaller wrote:
> 
>> @Radek: is it possible to manually contact the AT interface in this state
>> and try if it is still operational and another AT+CLCC would succeed?
> 
> It seems after few errors it starts working again - if i understand it right 
> (see log below). Btw the probability of +CME ERROR increases with smaller CLCC 
> interval.
> 

FYI, CME ERROR: 100 means: "Unknown Error".  This firmware is rather
helpful here isn't it?

> So ingoring the error and trying again is the way to go for us?
> 

That sounds like your only avenue at this point.  If you're doing this
in oFono, then I would create an Option / GTA04 specific vendor quirk
for the voicecall driver.  When this quirk is set, ignore CME ERROR 100
errors (not any others) and retry the CLCC poll.

Regards,
-Denis