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