context activation quickly after context deactivation fails

context activation quickly after context deactivation fails

[Cedric Jehasse]

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

Hi,

When i want to change a Property (eg. APN) of an Active
ConnectionContext. I first deactivate the context, wait for a reply
then set the property and re-activate the context.
The problem is i'm already trying to re-activate the context, before
oFono gets a "NO CARRIER" from the modem. oFono tries to send
AT+CGDCONT, but get's a "NO CARRIER" response and fails to activate
the context.
Is there a way to tell if it's ready to re-activate? Should oFono wait
for the "NO CARRIER" before it sends a reply to the deactivation?

Here's a log of the problem
Jan  4 22:14:38 ofonod[3022]:
drivers/atmodem/gprs-context.c:at_gprs_deactivate_primary() cid 1
Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_generate_event: current
state 9:OPENED
Jan  4 22:14:38 ofonod[3022]: PPP: event: 3 (Close), action: 8224,
new_state: 4 (CLOSING)
Jan  4 22:14:38 ofonod[3022]: PPP: lcp:
pppcp_initialize_restart_count: current state 9:OPENED
Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_send_terminate_request:
current state 9:OPENED
Jan  4 22:14:38 ofonod[3022]: PPP: ipcp: pppcp_generate_event: current
state 9:OPENED
Jan  4 22:14:38 ofonod[3022]: PPP: event: 1 (Down), action: 201,
new_state: 1 (STARTING)
Jan  4 22:14:38 ofonod[3022]: PPP: gatchat/gatppp.c:ppp_enter_phase() 5
Jan  4 22:14:38 ofonod[3022]: plugins/udevng.c:remove_device()
/sys/devices/virtual/net/ppp0
Jan  4 22:14:38 ofonod[3022]: plugins/udev.c:udev_event() subsystem net remove
Jan  4 22:14:38 ofonod[3022]: plugins/udev.c:remove_modem()
/devices/virtual/net/ppp0
Jan  4 22:14:38 ofonod[3022]: plugins/udev.c:udev_event() subsystem net finished
Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_process_terminate_ack:
current state 4:CLOSING
Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_generate_event: current
state 4:CLOSING
Jan  4 22:14:38 ofonod[3022]: PPP: event: 11 (RTA), action: 802,
new_state: 2 (CLOSED)
Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_this_layer_finished:
current state 2:CLOSED
Jan  4 22:14:38 ofonod[3022]: PPP: gatchat/gatppp.c:ppp_enter_phase() 0
Jan  4 22:14:38 ofonod[3022]: PPP: gatchat/gatppp.c:ppp_dead()
Jan  4 22:14:38 ofonod[3022]: src/gprs.c:assign_context()
Jan  4 22:14:38 ofonod[3022]: src/gprs.c:assign_context()
gprs[0x557f80] context_driver[0x556a40]
Jan  4 22:14:38 ofonod[3022]:
drivers/atmodem/gprs-context.c:at_gprs_activate_primary() cid 1
Jan  4 22:14:38 ofonod[3022]: Modem: > AT+CGDCONT=1,"IP","test"\r
Jan  4 22:14:39 ofonod[3022]: PCUI: < \r\n^RSSI:17\r\n
Jan  4 22:14:40 ofonod[3022]: PCUI: < \r\n^MODE:5,4\r\n
Jan  4 22:14:40 ofonod[3022]: Modem: < \r\nNO CARRIER\r\n
Jan  4 22:14:40 ofonod[3022]:
drivers/atmodem/gprs-context.c:at_cgdcont_cb() ok 0
Jan  4 22:14:40 ofonod[3022]: src/gprs.c:pri_activate_callback() 0x55dc88
Jan  4 22:14:40 ofonod[3022]: src/gprs.c:pri_activate_callback()
Activating context failed with error: Unknown error type

Thanks,
Cedric

Re: context activation quickly after context deactivation fails

[Denis Kenzior]

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

Hi Cedric,

