9:50 a.m.
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.
3:49 p.m.
Hi Christopher,
On 07/12/2012 09:50 AM, Christopher Vogl wrote:
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.
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
5:12 a.m.
Hi Denis,
On 12/07/12 22:49, Denis Kenzior wrote:
Hi Christopher,
On 07/12/2012 09:50 AM, Christopher Vogl wrote:
> 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.
>
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.
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.
8:39 a.m.
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
7:31 a.m.
Hi Guillaume,
On 13/07/12 15:39, Guillaume Zajac wrote:
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?
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.
>
> 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: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.
For this APN there is no username and password provided and it also
works like that before I remove the antenna.
> Jan 1 01:20:15 mx31tt01 daemon.info ofonod[810]: PPP:
> gatchat/gatppp.c:ppp_enter_phase() 3
> {...}
> 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: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.
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
> 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?
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()
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.
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.
1:40 p.m.
Hi Guillaume and Denis,
<snip>
> 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.
<snip>
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.
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.
6:56 p.m.
Hi Christopher,
<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'.
That sounds like a firmware bug, we should be able to tell the modem to
abort the attach procedure or detach at any time.
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).
Does sending 'AT+CGACT=0' per 3GPP 27.007 10.1.10 work?
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."
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...
I don't know if this is a firmware or ofono issue as I don't know how this should
be handled correctly.
Sounds like firmware is at fault, or maybe the Telit modem has to be
driven 'differently', but I do not see how.
Regards,
-Denis
3073
days inactive
3121
days old
6 comments
4 participants
participants (4)
-
Chrisopher Vogl -
Christopher Vogl
-
Denis Kenzior -
Guillaume Zajac