From: Guillaume Zajac <guillaume.zajac@linux.intel.com>
To: ofono@ofono.org
Subject: Re: Re-activating a context.
Date: Fri, 13 Jul 2012 15:39:37 +0200 [thread overview]
Message-ID: <50002519.3060105@linux.intel.com> (raw)
In-Reply-To: <4FFFF48B.7040903@hale.at>
[-- Attachment #1: Type: text/plain, Size: 28686 bytes --]
Hi Christopher,
On 13/07/2012 12:12, Christopher Vogl wrote:
>>>
>>> I am trying to simulate a connection loss and after a valid ppp
>>> connection I disconnect the antenna to get detached from GPRS.
>>> After reconnecting the antenna everything seems to work fine just until
>>> activating the context.
>>>
>>> Ofono seems to get stuck in
>>> drivers/atmodem/gprs-context.c:at_gprs_activate_primary() and
>>> AT+CGDCONT=1 is missing on the debug output.
>>> When I retry to activate the context after some minutes with a
>>> dbus-send
>>> call, I receive an operation in progress error.
>>>
>>> Below I have attached ofono's debug output and dbus-send calls for
>>> important interfaces
>>> - before removing the antenna
>>> - after removing the antenna
>>> - after reconnecting the antenna
>>>
>>> Modem in use: Telit UC864-G
>>>
>>> connMan in the debug output is my own simple connection manger. I am
>>> not
>>> sure if I missed to set some ofono state or if there is a known issue.
>>> I really would appreciate a hint in this case.
>>>
>>
>> To me it looks like your PPP connection has not been dropped when the
>> antenna has been removed. Today oFono assumes that the PPP
>> connection will be dropped by the modem in this case, and your modem
>> does not do this. This leads to problems because the AT channel on
>> which the PPP connection is being run can not accept additional
>> commands. This is why you're not seeing the CGDCONT.
>>
>> A while ago Guillaume posted a patch to fix this problem (we saw this
>> with Huawei PPP based devices). The patch looked good to me but
>> needed further testing (e.g. for regressions). Can you dig the
>> mailing archives and test that patch?
>>
>> Or maybe Guillaume will be nice enough to repost it to the mailing list.
>
>
> Thanks Denis!
> I found the patch from Guillaume and applied it (ofono 1.7 & 1.8).
> The ppp connection seems to get dropped now when I remove the antenna
> but does not come up again correctly when I reconnect the antenna.
>
I have a new version but only naming is changed but the main goal of
this set of patches is to end properly the PPP connection which goal you
seem to have reached.
I guess you are using upstream oFono and ConnMan version right?
>
> After disconnecting the antenna:
>
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CREG: 2\r\n
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> src/network.c:ofono_netreg_status_notify() /telit_0 status 2 tech -1
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> src/network.c:current_operator_callback() 0x1bed30, (nil)
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:netreg_status_changed() 2
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: Aux: > AT+CGATT=0\r
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGREG:
> 2\r\n
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:ofono_gprs_status_notify() /telit_0 status 2
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:at_gprs_release_primary() cid 1
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 9:OPENED
> Jan 1 01:18:53 mx31tt01 user.debug connMan[803]: Got network
> registration signal Status: 'searching'
> Jan 1 01:18:53 mx31tt01 user.err connMan[803]:
> checkAndSetOperatorSelection()
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: event: 3
> (Close), action: 8224, new_state: 4 (CLOSING)
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_initialize_restart_count: current state 9:OPENED
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_send_terminate_request: current state 9:OPENED
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 9:OPENED
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: event: 1
> (Down), action: 201, new_state: 1 (STARTING)
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 5
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> plugins/udevng.c:remove_device() /sys/devices/virtual/net/ppp0
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> plugins/udev.c:udev_event() subsystem net remove
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> plugins/udev.c:remove_modem() /devices/virtual/net/ppp0
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> plugins/udev.c:udev_event() subsystem net finished
> Jan 1 01:18:53 mx31tt01 user.debug connMan[803]: Got connection
> manager signal Attached, Val = false
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_process_terminate_ack: current state 4:CLOSING
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 4:CLOSING
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: event: 11
> (RTA), action: 802, new_state: 2 (CLOSED)
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_this_layer_finished: current state 2:CLOSED
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 0
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:at_gprs_deactivate_primary() cid 1
> Jan 1 01:18:53 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_dead()
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:ppp_disconnect()
> Jan 1 01:18:53 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:gprs_remove_context() Unregistering context: /telit_0/context1
> Jan 1 01:18:53 mx31tt01 user.debug connMan[803]: Got connection
> manager signal Powered, Val = false
> Jan 1 01:18:57 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CME
> ERROR: 30\r\n
> Jan 1 01:18:57 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:gprs_attach_callback() /telit_0 error = 1
> Jan 1 01:18:57 mx31tt01 daemon.info ofonod[810]: Aux: > AT+CGREG?\r
> Jan 1 01:18:57 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGREG:
> 2,2\r\n\r\nOK\r\n
> Jan 1 01:18:57 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:registration_status_cb() /telit_0 error 0 status 2
> Jan 1 01:18:57 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:ofono_gprs_status_notify() /telit_0 status 2
>
> Jan 1 01:19:30 mx31tt01 daemon.info ofonod[810]: Modem: < \r\nNO
> CARRIER\r\n
>
>
So your PPP session seems to be well ended.
>
>
> After reconnecting the antenna:
>
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Modem: < \r\n+CGEV:
> ME DETACH\r\n
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGEV: ME
> DETACH\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:ofono_gprs_detached_notify() /telit_0
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Modem: < \r\n+CREG:
> 1,"0340","C149"\r\n
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CREG:
> 1,"0340","C149"\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/network.c:ofono_netreg_status_notify() /telit_0 status 1 tech 3
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal Status: 'registered'
> Jan 1 01:20:12 mx31tt01 user.err connMan[803]:
> checkAndSetOperatorSelection()
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:netreg_status_changed() 1
> Jan 1 01:20:12 mx31tt01 user.notice ttsession: void
> hale::gtk::StatusBar::on_tech_changed(const std::string&), this =
> 0x1316000, New technology: edge
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: > AT+COPS=3,2\r
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGREG:
> 0\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:ofono_gprs_status_notify() /telit_0 status 0
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Modem: < \r\n+CGREG:
> 0\r\n
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal LocationAreaCode: uint16 832
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal CellId: uint32 49481
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal Technology: 'edge'
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got connection
> manager signal Powered, Val = true
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\nOK\r\n
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: > AT+COPS?\r
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+COPS:
> 0,2,"26202",0\r\n\r\nOK\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric
> got mcc: 262, mnc: 02
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: > AT+CIND?\r
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CIND:
> 4,99,1,0,0,0,0,0,1\r\n\r\nOK\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/network.c:ofono_netreg_strength_notify() strength 20
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal Strength: byte 0x14
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: > AT+CGATT=1\r
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\nOK\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:gprs_attach_callback() /telit_0 error = 0
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: > AT+COPS=3,0\r
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\nOK\r\n
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: > AT+COPS?\r
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+COPS:
> 0,0,"Vodafone D2",0\r\n\r\nOK\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/network-registration.c:cops_cb() cops_cb: Vodafone D2,
> 262 02 0
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/network.c:current_operator_callback() 0x1bed30, (nil)
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal Name: 'Vodafone D2'
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:netreg_status_changed() 1
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal MobileCountryCode: '262'
> Jan 1 01:20:12 mx31tt01 user.debug connMan[803]: Got network
> registration signal MobileNetworkCode: '02'
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: > AT+CGREG?\r
> Jan 1 01:20:12 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGREG:
> 2,0\r\n\r\nOK\r\n
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:registration_status_cb() /telit_0 error 0 status 0
> Jan 1 01:20:12 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:ofono_gprs_status_notify() /telit_0 status 0
> Jan 1 01:20:14 mx31tt01 daemon.info ofonod[810]: Modem: < \r\n+CGREG:
> 2\r\n
> Jan 1 01:20:14 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGREG:
> 2\r\n
> Jan 1 01:20:14 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:ofono_gprs_status_notify() /telit_0 status 2
> Jan 1 01:20:14 mx31tt01 daemon.info ofonod[810]: Modem: < \r\n+CGREG:
> 1,"0340","C149"\r\n
> Jan 1 01:20:14 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGREG:
> 1,"0340","C149"\r\n
> Jan 1 01:20:14 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:ofono_gprs_status_notify() /telit_0 status 1
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: Got connection
> manager signal Attached, Val = true
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: Getting first
> internet context ...
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: No internet context
> found! Adding a new internet context.
> Jan 1 01:20:14 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:add_context() Registering new context
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: Context path:
> /telit_0/context2
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: Connecting to
> org.ofono.ConnectionContext PropertyChanged signal.
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: Connecting to
> org.ofono.ConnectionContext ContextAdded signal.
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: Connecting to
> org.ofono.ConnectionContext ContextRemoved signal.
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]:
> set_and_activate_context()
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: Setting and
> Activating the Internet connection context.
> Jan 1 01:20:14 mx31tt01 user.debug connMan[803]: mccmnc = '26202',
> len = 5
> Jan 1 01:20:15 mx31tt01 user.debug connMan[803]: Provider name '1&1'
> Jan 1 01:20:15 mx31tt01 user.debug connMan[803]: Set AccessPointName:
> web.vodafone.de
> Jan 1 01:20:15 mx31tt01 user.debug connMan[803]: Set Username:
> Jan 1 01:20:15 mx31tt01 user.debug connMan[803]: Set Password:
> Jan 1 01:20:15 mx31tt01 user.debug connMan[803]: Trying to set
> context:web.vodafone.de
> Jan 1 01:20:15 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:at_gprs_activate_primary() cid 1
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: Modem: >
> AT+CGDCONT=1,"IP","web.vodafone.de"\r
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: Modem: < \r\nOK\r\n
> Jan 1 01:20:15 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:at_cgdcont_cb() ok 1
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: Modem: >
> AT+CGDATA="PPP",1\r
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: Modem: <
> \r\nCONNECT\r\n
> Jan 1 01:20:15 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:at_cgdata_cb() ok 1
> Jan 1 01:20:15 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:setup_ppp()
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 0:INITIAL
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: event: 0 (Up),
> action: 2, new_state: 2 (CLOSED)
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 2:CLOSED
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: event: 2
> (Open), action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_initialize_restart_count: current state 2:CLOSED
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_send_configure_request: current state 2:CLOSED
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 1
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_process_configure_request: current state 6:REQSENT
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: event: 6
> (RCR+), action: 2008, new_state: 8 (ACKSENT)
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_send_configure_ack: current state 6:REQSENT
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_process_configure_ack: current state 8:ACKSENT
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 8:ACKSENT
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: event: 8 (RCA),
> action: 129, new_state: 9 (OPENED)
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_initialize_restart_count: current state 8:ACKSENT
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 2
As you use no username and no password authentication phase is passed
through. It is ok.
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 3
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 0:INITIAL
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: event: 2
> (Open), action: 401, new_state: 1 (STARTING)
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 1:STARTING
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: event: 0 (Up),
> action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_initialize_restart_count: current state 1:STARTING
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 1:STARTING
> Jan 1 01:20:16 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_process_configure_nak: current state 6:REQSENT
> Jan 1 01:20:16 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:16 mx31tt01 daemon.info ofonod[810]: PPP: event: 9 (RCN),
> action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:16 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_initialize_restart_count: current state 6:REQSENT
> Jan 1 01:20:16 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:17 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_process_configure_nak: current state 6:REQSENT
> Jan 1 01:20:17 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:17 mx31tt01 daemon.info ofonod[810]: PPP: event: 9 (RCN),
> action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:17 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_initialize_restart_count: current state 6:REQSENT
> Jan 1 01:20:17 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:18 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_process_configure_nak: current state 6:REQSENT
> Jan 1 01:20:18 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:18 mx31tt01 daemon.info ofonod[810]: PPP: event: 9 (RCN),
> action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:18 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_initialize_restart_count: current state 6:REQSENT
> Jan 1 01:20:18 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:19 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_process_configure_nak: current state 6:REQSENT
> Jan 1 01:20:19 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:19 mx31tt01 daemon.info ofonod[810]: PPP: event: 9 (RCN),
> action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:19 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_initialize_restart_count: current state 6:REQSENT
> Jan 1 01:20:19 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:20 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_process_configure_nak: current state 6:REQSENT
> Jan 1 01:20:20 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:20 mx31tt01 daemon.info ofonod[810]: PPP: event: 9 (RCN),
> action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:20 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_initialize_restart_count: current state 6:REQSENT
> Jan 1 01:20:20 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:21 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_process_configure_nak: current state 6:REQSENT
> Jan 1 01:20:21 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:21 mx31tt01 daemon.info ofonod[810]: PPP: event: 9 (RCN),
> action: 1026, new_state: 6 (REQSENT)
> Jan 1 01:20:21 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_initialize_restart_count: current state 6:REQSENT
> Jan 1 01:20:21 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:21 mx31tt01 daemon.info ofonod[810]: Aux: < \r\n+CGEV: ME
> DEACT IP, , 1\r\n
It seems IP Control Protocol is failing so that modem cannot receive the
IP configuration from the network.
IP phase is deactivated by the modem itself.
I don't know what is happening there.
> Jan 1 01:20:24 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:24 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:24 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:24 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:27 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:27 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:27 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:27 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:30 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:30 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:30 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:30 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:33 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:33 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:33 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:33 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:36 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:36 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:36 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:36 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:39 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:39 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:39 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:39 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:40 mx31tt01 user.debug connMan[803]: Got connection
> context signal AccessPointName, Val = 'web.vodafone.de'
> Jan 1 01:20:40 mx31tt01 user.info connMan[803]: APN: web.vodafone.de
> Jan 1 01:20:42 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:42 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:42 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:42 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:45 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:45 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:45 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:45 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:48 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:48 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:48 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 1006, new_state: 6 (REQSENT)
> Jan 1 01:20:48 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_send_configure_request: current state 6:REQSENT
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_timeout: current state 6:REQSENT
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 6:REQSENT
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: event: 5 (TO-),
> action: 803, new_state: 3 (STOPPED)
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_this_layer_finished: current state 3:STOPPED
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 3:STOPPED
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: event: 3
> (Close), action: 2, new_state: 2 (CLOSED)
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 9:OPENED
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: event: 3
> (Close), action: 8224, new_state: 4 (CLOSING)
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_initialize_restart_count: current state 9:OPENED
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_send_terminate_request: current state 9:OPENED
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: ipcp:
> pppcp_generate_event: current state 2:CLOSED
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP: event: 1
> (Down), action: 0, new_state: 0 (INITIAL)
> Jan 1 01:20:51 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 5
> Jan 1 01:20:54 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_timeout: current state 4:CLOSING
> Jan 1 01:20:54 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 4:CLOSING
> Jan 1 01:20:54 mx31tt01 daemon.info ofonod[810]: PPP: event: 4 (TO+),
> action: 8004, new_state: 4 (CLOSING)
> Jan 1 01:20:54 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_send_terminate_request: current state 4:CLOSING
> Jan 1 01:20:57 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_timeout: current state 4:CLOSING
> Jan 1 01:20:57 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_generate_event: current state 4:CLOSING
> Jan 1 01:20:57 mx31tt01 daemon.info ofonod[810]: PPP: event: 5 (TO-),
> action: 802, new_state: 2 (CLOSED)
> Jan 1 01:20:57 mx31tt01 daemon.info ofonod[810]: PPP: lcp:
> pppcp_this_layer_finished: current state 2:CLOSED
> Jan 1 01:20:57 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 0
> Jan 1 01:20:57 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_dead()
> Jan 1 01:20:57 mx31tt01 daemon.debug ofonod[810]:
> drivers/atmodem/gprs-context.c:ppp_disconnect()
I guess the disconnect reason is G_AT_PPP_REASON_IPCP_FAIL( according to
gatppp.h enum) but you could still add a trace in ppp_disconnect() into
drivers/atmodem/gprs-context.c:
DBG("Reason: %d", reason);
to be sure.
> Jan 1 01:20:57 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:pri_activate_callback() 0x1ce500
> Jan 1 01:20:57 mx31tt01 daemon.debug ofonod[810]:
> src/gprs.c:pri_activate_callback() Activating context failed with
> error: Unknown error type
>
Did you try to activate manually the context from oFono test scripts
after this failure?
Although ConnMan is correctly waiting for the modem to be attached to
the network before trying to reconnect, maybe modem is not internally
ready to reconnect. The reason might be PPP session ending is initiated
by oFono core and not the modem itself.
With Huawei modems we also noticed that automatic reconnection was
sometime failing also. But testing conditions were not the same as we
could not disconnect the antenna.
Anyway I am not a PPP expert but something wrong is happening between
the network and your modem because not IP configuration is sent by the
network.
Kind regards,
Guillaume
next prev parent reply other threads:[~2012-07-13 13:39 UTC|newest]
Thread overview: 7+ messages / expand[flat|nested] mbox.gz Atom feed top
2012-07-12 14:50 Re-activating a context Christopher Vogl
2012-07-12 20:49 ` Denis Kenzior
2012-07-13 10:12 ` Christopher Vogl
2012-07-13 13:39 ` Guillaume Zajac [this message]
2012-07-16 12:31 ` Christopher Vogl
2012-08-29 18:40 ` Chrisopher Vogl
2012-08-29 23:56 ` Denis Kenzior
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=50002519.3060105@linux.intel.com \
--to=guillaume.zajac@linux.intel.com \
--cc=ofono@ofono.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.