Cellular Modem connectivity issues on boot


#1

I’ve got a ResinOS 2.0 device using a cellular modem for connectivity on a Raspberry Pi 3. However, the cellular modem is only usable by NetworkManager after being unplugged and plugged back in once docker and the container is started.

One thing I noticed is that the modem is present according to nmcli early during startup. Once docker and the container starts up, though, it disappears from nm.

Early during startup:

# nmcli c
NAME                UUID                                  TYPE             DEVICE  
Wired connection 1  5313b130-8940-3deb-97f8-5afeba8fbf40  802-3-ethernet   eth0    
resin-verizon       9290a7a8-70f7-44b0-94e4-83f0b2635f07  cdma             ttyUSB3 
resin-sample        bcb05b81-52cb-3828-8088-c0f55e950375  802-11-wireless  --   
# nmcli d
DEVICE   TYPE      STATE         CONNECTION         
ttyUSB3  cdma      connected     resin-verizon      
eth0     ethernet  connected     Wired connection 1 
wlan0    wifi      disconnected  --                 
lo       loopback  unmanaged     -- 
# mmcli -L
Found 1 modems:
	/org/freedesktop/ModemManager1/Modem/0 [Telit] DE910-DUAL

Later on after startup of docker/container:

# nmcli c
NAME                UUID                                  TYPE             DEVICE 
Wired connection 1  5313b130-8940-3deb-97f8-5afeba8fbf40  802-3-ethernet   eth0   
resin-sample        bcb05b81-52cb-3828-8088-c0f55e950375  802-11-wireless  --     
resin-verizon       9290a7a8-70f7-44b0-94e4-83f0b2635f07  cdma             --     
# nmcli d
DEVICE     TYPE      STATE         CONNECTION         
eth0       ethernet  connected     Wired connection 1 
wlan0      wifi      disconnected  --                 
docker0    bridge    unmanaged     --                 
lo         loopback  unmanaged     --                 
resin-vpn  tun       unmanaged     --                 
# mmcli -L
No modems were found

Not until unplugging and plugging the modem back in do I get connectivity back.

My NetworkManager connection profile also:

[connection]
id=resin-verizon
uuid=9290a7a8-70f7-44b0-94e4-83f0b2635f07
type=cdma
autoconnect=true
secondaries=
[cdma]
number=#777
password-flags=1
[ipv4]
dns-search=
method=auto
[ipv6]
addr-gen-mode=stable-privacy
dns-search=
method=auto

#2

Hi, we are looking into this!
For some context, does your application try to manage the network connections? Does this modem disappearance also happen when running just a minimal project like simple-server-python?


#3

hey @liammonahan , I have seen similar types of behaviour when the modem is under powered and it just dissapears. How are you powering the modem, is it attached over usb to the RPI3? Many forums suggest having an externally powered USB hub (which is annoying), but for most of my projects I normally set the options to allow maximuim current to the usb, these can be set in /boot/config.txt

max_usb_current=1
safe_mode_gpio=4

By default the RPI3 limits the usb current output to 600ma, but these settings allow the usb to supply I think up to 1.2A of current, which is usually good for a modem.


#4

No managing of network connections going on here. Yes, also happens for minimal projects like simple-server-python.


#5

@shaunmulligan The modem is being powered through a fairly high quality USB hub with external power right now as this is happening. The modem requires about 650ma of current–just north of the default output of the RPI3. :slight_smile:


#6

If I use the same hardware setup and install Raspian+NetworkManager, the link comes up on boot.


#7

@liammonahan that is really strange. Can you provision a -dev version of resinOS (basically download v2.0.0-rc1.rev2-dev ) and bring it up on ethernet/wifi with the GSM modem plugged in. You can then ssh into the hostOS using ssh root@<DEVICE_IP> -p22222 and then check the both the networkManager and modemManager logs using journalctl -u NetworkManager -n100 and the same for ModemManager .

Hopefully those logs will have something interesting to point at. Additionally can you tell me what version of NetworkManager is installed on raspbian and what is the name of the modem you are using?


#8

