Re-activating a context.

Hello,

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.

Thanks!

Greetings,

Christopher Vogl

...

Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_initialize_restart_count: current state 6:REQSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_send_configure_request: current state 6:REQSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_process_configure_request: current state 6:REQSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_generate_event: current state 6:REQSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: event: 6 (RCR+), 
action: 2008, new_state: 8 (ACKSENT)
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_send_configure_ack: current state 6:REQSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_process_configure_reject: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_generate_event: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: event: 9 (RCN), 
action: 1028, new_state: 8 (ACKSENT)
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_initialize_restart_count: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_send_configure_request: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_process_configure_nak: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_generate_event: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: event: 9 (RCN), 
action: 1028, new_state: 8 (ACKSENT)
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_initialize_restart_count: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_send_configure_request: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_process_configure_ack: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_generate_event: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: event: 8 (RCA), 
action: 129, new_state: 9 (OPENED)
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: ipcp: 
pppcp_initialize_restart_count: current state 8:ACKSENT
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: PPP: 
gatchat/gatppp.c:ppp_enter_phase() 4
Jan  1 07:56:39 mx31tt01 daemon.debug ofonod[408]: 
drivers/atmodem/gprs-context.c:ppp_connect()
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: IP: 2.200.229.88
Jan  1 07:56:39 mx31tt01 daemon.info ofonod[408]: DNS: 139.7.30.126, 
139.7.30.125
Jan  1 07:56:39 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:pri_activate_callback() 0x1b7dde0
Jan  1 07:56:39 mx31tt01 user.debug connMan[371]: Got connection context 
signal Settings, Val = {'Interface': <'ppp0'>, 'Method': <'static'>, 
'Address': <'2.200.229.88'>, 'Netmask': <'255.255.255.255'>, 'Do
mainNameServers': <['139.7.30.126', '139.7.30.125']>}
Jan  1 07:56:39 mx31tt01 daemon.debug ofonod[408]: 
plugins/udev.c:udev_event() subsystem net add
Jan  1 07:56:39 mx31tt01 daemon.debug ofonod[408]: 
plugins/udev.c:udev_event() subsystem net finished
Jan  1 07:56:39 mx31tt01 user.debug connMan[371]: Got connection context 
signal Active, Val = true
Jan  1 07:56:39 mx31tt01 user.debug connMan[371]: Method is a string static
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: Set up ip ip addr add 
2.200.229.88/32 dev ppp0
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: Domain name servers:
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: 139.7.30.126
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: Adding route ip route 
add 139.7.30.126/32 dev ppp0
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: 139.7.30.125
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: Adding route ip route 
add 139.7.30.125/32 dev ppp0
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: resolv.conf file will 
look like this:
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: nameserver 139.7.30.126 
nameserver 139.7.30.125
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: Writing resolv.conf
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: Setting default route 
for interface ppp0
Jan  1 07:56:39 mx31tt01 user.info connMan[371]: Adding default route 
route add default gw 2.200.229.88 ppp0
Jan  1 07:56:40 mx31tt01 daemon.debug ofonod[408]: 

plugins/udevng.c:check_modem_list()

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.NetworkRegistration.GetProperties method return sender=:1.5 -> dest=:1.16 reply_serial=2

    array [
       dict entry(
          string "Status"
          variant             string "registered"
       )
       dict entry(
          string "Mode"
          variant             string "auto"
       )
       dict entry(
          string "LocationAreaCode"
          variant             uint16 832
       )
       dict entry(
          string "CellId"
          variant             uint32 49481
       )
       dict entry(
          string "Name"
          variant             string ""
       )
       dict entry(
          string "Strength"
          variant             byte 100
       )
    ]

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.ConnectionManager.GetProperties
method return sender=:1.5 -> dest=:1.17 reply_serial=2

    array [
       dict entry(
          string "Attached"
          variant             boolean true
       )
       dict entry(
          string "Bearer"
          variant             string "none"
       )
       dict entry(
          string "RoamingAllowed"
          variant             boolean true
       )
       dict entry(
          string "Powered"
          variant             boolean true
       )
       dict entry(
          string "Suspended"
          variant             boolean false
       )
    ]

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.ConnectionManager.GetContexts
method return sender=:1.5 -> dest=:1.18 reply_serial=2

    array [
       struct {
          object path "/telit_0/context2"
          array [
             dict entry(
                string "Name"
                variant                   string "Internet"
             )
             dict entry(
                string "Active"
                variant                   boolean true
             )
             dict entry(
                string "Type"
                variant                   string "internet"
             )
             dict entry(
                string "Protocol"
                variant                   string "ip"
             )
             dict entry(
                string "AccessPointName"
                variant                   string "web.vodafone.de"
             )
             dict entry(
                string "Username"
                variant                   string ""
             )
             dict entry(
                string "Password"
                variant                   string ""
             )
             dict entry(
                string "Settings"
                variant                   array [
                      dict entry(
                         string "Interface"
                         variant                            string "ppp0"
                      )
                      dict entry(
                         string "Method"
                         variant                            string "static"
                      )
                      dict entry(
                         string "Address"
                         variant                            string 
"2.200.229.88"
                      )
                      dict entry(
                         string "Netmask"
                         variant                            string 
"255.255.255.255"
                      )
                      dict entry(
                         string "DomainNameServers"
                         variant                            array [
                               string "139.7.30.126"
                               string "139.7.30.125"
                            ]
                      )
                   ]
             )
             dict entry(
                string "IPv6.Settings"
                variant                   array [
                   ]
             )
          ]
       }
    ]

After disconnecting the antenna:

Jan  1 08:02:25 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CREG: 2\r\n
Jan  1 08:02:25 mx31tt01 daemon.debug ofonod[408]: 
src/network.c:ofono_netreg_status_notify() /telit_0 status 2 tech -1
Jan  1 08:02:25 mx31tt01 daemon.debug ofonod[408]: 
src/network.c:current_operator_callback() 0x1b79df8, 0x1b80eb0
Jan  1 08:02:25 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:netreg_status_changed() 2
Jan  1 08:02:25 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:netreg_status_changed() 2
Jan  1 08:02:25 mx31tt01 user.debug connMan[371]: Got network 
registration signal Status: 'searching'
Jan  1 08:02:25 mx31tt01 user.err connMan[371]: 
checkAndSetOperatorSelection()
Jan  1 08:02:25 mx31tt01 daemon.info ofonod[408]: Aux: > AT+CGATT=0\r
Jan  1 08:02:25 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGREG: 2\r\n
Jan  1 08:02:25 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:ofono_gprs_status_notify() /telit_0 status 2
Jan  1 08:02:25 mx31tt01 user.debug connMan[371]: Got network 
registration signal Name: ''
Jan  1 08:02:25 mx31tt01 user.debug connMan[371]: Got connection context 
signal Settings, Val = @a{sv} {}
Jan  1 08:02:25 mx31tt01 user.debug connMan[371]: Got connection context 
signal Active, Val = false
Jan  1 08:02:25 mx31tt01 user.info connMan[371]: Connection context has 
been deactivated.
Jan  1 08:02:25 mx31tt01 user.debug connMan[371]: Got connection manager 
signal Attached, Val = false
Jan  1 08:02:25 mx31tt01 user.info connMan[371]: Detached - all contexts 
have been deactivated
Jan  1 08:02:25 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:gprs_remove_context() Unregistering context: /telit_0/context2
Jan  1 08:02:25 mx31tt01 user.debug connMan[371]: Got connection manager 
signal Powered, Val = false
Jan  1 08:02:28 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CME ERROR: 
30\r\n
Jan  1 08:02:28 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:gprs_attach_callback() /telit_0 error = 1
Jan  1 08:02:28 mx31tt01 daemon.info ofonod[408]: Aux: > AT+CGREG?\r
Jan  1 08:02:28 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGREG: 
2,2\r\n\r\nOK\r\n
Jan  1 08:02:28 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:registration_status_cb() /telit_0 error 0 status 2
Jan  1 08:02:28 mx31tt01 daemon.debug ofonod[408]: 

src/gprs.c:ofono_gprs_status_notify() /telit_0 status 2

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.NetworkRegistration.GetProperties method return sender=:1.5 -> dest=:1.21 reply_serial=2

    array [
       dict entry(
          string "Status"
          variant             string "searching"
       )
       dict entry(
          string "Mode"
          variant             string "auto"
       )
       dict entry(
          string "Name"
          variant             string ""
       )
    ]

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.ConnectionManager.GetProperties
method return sender=:1.5 -> dest=:1.22 reply_serial=2

    array [
       dict entry(
          string "Attached"
          variant             boolean false
       )
       dict entry(
          string "RoamingAllowed"
          variant             boolean true
       )
       dict entry(
          string "Powered"
          variant             boolean false
       )
    ]

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.ConnectionManager.GetContexts
method return sender=:1.5 -> dest=:1.23 reply_serial=2

    array [
    ]

After reconnecting the antenna:

Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGEV: ME 
DETACH\r\n
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:ofono_gprs_detached_notify() /telit_0
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CREG: 
1,"0340","143D"\r\n
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/network.c:ofono_netreg_status_notify() /telit_0 status 1 tech -1
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:netreg_status_changed() 1
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got network 
registration signal Status: 'registered'
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got network 
registration signal LocationAreaCode: uint16 832
Jan  1 08:08:48 mx31tt01 user.err connMan[371]: 
checkAndSetOperatorSelection()
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS=3,2\r
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGREG: 0\r\n
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:ofono_gprs_status_notify() /telit_0 status 0
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\nOK\r\n
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS?\r
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+COPS: 
0,2,"26202",0\r\n\r\nOK\r\n
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric 
got mcc: 262, mnc: 02
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: > AT+CIND?\r
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CIND: 
4,99,1,0,0,0,0,0,2\r\n\r\nOK\r\n
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got network 
registration signal CellId: uint32 5181
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got connection manager 
signal Powered, Val = true
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/network.c:ofono_netreg_strength_notify() strength 40
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS=3,0\r
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\nOK\r\n
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS?\r
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got network 
registration signal Strength: byte 0x28
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+COPS: 
0,0,"Vodafone D2",0\r\n\r\nOK\r\n
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
drivers/atmodem/network-registration.c:cops_cb() cops_cb: Vodafone D2, 
262 02 0
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/network.c:current_operator_callback() 0x1b79df8, (nil)
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got network 
registration signal Name: 'Vodafone D2'
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:netreg_status_changed() 1
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: > AT+CGATT=1\r
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got network 
registration signal MobileCountryCode: '262'
Jan  1 08:08:48 mx31tt01 user.debug connMan[371]: Got network 
registration signal MobileNetworkCode: '02'
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\nOK\r\n
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:gprs_attach_callback() /telit_0 error = 0
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: > AT+CGREG?\r
Jan  1 08:08:48 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGREG: 
2,0\r\n\r\nOK\r\n
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:registration_status_cb() /telit_0 error 0 status 0
Jan  1 08:08:48 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:ofono_gprs_status_notify() /telit_0 status 0
Jan  1 08:08:57 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGREG: 2\r\n
Jan  1 08:08:57 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:ofono_gprs_status_notify() /telit_0 status 2
Jan  1 08:08:57 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGREG: 
1,"0340","143D"\r\n
Jan  1 08:08:57 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:ofono_gprs_status_notify() /telit_0 status 1
Jan  1 08:08:57 mx31tt01 user.debug connMan[371]: Got connection manager 
signal Attached, Val = true
Jan  1 08:08:57 mx31tt01 user.info connMan[371]: Attached
Jan  1 08:08:57 mx31tt01 user.debug connMan[371]: Getting first internet 
context ...
Jan  1 08:08:57 mx31tt01 user.debug connMan[371]: No internet context 
found! Adding a new internet context.
Jan  1 08:08:57 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:add_context() Registering new context
Jan  1 08:08:57 mx31tt01 user.debug connMan[371]: Context path: 
/telit_0/context3
Jan  1 08:08:57 mx31tt01 user.debug connMan[371]: Connecting to 
org.ofono.ConnectionContext PropertyChanged signal.
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Connecting to 
org.ofono.ConnectionContext ContextAdded signal.
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Connecting to 
org.ofono.ConnectionContext ContextRemoved signal.
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: set_and_activate_context()
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Setting and Activating 
the Internet connection context.
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: mccmnc = '26202', len = 5
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Provider name '1&1'
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Set AccessPointName: 
web.vodafone.de
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Set Username:
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Set Password:
Jan  1 08:08:58 mx31tt01 user.debug connMan[371]: Trying to set 
context:web.vodafone.de
Jan  1 08:08:58 mx31tt01 daemon.debug ofonod[408]: 
drivers/atmodem/gprs-context.c:at_gprs_activate_primary() cid 1
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CREG: 
1,"0340","C149"\r\n
Jan  1 08:09:18 mx31tt01 daemon.debug ofonod[408]: 
src/network.c:ofono_netreg_status_notify() /telit_0 status 1 tech -1
Jan  1 08:09:18 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:netreg_status_changed() 1
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS=3,2\r
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CGREG: 
1,"0340","C149"\r\n
Jan  1 08:09:18 mx31tt01 daemon.debug ofonod[408]: 
src/gprs.c:ofono_gprs_status_notify() /telit_0 status 1
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: < \r\nOK\r\n
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS?\r
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+COPS: 
0,2,"26202",0\r\n\r\nOK\r\n
Jan  1 08:09:18 mx31tt01 daemon.debug ofonod[408]: 
drivers/atmodem/network-registration.c:cops_numeric_cb() Cops numeric 
got mcc: 262, mnc: 02
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: > AT+CIND?\r
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+CIND: 
4,99,1,0,0,0,0,0,2\r\n\r\nOK\r\n
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS=3,0\r
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: < \r\nOK\r\n
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: > AT+COPS?\r
Jan  1 08:09:18 mx31tt01 daemon.info ofonod[408]: Aux: < \r\n+COPS: 
0,0,"Vodafone D2",0\r\n\r\nOK\r\n
Jan  1 08:09:18 mx31tt01 daemon.debug ofonod[408]: 
drivers/atmodem/network-registration.c:cops_cb() cops_cb: Vodafone D2, 
262 02 0
Jan  1 08:09:18 mx31tt01 daemon.debug ofonod[408]: 
src/network.c:current_operator_callback() 0x1b79df8, 0x1b80eb0
Jan  1 08:09:23 mx31tt01 user.debug connMan[371]: Got connection context 
signal AccessPointName, Val = 'web.vodafone.de'
Jan  1 08:09:23 mx31tt01 user.info connMan[371]: APN: web.vodafone.de
Jan  1 08:09:23 mx31tt01 user.debug connMan[371]: Got network 

registration signal CellId: uint32 49481

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.NetworkRegistration.GetProperties method return sender=:1.5 -> dest=:1.24 reply_serial=2

    array [
       dict entry(
          string "Status"
          variant             string "registered"
       )
       dict entry(
          string "Mode"
          variant             string "auto"
       )
       dict entry(
          string "LocationAreaCode"
          variant             uint16 832
       )
       dict entry(
          string "CellId"
          variant             uint32 49481
       )
       dict entry(
          string "MobileCountryCode"
          variant             string "262"
       )
       dict entry(
          string "MobileNetworkCode"
          variant             string "02"
       )
       dict entry(
          string "Name"
          variant             string "Vodafone D2"
       )
       dict entry(
          string "Strength"
          variant             byte 40
       )
    ]

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.ConnectionManager.GetProperties
method return sender=:1.5 -> dest=:1.25 reply_serial=2

    array [
       dict entry(
          string "Attached"
          variant             boolean true
       )
       dict entry(
          string "RoamingAllowed"
          variant             boolean true
       )
       dict entry(
          string "Powered"
          variant             boolean true
       )
       dict entry(
          string "Suspended"
          variant             boolean false
       )
    ]

dbus-send --system --type=method_call --print-reply --dest=org.ofono /telit_0 org.ofono.ConnectionManager.GetContexts
method return sender=:1.5 -> dest=:1.26 reply_serial=2

    array [
       struct {
          object path "/telit_0/context3"
          array [
             dict entry(
                string "Name"
                variant                   string "Internet"
             )
             dict entry(
                string "Active"
                variant                   boolean false
             )
             dict entry(
                string "Type"
                variant                   string "internet"
             )
             dict entry(
                string "Protocol"
                variant                   string "ip"
             )
             dict entry(
                string "AccessPointName"
                variant                   string "web.vodafone.de"
             )
             dict entry(
                string "Username"
                variant                   string ""
             )
             dict entry(
                string "Password"
                variant                   string ""
             )
             dict entry(
                string "Settings"
                variant                   array [
                      dict entry(
                         string "Method"
                         variant                            string "dhcp"
                      )
                   ]
             )
             dict entry(
                string "IPv6.Settings"
                variant                   array [
                   ]
             )
          ]
       }
    ]

--
Scanned by MailScanner.

Hi Christopher,

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.

Regards,
-Denis

Hi Denis,

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.

Regards,
Christopher

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

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
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
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()
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

--
Scanned by MailScanner.

Hi Christopher,

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?

So your PPP session seems to be well ended.

As you use no username and no password authentication phase is passed through. It is ok.

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.

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.

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

Hi Guillaume,

Thank you very much for your patches, they seem to do what they were intended for.

Sorry for the misleading name in the debug output, but we are not using THE ConnMan. It is just our own simple connection manager which emerged from the ofono test scripts.
We did not start with THE ConnMan because we needed special features like sim switching - we have two sim slots.

Basically we are using upstream ofono but with some patches. Some parts will be submitted for review soon, e.g. sim retry counter, gprs bearer, AT&C0 after PPP link was dropped.
We are also using separate serials for the AT chat and the data/PPP. With some parts we are not sure yet if we can commit anything of it. These parts are hardware specific and set GPIO pins to switch the sim cards. i.e. activate one of two sim slots.
These patches are currently implemented as hooks in telit.c. Maybe there is an elegant generic way to provide the ability to extend ofono with hardware specific features.

For this APN there is no username and password provided and it also works like that before I remove the antenna.

Yes, you are right! Here the the trace:

Jan  1 03:33:21 mx31tt01 daemon.info ofonod[471]: PPP: 
gatchat/gatppp.c:ppp_enter_phase() 0
Jan  1 03:33:21 mx31tt01 daemon.info ofonod[471]: PPP: 
gatchat/gatppp.c:ppp_dead()
Jan  1 03:33:21 mx31tt01 daemon.debug ofonod[471]: 
drivers/atmodem/gprs-context.c:ppp_disconnect() Reason: 2
Jan  1 03:33:21 mx31tt01 daemon.debug ofonod[471]: 
src/gprs.c:pri_activate_callback() 0x1ebdbb0
Jan  1 03:33:21 mx31tt01 daemon.debug ofonod[471]: 

src/gprs.c:pri_activate_callback() Activating context failed with error:
Unknown error type

I tried that before applying your patches and I always got a "in progress error" from ofono.

Now with your patches the activation of the context works for the retry and I get a valid ppp connection.

Trace after activating the context a second time (manually):

Jan  1 03:34:28 mx31tt01 user.debug connMan[402]: Got connection context 
signal Settings, Val = {'Interface': <'ppp0'>, 'Method': <'static'>, 
'Address': <'2.205.178.119'>, 'Netmask': <'255.255.255.255'>, 'D
omainNameServers': <['139.7.30.126', '139.7.30.125']>}
Jan  1 03:34:28 mx31tt01 daemon.debug ofonod[471]: 
plugins/udev.c:udev_event() subsystem net add
Jan  1 03:34:28 mx31tt01 daemon.debug ofonod[471]: 
plugins/udev.c:udev_event() subsystem net finished
Jan  1 03:34:28 mx31tt01 user.debug connMan[402]: Got connection context 
signal Active, Val = true
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: Connection context has 
been activated.
Jan  1 03:34:28 mx31tt01 user.debug connMan[402]: Method is a string static
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: Set up ip ip addr add 
2.205.178.119/32 dev ppp0
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: Domain name servers:
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: 139.7.30.126
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: Adding route ip route 
add 139.7.30.126/32 dev ppp0
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: 139.7.30.125
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: Adding route ip route 
add 139.7.30.125/32 dev ppp0
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: resolv.conf file will 
look like this:
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: nameserver 139.7.30.126 
nameserver 139.7.30.125
Jan  1 03:34:28 mx31tt01 user.info connMan[402]: Writing resolv.conf
Jan  1 03:34:29 mx31tt01 user.info connMan[402]: Setting default route 
for interface ppp0
Jan  1 03:34:29 mx31tt01 user.info connMan[402]: Adding default route 
route add default gw 2.205.178.119 ppp0
Jan  1 03:34:30 mx31tt01 daemon.debug ofonod[471]: 

plugins/udevng.c:check_modem_list()

Thanks a lot for your help so far. You have given me some good points to dig into ofono.

Kind regards,
Christopher

--
Scanned by MailScanner.

Hi Guillaume and Denis,

<snip>

<snip>

I now know why I receive '+CGEV: ME DEACT IP, , 1\r\n'.
According to Telit support this happens because the context does not get deactivated and ofono is trying to request a new IP address although the previous one is still valid.

After the antenna gets disconnected, the modem sends '+CREG: 2' and '+CGREG: 2'.
In consequence drivers/atmodem/gprs-context.c:telit_gprs_detach_shutdown() is called to end ppp connection and 'AT+CGATT=0' is sent.
'AT+CGATT=0' should normally deactivate all active contexts, but it returns '+CME ERROR: 30'. When I try to deactivate the context with +CGACT like ifx does in drivers/ifxmodem/gprs-context.c:ifx_gprs_deactivate_primary(), then I get '+CME ERROR: 0' (phone failure).

Furthermore I thought that when I receive 'NO CARRIER' at least then all context should be deactivated. From a Cinterion manual (as the Telit manual is very poor):
"If the TE wants to close the LCP link the MT may perform an LCP termination request procedure on PPP level. After this LCP termination procedure the MT deactivates the PDP context automatically and the MT returns to V.250 command mode and issues the final result code NO CARRIER."

I don't know if this is a firmware or ofono issue as I don't know how this should be handled correctly.

Regards,

Christopher

--
Scanned by MailScanner.

Hi Christopher,

<snip>

That sounds like a firmware bug, we should be able to tell the modem to abort the attach procedure or detach at any time.

Does sending 'AT+CGACT=0' per 3GPP 27.007 10.1.10 work?

Yes, that is the expected behavior, NO CARRIER means context is deactivated. We've had problems with Huawei modems that try to keep the PPP link alive when network registration is lost. We then had to force-deactivate them by sending the relevant LCP close procedure. But that doesn't seem to be the issue here...

Sounds like firmware is at fault, or maybe the Telit modem has to be driven 'differently', but I do not see how.

Regards,
-Denis