On 09/03/2012 07:50 AM, Cedric Jehasse wrote:
> Hi,
>
> When i want to change a Property (eg. APN) of an Active
> ConnectionContext. I first deactivate the context, wait for a reply
> then set the property and re-activate the context.
> The problem is i'm already trying to re-activate the context, before
> oFono gets a "NO CARRIER" from the modem. oFono tries to send
> AT+CGDCONT, but get's a "NO CARRIER" response and fails to activate
> the context.
> Is there a way to tell if it's ready to re-activate? Should oFono wait
> for the "NO CARRIER" before it sends a reply to the deactivation?
>
> Here's a log of the problem
> Jan  4 22:14:38 ofonod[3022]:
> drivers/atmodem/gprs-context.c:at_gprs_deactivate_primary() cid 1
> Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_generate_event: current
> state 9:OPENED
> Jan  4 22:14:38 ofonod[3022]: PPP: event: 3 (Close), action: 8224,
> new_state: 4 (CLOSING)
> Jan  4 22:14:38 ofonod[3022]: PPP: lcp:
> pppcp_initialize_restart_count: current state 9:OPENED
> Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_send_terminate_request:
> current state 9:OPENED
> Jan  4 22:14:38 ofonod[3022]: PPP: ipcp: pppcp_generate_event: current
> state 9:OPENED
> Jan  4 22:14:38 ofonod[3022]: PPP: event: 1 (Down), action: 201,
> new_state: 1 (STARTING)
> Jan  4 22:14:38 ofonod[3022]: PPP: gatchat/gatppp.c:ppp_enter_phase() 5
> Jan  4 22:14:38 ofonod[3022]: plugins/udevng.c:remove_device()
> /sys/devices/virtual/net/ppp0
> Jan  4 22:14:38 ofonod[3022]: plugins/udev.c:udev_event() subsystem net remove
> Jan  4 22:14:38 ofonod[3022]: plugins/udev.c:remove_modem()
> /devices/virtual/net/ppp0
> Jan  4 22:14:38 ofonod[3022]: plugins/udev.c:udev_event() subsystem net finished
> Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_process_terminate_ack:
> current state 4:CLOSING
> Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_generate_event: current
> state 4:CLOSING
> Jan  4 22:14:38 ofonod[3022]: PPP: event: 11 (RTA), action: 802,
> new_state: 2 (CLOSED)
> Jan  4 22:14:38 ofonod[3022]: PPP: lcp: pppcp_this_layer_finished:
> current state 2:CLOSED
> Jan  4 22:14:38 ofonod[3022]: PPP: gatchat/gatppp.c:ppp_enter_phase() 0
> Jan  4 22:14:38 ofonod[3022]: PPP: gatchat/gatppp.c:ppp_dead()
> Jan  4 22:14:38 ofonod[3022]: src/gprs.c:assign_context()
> Jan  4 22:14:38 ofonod[3022]: src/gprs.c:assign_context()
> gprs[0x557f80] context_driver[0x556a40]
> Jan  4 22:14:38 ofonod[3022]:
> drivers/atmodem/gprs-context.c:at_gprs_activate_primary() cid 1
> Jan  4 22:14:38 ofonod[3022]: Modem:>  AT+CGDCONT=1,"IP","test"\r
> Jan  4 22:14:39 ofonod[3022]: PCUI:<  \r\n^RSSI:17\r\n
> Jan  4 22:14:40 ofonod[3022]: PCUI:<  \r\n^MODE:5,4\r\n
> Jan  4 22:14:40 ofonod[3022]: Modem:<  \r\nNO CARRIER\r\n
> Jan  4 22:14:40 ofonod[3022]:
> drivers/atmodem/gprs-context.c:at_cgdcont_cb() ok 0
> Jan  4 22:14:40 ofonod[3022]: src/gprs.c:pri_activate_callback() 0x55dc88
> Jan  4 22:14:40 ofonod[3022]: src/gprs.c:pri_activate_callback()
> Activating context failed with error: Unknown error type
>

It does indeed sound like oFono is not waiting for the final response, 
in this case a 'NO CARRIER'.  Can you try a highly experimental patch 
(attached) and tell me if something along these lines would work for 
your case?

Regards,
-Denis