The version of NM available w/ Raspian is 0.9.10.0, so a little older it looks like than what ships w/ ResinOS. Hardware-wise, I’m using a Multitech MTD-EV3. http://www.multitech.com/documents/publications/data-sheets/86002162.pdf It identifies as a Telit modem under the covers.

Here are interleaved logs from both units. I can also follow up with ModemManager debug-level logs. The onboard time is wrong on startup, hence the logs saying they’re from March 6th…

# journalctl --no-pager --unit=ModemManager --unit=NetworkManager -n200
-- Logs begin at Mon 2017-03-06 12:06:25 UTC, end at Mon 2017-03-06 12:08:27 UTC. --
Mar 06 12:06:29 raspberrypi3 systemd[1]: Starting Modem Manager...
Mar 06 12:06:29 raspberrypi3 systemd[1]: Starting Network Manager...
Mar 06 12:06:30 raspberrypi3 ModemManager[637]: <info>  ModemManager (version 1.6.4) starting in system bus...
Mar 06 12:06:30 e5882e6 NetworkManager[723]: <info>  [1488801990.5777] NetworkManager (version 1.4.2) is starting...
Mar 06 12:06:30 e5882e6 NetworkManager[723]: <info>  [1488801990.5783] Read config: /etc/NetworkManager/NetworkManager.conf
Mar 06 12:06:30 e5882e6 NetworkManager[723]: <info>  [1488801990.6102] manager[0x19c9880]: monitoring kernel firmware directory '/lib/firmware'.
Mar 06 12:06:30 e5882e6 NetworkManager[723]: <info>  [1488801990.6647] dns-mgr[0x19d4818]: init: dns=default, rc-manager=resolvconf
Mar 06 12:06:30 e5882e6 NetworkManager[723]: <info>  [1488801990.6692] rfkill0: found WiFi radio killswitch (at /sys/devices/platform/soc/3f300000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1/ieee80211/phy0/rfkill0) (driver brcmfmac_sdio)
Mar 06 12:06:30 e5882e6 NetworkManager[723]: <info>  [1488801990.6702] manager[0x19c9880]: WiFi hardware radio set enabled
Mar 06 12:06:30 e5882e6 NetworkManager[723]: <info>  [1488801990.6705] manager[0x19c9880]: WWAN hardware radio set enabled
Mar 06 12:06:30 e5882e6 systemd[1]: Started Network Manager.
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.1467] settings: loaded plugin keyfile: (c) 2007 - 2015 Red Hat, Inc.  To report bugs please use the NetworkManager mailing list.
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.2602] keyfile: new connection /etc/NetworkManager/system-connections/resin-sample (bcb05b81-52cb-3828-8088-c0f55e950375,"resin-sample")
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.3534] keyfile: new connection /etc/NetworkManager/system-connections/resin-verizon (9290a7a8-70f7-44b0-94e4-83f0b2635f07,"resin-verizon")
Mar 06 12:06:31 e5882e6 systemd[1]: Started Modem Manager.
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8042] settings: hostname: using hostnamed
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8043] settings: hostname changed from (none) to "e5882e6"
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8055] dhcp-init: Using DHCP client 'dhclient'
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8056] manager: WiFi enabled by radio killswitch; enabled by state file
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8059] manager: WWAN enabled by radio killswitch; enabled by state file
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8064] manager: Networking is enabled by state file
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8068] Loaded device plugin: NMVxlanFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8069] Loaded device plugin: NMVlanFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8071] Loaded device plugin: NMVethFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8072] Loaded device plugin: NMTunFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8074] Loaded device plugin: NMMacvlanFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8075] Loaded device plugin: NMIPTunnelFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8077] Loaded device plugin: NMInfinibandFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8079] Loaded device plugin: NMEthernetFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8083] Loaded device plugin: NMBridgeFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8085] Loaded device plugin: NMBondFactory (internal)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.8525] Loaded device plugin: NMWwanFactory (/usr/lib/NetworkManager/libnm-device-plugin-wwan.so)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.9084] Loaded device plugin: NMBluezManager (/usr/lib/NetworkManager/libnm-device-plugin-bluetooth.so)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.9428] Loaded device plugin: NMWifiFactory (/usr/lib/NetworkManager/libnm-device-plugin-wifi.so)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.9704] device (lo): link connected
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.9763] manager: (lo): new Generic device (/org/freedesktop/NetworkManager/Devices/0)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.9883] manager: (eth0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/1)
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.9955] keyfile: add connection in-memory (cc17d9e1-cce2-34ec-b860-f0c313cd0a97,"Wired connection 1")
Mar 06 12:06:31 e5882e6 NetworkManager[723]: <info>  [1488801991.9992] settings: (eth0): created default wired connection 'Wired connection 1'
Mar 06 12:06:32 e5882e6 NetworkManager[723]: <info>  [1488801992.0088] device (eth0): state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Mar 06 12:06:32 e5882e6 NetworkManager[723]: <info>  [1488801992.1195] (wlan0): using nl80211 for WiFi device control
Mar 06 12:06:32 e5882e6 NetworkManager[723]: <info>  [1488801992.1211] device (wlan0): driver supports Access Point (AP) mode
Mar 06 12:06:32 e5882e6 NetworkManager[723]: <info>  [1488801992.1290] manager: (wlan0): new 802.11 WiFi device (/org/freedesktop/NetworkManager/Devices/2)
Mar 06 12:06:32 e5882e6 NetworkManager[723]: <info>  [1488801992.1392] device (wlan0): state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Mar 06 12:06:32 e5882e6 NetworkManager[723]: <info>  [1488801992.7692] device (wlan0): set-hw-addr: set MAC address to 92:9C:1E:F0:69:A4 (scanning)
Mar 06 12:06:32 e5882e6 NetworkManager[723]: <info>  [1488801992.8631] ModemManager available in the bus
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.0872] supplicant: wpa_supplicant running
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.0875] device (wlan0): supplicant interface state: init -> starting
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.1817] sup-iface[0x19d30d8,wlan0]: supports 5 scan SSIDs
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.1873] device (wlan0): supplicant interface state: starting -> ready
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.1877] device (wlan0): state change: unavailable -> disconnected (reason 'supplicant-available') [20 30 42]
Mar 06 12:06:33 e5882e6 ModemManager[637]: <warn>  (ttyUSB3): port attributes not fully set
Mar 06 12:06:33 e5882e6 ModemManager[637]: <warn>  (ttyUSB2): port attributes not fully set
Mar 06 12:06:33 e5882e6 ModemManager[637]: <warn>  (ttyUSB1): port attributes not fully set
Mar 06 12:06:33 e5882e6 ModemManager[637]: <warn>  (ttyUSB0): port attributes not fully set
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6314] device (eth0): link connected
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6500] device (eth0): state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6539] policy: auto-activating connection 'Wired connection 1'
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6617] device (eth0): Activation: starting connection 'Wired connection 1' (cc17d9e1-cce2-34ec-b860-f0c313cd0a97)
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6629] device (eth0): state change: disconnected -> prepare (reason 'none') [30 40 0]
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6637] manager: NetworkManager state is now CONNECTING
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6666] device (eth0): state change: prepare -> config (reason 'none') [40 50 0]
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6708] device (eth0): state change: config -> ip-config (reason 'none') [50 70 0]
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.6761] dhcp4 (eth0): activation: beginning transaction (timeout in 45 seconds)
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.7187] dhcp4 (eth0): dhclient started with pid 833
Mar 06 12:06:33 e5882e6 NetworkManager[723]: <info>  [1488801993.7321] device (wlan0): supplicant interface state: ready -> inactive
Mar 06 12:06:34 e5882e6 dhclient[833]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 7
Mar 06 12:06:34 e5882e6 ModemManager[637]: <info>  Couldn't check support for device at '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1': not supported by any plugin
Mar 06 12:06:35 e5882e6 dhclient[833]: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Mar 06 12:06:35 e5882e6 dhclient[833]: DHCPOFFER from XXX.XX.1.1
Mar 06 12:06:35 e5882e6 dhclient[833]: DHCPACK from XXX.XX.1.1
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1917] dhcp4 (eth0):   address XXX.XXX.XXX.XXX
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1918] dhcp4 (eth0):   plen 23 (255.255.254.0)
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1920] dhcp4 (eth0):   gateway XXX.XXX.XXX.XXX
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1921] dhcp4 (eth0):   server identifier XXX.XXX.XXX.XXX
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1922] dhcp4 (eth0):   lease time 86400
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1924] dhcp4 (eth0):   nameserver 'XXX.XXX.XXX.XXX'
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1925] dhcp4 (eth0):   nameserver '8.8.8.8'
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1926] dhcp4 (eth0): state changed unknown -> bound
Mar 06 12:06:35 e5882e6 dhclient[833]: bound to XXX.XXX.XXX.XXX -- renewal in 35201 seconds.
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.1988] device (eth0): state change: ip-config -> ip-check (reason 'none') [70 80 0]
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.2033] device (eth0): state change: ip-check -> secondaries (reason 'none') [80 90 0]
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.2055] device (eth0): state change: secondaries -> activated (reason 'none') [90 100 0]
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.2064] manager: NetworkManager state is now CONNECTED_LOCAL
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.2107] manager: NetworkManager state is now CONNECTED_GLOBAL
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.2113] policy: set 'Wired connection 1' (eth0) as default for IPv4 routing and DNS
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.2120] dns-mgr: Writing DNS information to /sbin/resolvconf
Mar 06 12:06:35 e5882e6 NetworkManager[723]: <info>  [1488801995.3174] device (eth0): Activation: successful, device activated.
Mar 06 12:06:39 e5882e6 NetworkManager[723]: <info>  [1488801999.2565] manager: startup complete
Mar 06 12:06:43 e5882e6 ModemManager[637]: <info>  Creating modem with plugin 'Telit' and '4' ports
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  (ttyUSB3): port attributes not fully set
Mar 06 12:06:43 e5882e6 ModemManager[637]: <info>  Modem for device at '/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.1/1-1.2.1.4' successfully created
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  couldn't load Supported Bands: 'Unknown error'
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  No respose for step 1: Unknown error
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  No respose for step 2: Unknown error
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  No respose for step 3: Unknown error
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  No respose for step 4: Unknown error
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  Couldn't load unlock retries: 'Could not get any of the SIM unlock retries values'
Mar 06 12:06:43 e5882e6 ModemManager[637]: <warn>  couldn't load current Bands: 'Unknown error'
Mar 06 12:06:43 e5882e6 ModemManager[637]: <info>  Modem: state changed (unknown -> disabled)
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9276] (ttyUSB3): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9371] manager: (ttyUSB3): new Broadband device (/org/freedesktop/NetworkManager/Devices/3)
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9401] device (ttyUSB3): state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9418] device (ttyUSB3): modem state 'enabling'
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9427] modem-broadband[ttyUSB3]: failed to retrieve SIM object: No SIM object available
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9450] device (ttyUSB3): state change: unavailable -> disconnected (reason 'none') [20 30 0]
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9488] policy: auto-activating connection 'resin-verizon'
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9562] device (ttyUSB3): Activation: starting connection 'resin-verizon' (9290a7a8-70f7-44b0-94e4-83f0b2635f07)
Mar 06 12:06:43 e5882e6 NetworkManager[723]: <info>  [1488802003.9573] device (ttyUSB3): state change: disconnected -> prepare (reason 'none') [30 40 0]
Mar 06 12:06:44 e5882e6 ModemManager[637]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Mar 06 12:06:44 e5882e6 ModemManager[637]: <warn>  (ttyUSB3): port attributes not fully set
Mar 06 12:06:44 e5882e6 ModemManager[637]: <warn>  (ttyUSB2): port attributes not fully set
Mar 06 12:06:44 e5882e6 ModemManager[637]: <info>  Simple connect started...
Mar 06 12:06:44 e5882e6 ModemManager[637]: <info>  Simple connect state (4/8): Wait to get fully enabled
Mar 06 12:06:44 e5882e6 ModemManager[637]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> enabled)
Mar 06 12:06:44 e5882e6 ModemManager[637]: <info>  Simple connect state (5/8): Register
Mar 06 12:06:44 e5882e6 NetworkManager[723]: <info>  [1488802004.9624] (ttyUSB3): modem state changed, 'enabling' --> 'enabled' (reason: user-requested)
Mar 06 12:06:45 e5882e6 ModemManager[637]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabled -> registered)
Mar 06 12:06:45 e5882e6 ModemManager[637]: <info>  Simple connect state (6/8): Bearer
Mar 06 12:06:45 e5882e6 NetworkManager[723]: <info>  [1488802005.0492] (ttyUSB3): modem state changed, 'enabled' --> 'registered' (reason: unknown)
Mar 06 12:06:45 e5882e6 ModemManager[637]: <info>  Simple connect state (7/8): Connect
Mar 06 12:06:45 e5882e6 ModemManager[637]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Mar 06 12:06:45 e5882e6 NetworkManager[723]: <info>  [1488802005.0565] (ttyUSB3): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Mar 06 12:06:46 e5882e6 ModemManager[637]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Mar 06 12:06:46 e5882e6 ModemManager[637]: <info>  Simple connect state (8/8): All done
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.2661] (ttyUSB3): modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <warn>  [1488802006.2745] device (ttyUSB3): failed to look up interface index
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.2754] device (ttyUSB3): state change: prepare -> config (reason 'none') [40 50 0]
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.2772] device (ttyUSB3): state change: config -> ip-config (reason 'none') [50 70 0]
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <warn>  [1488802006.2780] device (ttyUSB3): interface ttyUSB3 not up for IP configuration
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.2782] (ttyUSB3): using modem-specified IP timeout: 20 seconds
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.2807] ppp-manager: starting PPP connection
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.3102] ppp-manager: pppd started with pid 856
Mar 06 12:06:46 e5882e6 pppd[856]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Mar 06 12:06:46 e5882e6 NetworkManager[723]: Plugin /usr/lib/pppd/2.4.5/nm-pppd-plugin.so loaded.
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (plugin_init): initializing
Mar 06 12:06:46 e5882e6 pppd[856]: pppd 2.4.7 started by root, uid 0
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Mar 06 12:06:46 e5882e6 pppd[856]: Using interface ppp0
Mar 06 12:06:46 e5882e6 NetworkManager[723]: Using interface ppp0
Mar 06 12:06:46 e5882e6 NetworkManager[723]: Connect: ppp0 <--> /dev/ttyUSB3
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Mar 06 12:06:46 e5882e6 pppd[856]: Connect: ppp0 <--> /dev/ttyUSB3
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 6 / phase 'authenticate'
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.5846] manager: (ppp0): new Generic device (/org/freedesktop/NetworkManager/Devices/4)
Mar 06 12:06:46 e5882e6 pppd[856]: local  IP address 166.249.XXX.XXX
Mar 06 12:06:46 e5882e6 NetworkManager[723]: local  IP address 166.249.XXX.XXX
Mar 06 12:06:46 e5882e6 NetworkManager[723]: remote IP address 66.174.XXX.XXX
Mar 06 12:06:46 e5882e6 NetworkManager[723]: primary   DNS address 198.224.191.135
Mar 06 12:06:46 e5882e6 NetworkManager[723]: secondary DNS address 198.224.190.135
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 9 / phase 'running'
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): ip-up event
Mar 06 12:06:46 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_ip_up): sending IPv4 config to NetworkManager...
Mar 06 12:06:46 e5882e6 pppd[856]: remote IP address 66.174.XXX.XXX
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.6702] ppp-manager: (IPv4 Config Get) reply received.
Mar 06 12:06:46 e5882e6 pppd[856]: primary   DNS address 198.224.XXX.XXX
Mar 06 12:06:46 e5882e6 pppd[856]: secondary DNS address 198.224.XXX.XXX
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.6887] device (ttyUSB3): state change: ip-config -> ip-check (reason 'none') [70 80 0]
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.6936] device (ttyUSB3): state change: ip-check -> secondaries (reason 'none') [80 90 0]
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.6955] device (ttyUSB3): state change: secondaries -> activated (reason 'none') [90 100 0]
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.6986] dns-mgr: Writing DNS information to /sbin/resolvconf
Mar 06 12:06:46 e5882e6 NetworkManager[723]: <info>  [1488802006.7816] device (ttyUSB3): Activation: successful, device activated.
Mar 06 12:07:16 e5882e6 pppd[856]: IPV6CP: timeout sending Config-Requests
Mar 06 12:07:16 e5882e6 NetworkManager[723]: IPV6CP: timeout sending Config-Requests
Mar 06 12:08:07 e5882e6 NetworkManager[723]: <info>  [1488802087.7799] manager: (docker0): new Bridge device (/org/freedesktop/NetworkManager/Devices/5)
Mar 06 12:08:12 e5882e6 ModemManager[637]: <info>  (tty/ttyUSB1): released by modem /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.1/1-1.2.1.4
Mar 06 12:08:12 e5882e6 ModemManager[637]: <info>  (tty/ttyUSB2): released by modem /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.1/1-1.2.1.4
Mar 06 12:08:12 e5882e6 ModemManager[637]: <info>  (tty/ttyUSB3): released by modem /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.1/1-1.2.1.4
Mar 06 12:08:13 e5882e6 ModemManager[637]: <info>  (tty/ttyUSB0): released by modem /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.1/1-1.2.1.4
Mar 06 12:08:13 e5882e6 NetworkManager[723]: <info>  [1488802093.2978] device (ttyUSB3): state change: activated -> unmanaged (reason 'removed') [100 10 36]
Mar 06 12:08:13 e5882e6 pppd[856]: Terminating on signal 15
Mar 06 12:08:13 e5882e6 NetworkManager[723]: Terminating on signal 15
Mar 06 12:08:13 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 10 / phase 'terminate'
Mar 06 12:08:13 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Mar 06 12:08:13 e5882e6 NetworkManager[723]: Connect time 1.5 minutes.
Mar 06 12:08:13 e5882e6 NetworkManager[723]: Sent 126 bytes, received 0 bytes.
Mar 06 12:08:13 e5882e6 pppd[856]: Connect time 1.5 minutes.
Mar 06 12:08:13 e5882e6 pppd[856]: Sent 126 bytes, received 0 bytes.
Mar 06 12:08:13 e5882e6 NetworkManager[723]: <info>  [1488802093.3319] dns-mgr: Writing DNS information to /sbin/resolvconf
Mar 06 12:08:13 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Mar 06 12:08:13 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect'
Mar 06 12:08:13 e5882e6 NetworkManager[723]: Connection terminated.
Mar 06 12:08:13 e5882e6 pppd[856]: Connection terminated.
Mar 06 12:08:13 e5882e6 ModemManager[637]: <info>  (net/eth0): released by modem /sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.1
Mar 06 12:08:13 e5882e6 NetworkManager[723]: <warn>  [1488802093.4772] modem-broadband[ttyUSB3]: failed to disconnect modem: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface 'org.freedesktop.ModemManager1.Modem.Simple' on object at path /org/freedesktop/ModemManager1/Modem/0
Mar 06 12:08:14 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Mar 06 12:08:14 e5882e6 NetworkManager[723]: nm-pppd-plugin-Message: nm-ppp-plugin: (nm_exit_notify): cleaning up
Mar 06 12:08:14 e5882e6 pppd[856]: Exit.
Mar 06 12:08:14 e5882e6 NetworkManager[723]: <info>  [1488802094.6547] manager: (resin-vpn): new Tun device (/org/freedesktop/NetworkManager/Devices/6)

