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.
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?
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.
@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.
@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?
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)
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.
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?
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.
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…
@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.
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?
@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.
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
