u-Blox SARA on Raspberry Pi - No connection

Thu Jun 30 22:11:15 UTC 2016

Hello,

I am using the ModemManager and network-manager packages provided by the
Raspbian jessie distribution (network-manager 0.9.10.0-7 modemmanager
1.4.0-1)
with a u-Blox SARA-U270 device connected as a serial device over the UART.
I have successfully obtained an IP address using AT commands at the serial
console, so the modem is certainly working.

However, I have been unable to get it to obtain an IP address using network-
manager. Using ModemManager I have verified that the device is registered on
the network but when attempting to obtain an IP address it fails.

This is a bit of a head-scratcher, as it is successfully using the "generic"
plugin.

The logs are as follows:
ModemManager[1129]: <info>  [1467261807.354155]
[mm-iface-modem-simple.c:641] connect_auth_ready(): Simple connect
started...
ModemManager[1129]: <debug> [1467261807.354270]
[mm-iface-modem-simple.c:651] connect_auth_ready():    PIN: unspecified
ModemManager[1129]: <debug> [1467261807.354307]
[mm-iface-modem-simple.c:653] connect_auth_ready():    Operator ID:
unspecified
ModemManager[1129]: <debug> [1467261807.354341]
[mm-iface-modem-simple.c:655] connect_auth_ready():    Allowed roaming: no
ModemManager[1129]: <debug> [1467261807.354374]
[mm-iface-modem-simple.c:657] connect_auth_ready():    APN: vodafone
ModemManager[1129]: <debug> [1467261807.354406]
[mm-iface-modem-simple.c:665] connect_auth_ready():    IP family:
unspecified
ModemManager[1129]: <debug> [1467261807.354460]
[mm-iface-modem-simple.c:670] connect_auth_ready():    Allowed
authentication: none, pap, chap, mschap, mschapv2, eap
ModemManager[1129]: <debug> [1467261807.354498]
[mm-iface-modem-simple.c:675] connect_auth_ready():    User: unspecified
ModemManager[1129]: <debug> [1467261807.354532]
[mm-iface-modem-simple.c:677] connect_auth_ready():    Password: unspecified
ModemManager[1129]: <debug> [1467261807.354565]
[mm-iface-modem-simple.c:679] connect_auth_ready():    Number: *99#
ModemManager[1129]: <info>  [1467261807.354597]
[mm-iface-modem-simple.c:469] connection_step(): Simple connect state
(4/8): Wait to get fully enabled
ModemManager[1129]: <info>  [1467261807.354744]
[mm-iface-modem-simple.c:478] connection_step(): Simple connect state
(5/8): Register
ModemManager[1129]: <debug> [1467261807.354818] [mm-iface-modem-3gpp.c:390]
mm_iface_modem_3gpp_register_in_network(): Already registered in network
'53001', automatic registration not launched...
ModemManager[1129]: <info>  [1467261807.355410]
[mm-iface-modem-simple.c:501] connection_step(): Simple connect state
(6/8): Bearer
ModemManager[1129]: <debug> [1467261807.356146]
[mm-iface-modem-simple.c:574] connection_step(): Using already existing
bearer at '/org/freedesktop/ModemManager1/Bearer/1'...
ModemManager[1129]: <info>  [1467261807.356859]
[mm-iface-modem-simple.c:583] connection_step(): Simple connect state
(7/8): Connect
ModemManager[1129]: <debug> [1467261807.357619] [mm-base-bearer.c:590]
mm_base_bearer_connect(): Connecting bearer
'/org/freedesktop/ModemManager1/Bearer/1'
ModemManager[1129]: <info>  [1467261807.358336] [mm-iface-modem.c:1392]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
connecting)
ModemManager[1129]: <debug> [1467261807.359947]
[mm-broadband-bearer.c:1254] connect(): Launching 3GPP connection attempt
with APN 'vodafone'
ModemManager[1129]: <debug> [1467261807.360046] [mm-broadband-bearer.c:177]
detailed_connect_context_new(): No specific IP family requested, defaulting
to ipv4
ModemManager[1129]: <debug> [1467261807.360354]
[mm-broadband-bearer.c:1044] connect_3gpp(): Looking for best CID...
ModemManager[1129]: <debug> [1467261807.361190] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 2 (open)
ModemManager[1129]: <debug> [1467261807.364994] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CGDCONT?<CR>'
ModemManager[1129]: <debug> [1467261807.381627] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261807.382289] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>+CG'
ModemManager[1129]: <debug> [1467261807.382775] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'DC'
ModemManager[1129]: <debug> [1467261807.383205] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'ONT'
ModemManager[1129]: <debug> [1467261807.383399] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ':'
ModemManager[1129]: <debug> [1467261807.383529] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ' '
ModemManager[1129]: <debug> [1467261807.383927] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '1,'
ModemManager[1129]: <debug> [1467261807.384123] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '"'
ModemManager[1129]: <debug> [1467261807.384262] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'I'
ModemManager[1129]: <debug> [1467261807.384386] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'P'
ModemManager[1129]: <debug> [1467261807.384510] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '"'
ModemManager[1129]: <debug> [1467261807.384968] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ',"'
ModemManager[1129]: <debug> [1467261807.385198] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'vo'
ModemManager[1129]: <debug> [1467261807.385614] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'da'
ModemManager[1129]: <debug> [1467261807.385827] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'f'
ModemManager[1129]: <debug> [1467261807.385970] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'o'
ModemManager[1129]: <debug> [1467261807.387359] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'ne","0.'
ModemManager[1129]: <debug> [1467261807.388617] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '0.0.0",0'
ModemManager[1129]: <debug> [1467261807.389870] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ',0<CR><LF><CR><LF>O'
ModemManager[1129]: <debug> [1467261807.391135] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K<CR><LF>'
ModemManager[1129]: <debug> [1467261807.392491] [mm-broadband-bearer.c:961]
parse_pdp_list(): Found '1' PDP contexts
ModemManager[1129]: <debug> [1467261807.393376] [mm-broadband-bearer.c:970]
parse_pdp_list():   PDP context [cid=1] [type='ipv4'] [apn='vodafone']
ModemManager[1129]: <debug> [1467261807.394449] [mm-broadband-bearer.c:994]
parse_pdp_list(): Found PDP context with CID 1 and PDP type ipv4 for APN
'vodafone'
ModemManager[1129]: <debug> [1467261807.395517] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 3 (open)
ModemManager[1129]: <debug> [1467261807.396434] [mm-broadband-bearer.c:214]
common_get_at_data_port(): Connection through a plain serial AT port (ttyS0)
ModemManager[1129]: <debug> [1467261807.397539] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 4 (open)
ModemManager[1129]: <debug> [1467261807.398570] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 3 (close)
ModemManager[1129]: <debug> [1467261807.399632] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'ATD*99***1#<CR>'
ModemManager[1129]: <debug> [1467261807.416728] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261807.417303] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>CO'
ModemManager[1129]: <debug> [1467261807.417775] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'NNE'
ModemManager[1129]: <debug> [1467261807.418248] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'CT<CR>'
ModemManager[1129]: <debug> [1467261807.418679] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261807.419209] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 2 (close)
ModemManager[1129]: <debug> [1467261807.419753] [mm-port.c:95]
mm_port_set_connected(): (ttyS0): port now connected
ModemManager[1129]: <debug> [1467261807.420167] [mm-base-bearer.c:488]
connect_ready(): Connected bearer '/org/freedesktop/ModemManager1/Bearer/1'
ModemManager[1129]: <info>  [1467261807.420790] [mm-iface-modem.c:1392]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connecting ->
connected)
ModemManager[1129]: <info>  [1467261807.422354]
[mm-iface-modem-simple.c:602] connection_step(): Simple connect state
(8/8): All done
ModemManager[1129]: <debug> [1467261812.857683] [mm-broadband-modem.c:1991]
modem_load_signal_quality(): loading signal quality...
ModemManager[1129]: <debug> [1467261812.857941] [mm-iface-modem.c:1221]
signal_quality_check_ready(): Couldn't refresh signal quality: 'No AT port
available to run command'
ModemManager[1129]: <debug> [1467261827.905242] [mm-base-bearer.c:760]
mm_base_bearer_disconnect(): Disconnecting bearer
'/org/freedesktop/ModemManager1/Bearer/1'
ModemManager[1129]: <info>  [1467261827.905501] [mm-iface-modem.c:1392]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (connected ->
disconnecting)
ModemManager[1129]: <debug> [1467261827.907181]
[mm-broadband-bearer.c:1554] data_reopen_3gpp(): Reopening data port
(ttyS0)...
ModemManager[1129]: <debug> [1467261827.907343] [mm-port-serial.c:1555]
mm_port_serial_reopen(): (ttyS0) reopening port (2)
ModemManager[1129]: <debug> [1467261827.907415] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 1 (close)
ModemManager[1129]: <debug> [1467261827.907480] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 0 (close)
ModemManager[1129]: <debug> [1467261827.907555] [mm-port-serial.c:1312]
mm_port_serial_close(): (ttyS0) closing serial port...
ModemManager[1129]: <debug> [1467261827.907636] [mm-port.c:95]
mm_port_set_connected(): (ttyS0): port now disconnected
ModemManager[1129]: <debug> [1467261827.907807] [mm-port-serial.c:1361]
mm_port_serial_close(): (ttyS0) serial port closed
ModemManager[1129]: <debug> [1467261828.909096] [mm-port-serial.c:1099]
mm_port_serial_open(): (ttyS0) opening serial port...
ModemManager[1129]: <debug> [1467261828.909516] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 1 (open)
ModemManager[1129]: <debug> [1467261828.909585] [mm-port-serial-at.c:476]
mm_port_serial_at_run_init_sequence(): (ttyS0): running init sequence...
ModemManager[1129]: <debug> [1467261828.909698] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 2 (open)
ModemManager[1129]: <debug> [1467261828.909789]
[mm-broadband-bearer.c:1542] data_reopen_3gpp_ready(): Flashing data port
(ttyS0)...
ModemManager[1129]: <debug> [1467261828.909892] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'ATE0<CR>'
ModemManager[1129]: <debug> [1467261829.911627] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 1 (close)
ModemManager[1129]: <debug> [1467261829.911742]
[mm-broadband-bearer.c:1515] data_flash_3gpp_ready(): Sending PDP context
deactivation in data port...
ModemManager[1129]: <debug> [1467261829.911871] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 2 (open)
ModemManager[1129]: <debug> [1467261831.854097] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'ATV1<CR>'
ModemManager[1129]: <debug> [1467261831.860830] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.861017] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.861153] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'O'
ModemManager[1129]: <debug> [1467261831.861335] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K'
ModemManager[1129]: <debug> [1467261831.861503] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.861673] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.861907] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CMEE=1<CR>'
ModemManager[1129]: <debug> [1467261831.874091] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.874281] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.874409] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'O'
ModemManager[1129]: <debug> [1467261831.874593] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K'
ModemManager[1129]: <debug> [1467261831.874771] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.874949] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.875129] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'ATX4<CR>'
ModemManager[1129]: <debug> [1467261831.881604] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.881865] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.882027] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'O'
ModemManager[1129]: <debug> [1467261831.882141] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K'
ModemManager[1129]: <debug> [1467261831.882266] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.882474] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.882649] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT&C1<CR>'
ModemManager[1129]: <debug> [1467261831.890322] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.890514] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.890734] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'O'
ModemManager[1129]: <debug> [1467261831.890878] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K'
ModemManager[1129]: <debug> [1467261831.891000] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.891173] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.891344] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CGACT=0,1<CR>'
ModemManager[1129]: <debug> [1467261831.906955] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.907146] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.907364] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'O'
ModemManager[1129]: <debug> [1467261831.907538] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K'
ModemManager[1129]: <debug> [1467261831.907661] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261831.907781] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261831.907931] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 1 (close)
ModemManager[1129]: <debug> [1467261831.908044] [mm-base-bearer.c:693]
disconnect_ready(): Disconnected bearer
'/org/freedesktop/ModemManager1/Bearer/1'
ModemManager[1129]: <info>  [1467261831.908158] [mm-iface-modem.c:1392]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting ->
registered)
ModemManager[1129]: <debug> [1467261833.020094] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261833.020473] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>+'
ModemManager[1129]: <debug> [1467261833.020713] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'CI'
ModemManager[1129]: <debug> [1467261833.020946] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'E'
ModemManager[1129]: <debug> [1467261833.021170] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'V'
ModemManager[1129]: <debug> [1467261833.021394] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ': '
ModemManager[1129]: <debug> [1467261833.021611] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '2'
ModemManager[1129]: <debug> [1467261833.021976] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ',3'
ModemManager[1129]: <debug> [1467261833.022206] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261833.022445] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>'
ModemManager[1129]: <debug> [1467261833.022861] [mm-iface-modem.c:1165]
update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0:
signal quality updated (60)
ModemManager[1129]: <debug> [1467261835.586681] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261835.587045] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>+'
ModemManager[1129]: <debug> [1467261835.587293] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'CI'
ModemManager[1129]: <debug> [1467261835.587527] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'E'
ModemManager[1129]: <debug> [1467261835.587750] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'V'
ModemManager[1129]: <debug> [1467261835.587972] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ':'
ModemManager[1129]: <debug> [1467261835.588186] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ' 2'
ModemManager[1129]: <debug> [1467261835.588397] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ','
ModemManager[1129]: <debug> [1467261835.588613] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '2'
ModemManager[1129]: <debug> [1467261835.588829] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR><LF>'
ModemManager[1129]: <debug> [1467261835.589271] [mm-iface-modem.c:1165]
update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0:
signal quality updated (40)
ModemManager[1129]: <debug> [1467261842.859776] [mm-broadband-modem.c:1991]
modem_load_signal_quality(): loading signal quality...
ModemManager[1129]: <debug> [1467261842.860019] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 2 (open)
ModemManager[1129]: <debug> [1467261842.860279] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CIND?<CR>'
ModemManager[1129]: <debug> [1467261842.871857] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261842.872182] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>+'
ModemManager[1129]: <debug> [1467261842.872439] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'C'
ModemManager[1129]: <debug> [1467261842.872684] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'IN'
ModemManager[1129]: <debug> [1467261842.872920] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'D'
ModemManager[1129]: <debug> [1467261842.873138] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ': '
ModemManager[1129]: <debug> [1467261842.873361] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '5'
ModemManager[1129]: <debug> [1467261842.873587] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ','
ModemManager[1129]: <debug> [1467261842.873807] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '2'
ModemManager[1129]: <debug> [1467261842.874027] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ','
ModemManager[1129]: <debug> [1467261842.874251] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '1,'
ModemManager[1129]: <debug> [1467261842.874485] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '0'
ModemManager[1129]: <debug> [1467261842.874731] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ',0'
ModemManager[1129]: <debug> [1467261842.874985] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- ','
ModemManager[1129]: <debug> [1467261842.876380] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '0,0,0,2,'
ModemManager[1129]: <debug> [1467261842.878232] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '0,0,0<CR><LF><CR><LF>O'
ModemManager[1129]: <debug> [1467261842.879940] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K<CR><LF>'
ModemManager[1129]: <debug> [1467261842.881768] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 1 (close)
ModemManager[1129]: <debug> [1467261842.883530] [mm-iface-modem.c:1165]
update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0:
signal quality updated (40)
^CModemManager[1129]: <info>  [1467261846.942400] [main.c:46] quit_cb():
Caught signal, shutting down...
ModemManager[1129]: <debug> [1467261846.942609] [mm-base-manager.c:810]
set_property(): Stopping connection in object manager server
ModemManager[1129]: <info>  [1467261846.943213] [mm-iface-modem.c:1392]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (registered ->
disabling)
ModemManager[1129]: <debug> [1467261846.943812] [mm-iface-modem.c:1165]
update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0:
signal quality updated (0)
ModemManager[1129]: <debug> [1467261846.943946] [mm-iface-modem.c:1282]
periodic_signal_quality_check_disable(): Periodic signal quality checks
disabled
ModemManager[1129]: <debug> [1467261846.944114] [mm-iface-modem.c:894]
mm_iface_modem_update_access_technologies(): Modem
/org/freedesktop/ModemManager1/Modem/0: access technology changed (umts ->
unknown)
ModemManager[1129]: <debug> [1467261846.944205] [mm-iface-modem.c:1008]
periodic_access_technologies_check_disable(): Periodic access technology
checks disabled
ModemManager[1129]: <debug> [1467261846.944606] [mm-broadband-modem.c:8282]
disabling_step(): Modem has messaging capabilities, disabling the Messaging
interface...
ModemManager[1129]: <debug> [1467261846.944860] [mm-broadband-modem.c:5791]
set_messaging_unsolicited_events_handlers(): (ttyS0) Removing messaging
unsolicited events handlers
ModemManager[1129]: <debug> [1467261846.945514] [mm-broadband-modem.c:8294]
disabling_step(): Modem has location capabilities, disabling the Location
interface...
ModemManager[1129]: <debug> [1467261846.945690]
[mm-iface-modem-location.c:765] setup_gathering(): Need to disable the
following location sources: '3gpp-lac-ci'
ModemManager[1129]: <debug> [1467261846.945859]
[mm-iface-modem-location.c:664] setup_gathering_step(): Disabled location
'3gpp-lac-ci' gathering...
ModemManager[1129]: <debug> [1467261846.946322] [mm-broadband-modem.c:8322]
disabling_step(): Modem has 3GPP/USSD capabilities, disabling the Modem
3GPP/USSD interface...
ModemManager[1129]: <debug> [1467261846.946500] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 2 (open)
ModemManager[1129]: <debug> [1467261846.947096] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CUSD=0<CR>'
ModemManager[1129]: <debug> [1467261846.961029] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR><LF>'
ModemManager[1129]: <debug> [1467261846.961486] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'OK'
ModemManager[1129]: <debug> [1467261846.961893] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR><LF>'
ModemManager[1129]: <debug> [1467261846.962258] [mm-broadband-modem.c:4908]
set_unsolicited_result_code_handlers(): (ttyS0) Removing unsolicited result
code handlers
ModemManager[1129]: <debug> [1467261846.962405] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 1 (close)
ModemManager[1129]: <debug> [1467261846.963007] [mm-broadband-modem.c:8334]
disabling_step(): Modem has 3GPP capabilities, disabling the Modem 3GPP
interface...
ModemManager[1129]: <debug> [1467261846.963145]
[mm-iface-modem-3gpp.c:1310] periodic_registration_check_disable():
Periodic 3GPP registration checks disabled
ModemManager[1129]: <debug> [1467261846.963287] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 2 (open)
ModemManager[1129]: <debug> [1467261846.963644] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CREG=0<CR>'
ModemManager[1129]: <debug> [1467261846.975823] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261846.976283] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>O'
ModemManager[1129]: <debug> [1467261846.976693] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K<CR><LF>'
ModemManager[1129]: <debug> [1467261846.977028] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 3 (open)
ModemManager[1129]: <debug> [1467261846.977216] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 2 (close)
ModemManager[1129]: <debug> [1467261846.977539] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CGREG=0<CR>'
ModemManager[1129]: <debug> [1467261846.990197] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261846.990654] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>O'
ModemManager[1129]: <debug> [1467261846.991050] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- 'K<CR><LF>'
ModemManager[1129]: <debug> [1467261846.991340] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 1 (close)
ModemManager[1129]: <debug> [1467261846.992720] [mm-broadband-modem.c:3648]
modem_3gpp_cleanup_unsolicited_registration_events(): (ttyS0) cleaning up
unsolicited registration messages handlers
ModemManager[1129]: <debug> [1467261846.993251] [mm-broadband-modem.c:2498]
set_unsolicited_events_handlers(): (ttyS0) Removing 3GPP unsolicited events
handlers
ModemManager[1129]: <debug> [1467261846.993636] [mm-port-serial.c:1237]
mm_port_serial_open(): (ttyS0) device open count is 2 (open)
ModemManager[1129]: <debug> [1467261846.993997] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): --> 'AT+CMER=0<CR>'
ModemManager[1129]: <debug> [1467261847.005949] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<CR>'
ModemManager[1129]: <debug> [1467261847.008966] [mm-port-serial-at.c:440]
debug_log(): (ttyS0): <-- '<LF>OK<CR><LF>'
ModemManager[1129]: <info>  [1467261847.009373]
[mm-iface-modem-3gpp.c:1169] update_registration_state(): Modem
/org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed
(home -> unknown)
ModemManager[1129]: <debug> [1467261847.009914] [mm-base-bearer.c:260]
modem_3gpp_registration_state_changed(): Bearer not allowed to connect, not
registered in 3GPP network
ModemManager[1129]: <debug> [1467261847.010120] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 1 (close)
ModemManager[1129]: <debug> [1467261847.010654] [mm-port-serial.c:1296]
mm_port_serial_close(): (ttyS0) device open count is 0 (close)
ModemManager[1129]: <debug> [1467261847.010763] [mm-port-serial.c:1312]
mm_port_serial_close(): (ttyS0) closing serial port...
ModemManager[1129]: <debug> [1467261847.011014] [mm-port-serial.c:1361]
mm_port_serial_close(): (ttyS0) serial port closed
ModemManager[1129]: <info>  [1467261847.011137] [mm-iface-modem.c:1392]
__iface_modem_update_state_internal(): Modem
/org/freedesktop/ModemManager1/Modem/0: state changed (disabling ->
disabled)
ModemManager[1129]: <debug> [1467261847.012097] [mm-base-bearer.c:895]
base_bearer_dbus_unexport(): Removing from DBus bearer at
'/org/freedesktop/ModemManager1/Bearer/1'
ModemManager[1129]: <debug> [1467261847.012298] [mm-device.c:382]
unexport_modem(): Unexported modem
'/sys/devices/platform/soc/3f215040.uart' from path
'/org/freedesktop/ModemManager1/Modem/0'
ModemManager[1129]: <debug> [1467261847.013605] [mm-port-serial.c:1415]
port_serial_close_force(): (ttyS0) forced to close port
ModemManager[1129]: <debug> [1467261847.014004] [mm-base-modem.c:1485]
finalize(): Modem (Generic) '/sys/devices/platform/soc/3f215040.uart'
completely disposed
ModemManager[1129]: <info>  [1467261847.026714] [main.c:191] main():
ModemManager is shut down

