1

I have a u-Blox SARA-U270 device connected to a Raspberry Pi 3 via UART GPIO pins, that I am trying to use for a 3G connection as a backup. I would like to manage this via NetworkManager/ModemManager as it can automatically handle the failover between a wired and 3G connection.

The Pi is running Raspbian Jessie 2016-05-10.

I have added a udev rule to ensure that ModemManager does not ignore the built in serial port, and verified that the serial connection is up as I can issue AT commands while the ModemManager service is down.

NetworkManager shows that the connection is active and registers on the network, but spontaneously fails when trying to actually connect to the network. Again, I have verified this is possible by entering AT commands manually.

The NetworkManager logs are as follows:

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)

ModemManager seems to be failing when it dials the connection:

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

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.