#9

The timing seems pretty consistent where the ppp connection terminates just after the docker0 bridge interface is coming up. I had seen gitter chat ( https://gitter.im/resin-io/chat/archives/2017/02/05 ) that was suggesting reliability issues between ppp <—> docker.

It’s still odd that the modem stays up indefinitely if plugged in after boot.


#10

ModemManager logs on debug level.

https://gist.githubusercontent.com/spicybits/afca83359e54c1edbc2973388e0821e7/raw/666561f1c1d84ee0bb367853678ed9b5e8c3a23e/nm-mm-debug.log


#11

I made a small config change in the meantime because it looked like the primary DNS server being assigned through ppp is unresponsive.

Started using something like this:

[ipv4]
method=auto
dns=8.8.8.8;
ignore-auto-dns=true

so that the bogus DNS nameservers returned by ppp-manager will not be used by NetworkManager. That, however, did not help. It definitely looks like openvpn cannot resolve vpn.resin.io.

Would there be much difference if I used a resinos.io image instead? Are they fulfilling similar roles now that -dev images are available through the dashboard?


#12

More datapoints: If I provision a brand new device (with ethernet and modem connected) and put it into local mode before it has a chance to download the application (it’s at the factory build) it will list the modem in nmcli indefinitely. As soon as I go and disable local mode and the application downloads and starts, the modem connection disappears from nmcli. There are no logs about what’s happening in journalctl.


#13

A note on resinos.io images: those are currently behind in versions, and the 2.0 images you get from the dashboard are newer. Once the final (non beta) release is out on resin.io, will update the open source resinos.io images as well. Currently, though, would not use that, lot has changed since then. The similar roles you mentioned are a thing, though, that’s one reason rdt is being rolled into resin-cli (and the resin local ... commands).

Thanks for the additional info, we are trying to narrow down what might be happening. It’s very strange, because there are a large number of cellular modems that work totally fine…


#14

By the way, would you consider use any other modem, or this one has any specific features that you need?


#15

@liammonahan if the connection stays up indefinitely with out ever running the container, then I suspect there is some kind of interaction with a service running in the container. Do you have INITSYSTEM=on set in all the projects you are testing? I am wondering if somehow the systemd in the container is causing some kind of killing of the modemmanager service. I’ll try do some testing with this today on the some of our latest base images, because I wonder if a recent change has introduced this behaviour.


#16

Hey Liam, I spent some time trying to reproduce this today, but haven’t been able to get the same behaviour with any of the modems I have here. It’s pretty strange, I am wondering if perhaps its something to do with the cdma modems as I am based in Europe, so have only ever tested GSM modems. Perhaps @mccollam has had some success with his CDMA based modems.

It’s also interesting to see these two lines:

Mar 06 12:08:13 e5882e6 pppd[856]: Terminating on signal 15
Mar 06 12:08:13 e5882e6 NetworkManager[723]: Terminating on signal 15

Which seem like something is sending SIGTERM to the pppd and NM. This I suspect is the systemd process in your container when it shutdown during a application stop while updating. So perhaps having INITSYSTEM=off will stop the issue from happening?


Modem Manager GPS issue
#17

@imrehg We’ve got some different modems we ordered that should get activated in the next couple of days to test out. We are not wedded to this modem, but it seems robust and has worked for us with NetworkManager in the past.


#18

I didn’t have any luck unfortunately using INITSYSTEM=off. The main difference this time is pppd exiting much more quickly (0.1 minutes instead of 1.5?) and the following log messages at the very end of the log. TERM signal is still being sent to MM/NM. Hmmm…

ModemManager[616]: (ttyUSB0): port attributes not fully set
ModemManager[616]: Couldn’t create modem for device at ‘/sys/devices/platform/soc/3f980000.usb/usb1/1-1/1-1.2/1-1.2.4’: Failed to find primary AT port

Log with INITSYSTEM=off: https://gist.githubusercontent.com/spicybits/4e58292d998cc3c6fc73f5126b18dc16/raw/ae285771d8d053bf314c8f1c12bf1d1ac924dc03/log


#19

The next thing I’m going to try is to see if I can confirm what’s sending a TERM signal through strace and auditd.


#20

Any luck w/ different CDMA modems @mccollam? Any issues/gotchas you ran into along the way? Thanks.