[-- Warning: decoded text below may be mangled, UTF-8 assumed --]
[-- Attachment #2: 0001-gprs-experimental-no-carrier-fix.patch --]
[-- Type: text/x-patch, Size: 1789 bytes --]

>From ec0798643cad94c5f337c891fe7447003613ca54 Mon Sep 17 00:00:00 2001
From: Denis Kenzior <denkenz@gmail.com>
Date: Wed, 5 Sep 2012 14:40:06 -0500
Subject: [PATCH] gprs: experimental no carrier fix

---
 drivers/atmodem/gprs-context.c |   21 +++++++++++++++------
 1 files changed, 15 insertions(+), 6 deletions(-)

diff --git a/drivers/atmodem/gprs-context.c b/drivers/atmodem/gprs-context.c
index 3694c27..4d5ed91 100644
--- a/drivers/atmodem/gprs-context.c
+++ b/drivers/atmodem/gprs-context.c
@@ -110,6 +110,19 @@ static void ppp_disconnect(GAtPPPDisconnectReason reason, gpointer user_data)
 	g_at_ppp_unref(gcd->ppp);
 	gcd->ppp = NULL;
 
+	/*
+	 * If the channel of gcd->chat is NULL, it might cause
+	 * gprs_context_remove get called and the gprs context will be
+	 * removed.
+	 */
+	g_at_chat_resume(gcd->chat);
+}
+
+static void no_carrier_notify(GAtResult *result, gpointer user_data)
+{
+	struct ofono_gprs_context *gc = user_data;
+	struct gprs_context_data *gcd = ofono_gprs_context_get_data(gc);
+
 	switch (gcd->state) {
 	case STATE_ENABLING:
 		CALLBACK_WITH_FAILURE(gcd->cb, gcd->cb_data);
@@ -124,12 +137,6 @@ static void ppp_disconnect(GAtPPPDisconnectReason reason, gpointer user_data)
 
 	gcd->active_context = 0;
 	gcd->state = STATE_IDLE;
-	/*
-	 * If the channel of gcd->chat is NULL, it might cause
-	 * gprs_context_remove get called and the gprs context will be
-	 * removed.
-	 */
-	g_at_chat_resume(gcd->chat);
 }
 
 static gboolean setup_ppp(struct ofono_gprs_context *gc)
@@ -363,6 +370,8 @@ static int at_gprs_context_probe(struct ofono_gprs_context *gc,
 		return 0;
 
 	g_at_chat_register(chat, "+CGEV:", cgev_notify, FALSE, gc, NULL);
+	g_at_chat_register(chat, "NO CARRIER", no_carrier_notify,
+				FALSE, gc, NULL);
 
 	return 0;
 }
-- 
1.7.8.6

Re: context activation quickly after context deactivation fails

[Cedric Jehasse]

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

Hi Denis,

with the patch i don't get a reply when deactivating the context. From
the on it's not possible to activate the context, because the
operation is still in progress.
This is a log of the deactivation:

Jan  1 03:13:05 ofonod[6856]:
drivers/atmodem/gprs-context.c:at_gprs_deactivate_primary() cid 1
Jan  1 03:13:05 ofonod[6856]: PPP: lcp: pppcp_generate_event: current
state 9:OPENED
Jan  1 03:13:05 ofonod[6856]: PPP: event: 3 (Close), action: 8224,
new_state: 4 (CLOSING)
Jan  1 03:13:05 ofonod[6856]: PPP: lcp:
pppcp_initialize_restart_count: current state 9:OPENED
Jan  1 03:13:05 ofonod[6856]: PPP: lcp: pppcp_send_terminate_request:
current state 9:OPENED
Jan  1 03:13:05 ofonod[6856]: PPP: ipcp: pppcp_generate_event: current
state 9:OPENED
Jan  1 03:13:05 ofonod[6856]: PPP: event: 1 (Down), action: 201,
new_state: 1 (STARTING)
Jan  1 03:13:05 ofonod[6856]: PPP: gatchat/gatppp.c:ppp_enter_phase() 5
Jan  1 03:13:07 ofonod[6856]: PCUI: < \r\n^MODE:5,4\r\n
Jan  1 03:13:07 ofonod[6856]: Modem: < \r\nNO CARRIER\r\n
Jan  1 03:13:08 ofonod[6856]: PCUI: < \r\n^RSSI:18\r\n
Jan  1 03:13:11 ofonod[6856]: PCUI: < \r\n^RSSI:18\r\n

thanks,
Cedric

Re: context activation quickly after context deactivation fails

[Denis Kenzior]

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

Hi Cedric,

On 09/06/2012 09:09 AM, Cedric Jehasse wrote:
> Hi Denis,
>
> with the patch i don't get a reply when deactivating the context. From
> the on it's not possible to activate the context, because the
> operation is still in progress.
> This is a log of the deactivation:
>
> Jan  1 03:13:05 ofonod[6856]:
> drivers/atmodem/gprs-context.c:at_gprs_deactivate_primary() cid 1
> Jan  1 03:13:05 ofonod[6856]: PPP: lcp: pppcp_generate_event: current
> state 9:OPENED
> Jan  1 03:13:05 ofonod[6856]: PPP: event: 3 (Close), action: 8224,
> new_state: 4 (CLOSING)
> Jan  1 03:13:05 ofonod[6856]: PPP: lcp:
> pppcp_initialize_restart_count: current state 9:OPENED
> Jan  1 03:13:05 ofonod[6856]: PPP: lcp: pppcp_send_terminate_request:
> current state 9:OPENED
> Jan  1 03:13:05 ofonod[6856]: PPP: ipcp: pppcp_generate_event: current
> state 9:OPENED
> Jan  1 03:13:05 ofonod[6856]: PPP: event: 1 (Down), action: 201,
> new_state: 1 (STARTING)
> Jan  1 03:13:05 ofonod[6856]: PPP: gatchat/gatppp.c:ppp_enter_phase() 5
> Jan  1 03:13:07 ofonod[6856]: PCUI:<  \r\n^MODE:5,4\r\n
> Jan  1 03:13:07 ofonod[6856]: Modem:<  \r\nNO CARRIER\r\n
> Jan  1 03:13:08 ofonod[6856]: PCUI:<  \r\n^RSSI:18\r\n
> Jan  1 03:13:11 ofonod[6856]: PCUI:<  \r\n^RSSI:18\r\n

Looks like I got the chat instances mixed up since the NO CARRIER is not 
being picked up.

Can you change:
+       g_at_chat_register(chat, "NO CARRIER", no_carrier_notify,
+                               FALSE, gc, NULL);

to read:

+       g_at_chat_register(gcd->chat, "NO CARRIER", no_carrier_notify,
+                               FALSE, gc, NULL);

Regards,
-Denis

Re: context activation quickly after context deactivation fails

[Cedric Jehasse]

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

Hi Dennis,

> Can you change:
> +       g_at_chat_register(chat, "NO CARRIER", no_carrier_notify,
> +                               FALSE, gc, NULL);
>
> to read:
>
> +       g_at_chat_register(gcd->chat, "NO CARRIER", no_carrier_notify,
> +                               FALSE, gc, NULL);
>

it's working now!

Thanks,
Cedric