And network-manager shows the following:
Jul 01 09:56:56 raspberrypi NetworkManager[2691]: <info> ModemManager
available in the bus
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <warn> (ttyS0): failed to
look up interface index
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <info> (ttyS0): modem
state changed, 'disabled' --> 'enabling' (reason: user preference)
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <info> (ttyS0): new
Broadband device (driver: 'of_serial' ifindex: 0)
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <info> (ttyS0): exported
as /org/freedesktop/NetworkManager/Devices/3
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <info> (ttyS0): device
state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <info> (ttyS0): preparing
device
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <info> (ttyS0): modem
state 'enabling'
Jul 01 09:57:00 raspberrypi NetworkManager[2691]: <info> (ttyS0): device
state change: unavailable -> disconnected (reason 'none') [20 30 0]
Jul 01 09:57:07 raspberrypi NetworkManager[2691]: <info> (ttyS0): modem
state changed, 'enabling' --> 'registered' (reason: user-requested)
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
starting connection 'Vodafone'
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 1 of 5 (Device Prepare) scheduled...
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 1 of 5 (Device Prepare) started...
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> (ttyS0): device
state change: disconnected -> prepare (reason 'none') [30 40 0]
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 1 of 5 (Device Prepare) complete.
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> (ttyS0): modem
state changed, 'registered' --> 'connecting' (reason: user-requested)
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> (ttyS0): modem
state changed, 'connecting' --> 'connected' (reason: user-requested)
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <warn> (ttyS0): failed to
look up interface index
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 2 of 5 (Device Configure) scheduled...
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 2 of 5 (Device Configure) starting...
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> (ttyS0): device
state change: prepare -> config (reason 'none') [40 50 0]
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 2 of 5 (Device Configure) successful.
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 3 of 5 (IP Configure Start) scheduled.
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 2 of 5 (Device Configure) complete.
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 3 of 5 (IP Configure Start) started...
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> (ttyS0): device
state change: config -> ip-config (reason 'none') [50 70 0]
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <warn> (ttyS0): interface
ttyS0 not up for IP configuration
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> using
modem-specified IP timeout: 20 seconds
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> starting PPP
connection
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> pppd started with
pid 2764
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 3 of 5 (IP Configure Start) complete.
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 4 of 5 (IPv6 Configure Timeout) started...
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 4 of 5 (IPv6 Configure Timeout) complete.
Jul 01 09:59:35 raspberrypi pppd[2764]: Plugin
/usr/lib/pppd/2.4.6/nm-pppd-plugin.so loaded.
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: Plugin
/usr/lib/pppd/2.4.6/nm-pppd-plugin.so loaded.
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: nm-pppd-plugin-Message:
nm-ppp-plugin: (plugin_init): initializing
Jul 01 09:59:35 raspberrypi pppd[2764]: pppd 2.4.6 started by root, uid 0
Jul 01 09:59:35 raspberrypi NetworkManager[2691]: nm-pppd-plugin-Message:
nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <warn> pppd timed out or
didn't initialize our dbus module
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 4 of 5 (IPv4 Configure Timeout) started...
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <info> (ttyS0): device
state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120
5]
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <warn> Activation (ttyS0)
failed for connection 'Vodafone'
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <info> Activation (ttyS0)
Stage 4 of 5 (IPv4 Configure Timeout) complete.
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <info> (ttyS0): device
state change: failed -> disconnected (reason 'none') [120 30 0]
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <info> (ttyS0):
deactivating device (reason 'none') [0]
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: nm-pppd-plugin-Message:
nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Jul 01 09:59:55 raspberrypi NetworkManager[2691]: <info> (ttyS0): modem
state changed, 'connected' --> 'disconnecting' (reason: user-requested)
Jul 01 09:59:56 raspberrypi NetworkManager[2691]: nm-pppd-plugin-Message:
nm-ppp-plugin: (nm_exit_notify): cleaning up
Jul 01 09:59:59 raspberrypi NetworkManager[2691]: <info> (ttyS0): modem
state changed, 'disconnecting' --> 'registered' (reason: user-requested)

Any insight you provide would be greatly appreciated. Thanks for all your
hard
work on this project.

Kind regards,
Andrew Mackintosh
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20160701/a61bcdad/attachment-0001.html>