On Tue, 2017-04-04 at 21:27 -0400, Liam Monahan wrote:
I definitely see the conspicuous gap you see with no dial out to #777 happening. The logs that are there are unpruned straight from journalctl. If I hotplug the modem back in, then I see additional info about the connection being made in the logs after “Simple connect started." Just to add a little additional color to what appears to be happening here…the host in question runs docker containers, at least one of which appears to be running its own systemd process. I noticed that systemd-udevd runs and ModemManager looks like it’s picking up on this udev event and re-scanning all ports. When this happens, the modem connection terminates.
Interesting. Could you play with "udevadm --trigger" and see if you can reproduce the issue? Dan
To isolate this, I delayed docker start and let the system become quiescent, and took all journalctl output since the “Activation successful” message. Here’s a log: https://gist.githubusercontent.com/spicybits/f723c9ce51 df5dad86e83726c44db623/raw/gistfile1.txt <https://gist.githubusercontent.com/spicybits/f723c9ce51df5dad86e8372 6c44db623/raw/gistfile1.txt> I first see an "Activation successful.” Then, at Apr 05 00:57:57 I trigger docker to start up. At Apr 05 00:58:00 udev triggers an event and MM reacts. Once the modem drops off, it never comes back unless it is replugged. LiamOn Apr 3, 2017, at 5:15 PM, Dan Williams <dcbw redhat com> wrote: On Mon, 2017-04-03 at 16:23 -0400, Liam Monahan wrote:Based off of the better picture I have now of what’s happening than when I originally posted, it looks like there is no condition where MM detection fails during boot. The problem is that verbose logging seems to suggest that a connection does come up for a short time during boot, but always crashes by the end of the boot sequence. The log posted is very representative of the repeatable behavior I’ve been seeing. MM detection and NM connection states both always take place, but by the time the system is quiescent and the boot sequence is “finished,” the modem has disappeared from “mmcli -L", which in turn no longer presents the device to NM. The log I posted is taken from that scenario taking place.That's clearer. A couple things: 1) are you sure the logs from ModemManager are complete? I would expect to see a large gap between 12:06:43 and 12:07:13 with no MM log messages but I'd expect to see some where MM is actually dialing the modem. For example, the last thing we see is: Mar 06 12:06:43 e5882e6 ModemManager[676]: <info> Simple connect started... Mar 06 12:06:43 e5882e6 ModemManager[676]: <debug> PIN: unspecified Mar 06 12:06:43 e5882e6 ModemManager[676]: <debug> Operator ID: unspecified and then later MM starts doing signal/registration checks. But in between there we should certainly see something like "ATDT#777" where MM is actually going through the steps for the "Simple connect", and we should see the resulting "CONNECT" from the modem before PPP happens. Any idea where those messages might have gone? If you just grab journal output from ModemManager, do they show up?Should I be focused on all the "released by modem” log messages that precede a state change from activated -> unmanaged (reason 'removed’)? I’m assuming that removal is indicated to NM through MM and not directly, right?Yeah, this is the larger problem. The modem appears to crash and drop off the USB bus. This could be due to either a firmware issue that ModemManager is triggering somehow, or it could be due to inadequate power from the USB hub. Once this happens, does it ever come back? Or is this what requires the replug? DanLiamOn Apr 3, 2017, at 3:56 PM, Dan Williams <dcbw redhat com> wrote: On Mon, 2017-04-03 at 15:08 -0400, Liam Monahan wrote:(a) Full journalctl output is available here: https://gist.gi thub user content.com/spicybits/afca83359e54c1edbc2973388e0821e7/raw/nm -mm- debug.log <https://gist.githubusercontent.com/spicybits/afca83359e54c1e dbc2 9733 88e0821e7/raw/nm-mm-debug.log> (I wasn't sure about the listserv ettiquete here around posting large logs inline or linking to them… If this has a resolution, I’ll definitely make sure the relevant parts get preserved for posterity.)That log shows a successful USB enumeration, MM detection, and NM connect. It doesn't show a failed MM detection though, which would allow us to debug further. It does show a problem detecting the access technology, which I've sent a patch for the list.(b) The modem is enumerated on boot-up in dmesg. After the device has deactivated and no longer shows up in MM, it *does* still show through lsusb. I’ve tried a few different powered hubs and the result is the same. The modem is right at the threshold current draw for a Raspberry Pi, so, yes, all testing has been done with a USB hub.Do we have logs of this bootup somewhere, rather than the above one that doesn't show the failure? DanLiamOn Apr 3, 2017, at 11:42 AM, Dan Williams <dcbw redhat com> wrote: On Mon, 2017-04-03 at 11:15 -0400, Liam Monahan wrote:Thanks for your guidance. When the device doesn’t show up in NM, it can’t be seen through mmcli. I turned up the logging level to see what’s going on. Maybe you have a different reading of this, but the first thing that jumps out at me is that something seems to be sending NM/MM a TERM signal.Ok, if the device cannot be seen in 'mmcli' that means ModemManager didn't find it either. MM must see it, because MM presents the modem to NetworkManager. If MM doesn't see it, then there are two possibilities: (a) ModemManager bug with device detection; here we need boot- time logs of ModemManager with debug log level to see if MM is told about the device by the kernel/udev, and what it does with that device. To do this, edit /usr/lib/systemd/system/ModemManager.service and change the ExecStart= line to add "--log-level=debug" and reboot the machine until the problem occurs. Then grab ModemManager journal output so we can debug. (b) kernel driver problems; usually due to your USB Host Controller driver rather than a modem driver itself; there are sometimes issues with device enumeration and specific USB chipsets. 'dmesg' output usually shows this as the device simply not being enumerated on boot-up and not showing up in 'lsusb'. Unfortunately, can take some pretty heavy kernel debugging. I see this is a Raspberry Pi 3 using dwc_otg as the USB host controller driver. Is the modem behind that USB hub I see being enumerated? Have you tried using a different hub to see if that makes a difference? Is the hub powered? Dan# 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 :000 1/mm c1:0 001: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.On Mar 30, 2017, at 1:10 PM, Dan Williams <dcbw@redhat. com> wrote: On Wed, 2017-03-29 at 10:48 -0400, Liam Monahan wrote:I have a USB cellular modem that will not show up in nm on boot. If the system is started up and I unplug and plug it back in, it shows up then. These device are deployed out in the field, so manual intervention is not a real option for my use case unfortunately. device is ttyUSB3 and does not show up at first: # 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 —When the device doesn't show up in NM, can you see it with "mmcli -L" before you replug it? If you can see it in mmcli, then the problem is likely in NetworkManager. Getting debug logs would be necessary, which you can do by adding this to /etc/NetworkManager/NetworkManager.conf: [logging] level=trace If you can't see it in ModemManager, then the bug is likely in MM. You can enable verbose MM debugging by modifying the ModemManager system unit file and adding "--log-level=debug" to the Exec= line. One of those should give us more info about the issue. Danand then after unplugging and plugging back in: # nmcli d DEVICE TYPE STATE CONNECTION ttyUSB3 cdma connected resin- verizon eth0 ethernet connected Wired connection 1 wlan0 wifi disconnected -- docker0 bridge unmanaged -- lo loopback unmanaged -- resin-vpn tun unmanaged -- # mmcli -L Found 1 modems: /org/freedesktop/ModemManager1/Modem/0 [Telit] DE910- DUAL dmesg makes it seem like the modem connected briefly and then disappeared. Does anyone have any thoughts on what’s going on or how I could do a better job of going about debugging this? [ 0.000000] Booting Linux on physical CPU 0x0 [ 0.000000] Initializing cgroup subsys cpuset [ 0.000000] Initializing cgroup subsys cpu [ 0.000000] Initializing cgroup subsys cpuacct [ 0.000000] Linux version 4.4.48 (andrei misc1 dev .res in.i o) (gcc version 6.2.0 (GCC) ) #2 SMP Sat Mar 11 03:08:12 UTC 2017 [ 0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d [ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache [ 0.000000] Machine model: Raspberry Pi 3 Model B Rev 1.2 [ 0.000000] cma: Reserved 8 MiB at 0x3d800000 [ 0.000000] Memory policy: Data cache writealloc [ 0.000000] On node 0 totalpages: 253952 [ 0.000000] free_area_init_node: node 0, pgdat 80ca84c0, node_mem_map bcf3a000 [ 0.000000] Normal zone: 2232 pages used for memmap [ 0.000000] Normal zone: 0 pages reserved [ 0.000000] Normal zone: 253952 pages, LIFO batch:31 [ 0.000000] [bcm2709_smp_init_cpus] enter (9540-f3003010)[ 0.000000] [bcm2709_smp_init_cpus] ncores=4 [ 0.000000] PERCPU: Embedded 13 pages/cpu @bcef6000 s23052 r8192 d22004 u53248 [ 0.000000] pcpu-alloc: s23052 r8192 d22004 u53248 alloc=13*4096 [ 0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 [ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 251720 [ 0.000000] Kernel command line: 8250.nr_uarts=1 dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2709.boardrev=0xa22082 bcm2709.serial=0xca8e10ef smsc95xx.macaddr=B8:27:EB:8E:10:EF bcm2708_fb.fbdepth=16 bcm2708_fb.fbswap=1 bcm2709.uart_clock=48000000 vc_mem.mem_base=0x3ea00000 vc_mem.mem_size=0x3f000000 dwc_otg.lpm_enable=0 console=tty1 console=ttyS0,115200 root=/dev/mmcblk0p2 rootfstype=ext4 rootwait [ 0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes) [ 0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes) [ 0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes) [ 0.000000] Memory: 983796K/1015808K available (7029K kernel code, 454K rwdata, 1956K rodata, 3524K init, 775K bss, 23820K reserved, 8192K cma-reserved) [ 0.000000] Virtual kernel memory layout: vector : 0xffff0000 - 0xffff1000 ( 4 kB) fixmap : 0xffc00000 - 0xfff00000 (3072 kB) vmalloc : 0xbe800000 - 0xff800000 (1040 MB) lowmem : 0x80000000 - 0xbe000000 ( 992 MB) modules : 0x7f000000 - 0x80000000 ( 16 MB) .text : 0x80008000 - 0x808ce6fc (8986 kB) .init : 0x808cf000 - 0x80c40000 (3524 kB) .data : 0x80c40000 - 0x80cb1a80 ( 455 kB) .bss : 0x80cb4000 - 0x80d75f84 ( 776 kB) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] Hierarchical RCU implementation. [ 0.000000] Build-time adjustment of leaf fanout to 32. [ 0.000000] NR_IRQS:16 nr_irqs:16 16 [ 0.000000] Architected cp15 timer(s) running at 19.20MHz (phys). [ 0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns [ 0.000008] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns [ 0.000024] Switching to timer-based delay loop, resolution 52ns [ 0.000269] Console: colour dummy device 80x30 [ 0.001295] console [tty1] enabled [ 0.001349] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000) [ 0.001417] pid_max: default: 32768 minimum: 301 [ 0.001746] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.001791] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes) [ 0.002732] Disabling cpuset control group subsystem [ 0.002790] Initializing cgroup subsys io [ 0.002841] Initializing cgroup subsys memory [ 0.002904] Initializing cgroup subsys devices [ 0.002947] Initializing cgroup subsys freezer [ 0.002989] Initializing cgroup subsys net_cls [ 0.003057] CPU: Testing write buffer coherency: ok [ 0.003147] ftrace: allocating 23395 entries in 69 pages [ 0.058204] CPU0: update cpu_capacity 1024 [ 0.058265] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000 [ 0.058299] [bcm2709_smp_prepare_cpus] enter [ 0.058459] Setting up static identity map for 0x8240 - 0x8274 [ 0.060108] [bcm2709_boot_secondary] cpu:1 started (0) 18 [ 0.060323] [bcm2709_secondary_init] enter cpu:1 [ 0.060366] CPU1: update cpu_capacity 1024 [ 0.060372] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001 [ 0.060751] [bcm2709_boot_secondary] cpu:2 started (0) 17 [ 0.060926] [bcm2709_secondary_init] enter cpu:2 [ 0.060946] CPU2: update cpu_capacity 1024 [ 0.060952] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002 [ 0.061314] [bcm2709_boot_secondary] cpu:3 started (0) 16 [ 0.061442] [bcm2709_secondary_init] enter cpu:3 [ 0.061462] CPU3: update cpu_capacity 1024 [ 0.061467] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003 [ 0.061528] Brought up 4 CPUs [ 0.061627] SMP: Total of 4 processors activated (153.60 BogoMIPS). [ 0.061656] CPU: All CPU(s) started in HYP mode. [ 0.061682] CPU: Virtualization extensions available. [ 0.062314] devtmpfs: initialized [ 0.072946] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4 [ 0.073313] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns [ 0.074055] pinctrl core: initialized pinctrl subsystem [ 0.074602] NET: Registered protocol family 16 [ 0.079711] DMA: preallocated 4096 KiB pool for atomic coherent allocations [ 0.086830] bcm2709: Mini UART enabled [ 0.086890] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers. [ 0.086937] hw-breakpoint: maximum watchpoint size is 8 bytes. [ 0.087110] Serial: AMBA PL011 UART driver [ 0.087264] uart-pl011 3f201000.uart: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe [ 0.087464] bcm2835-mbox 3f00b880.mailbox: mailbox enabled [ 0.150273] bcm2835-dma 3f007000.dma: DMA legacy API manager at f3007000, dmachans=0x1 [ 0.150899] SCSI subsystem initialized [ 0.151102] usbcore: registered new interface driver usbfs [ 0.151201] usbcore: registered new interface driver hub [ 0.151312] usbcore: registered new device driver usb [ 0.157747] raspberrypi-firmware soc:firmware: Attached to firmware from 2016-11-25 16:05 [ 0.184829] clocksource: Switched to clocksource arch_sys_counter [ 0.230483] FS-Cache: Loaded [ 0.230782] CacheFiles: Loaded [ 0.242888] NET: Registered protocol family 2 [ 0.243743] TCP established hash table entries: 8192 (order: 3, 32768 bytes) [ 0.243881] TCP bind hash table entries: 8192 (order: 4, 65536 bytes) [ 0.244091] TCP: Hash tables configured (established 8192 bind 8192) [ 0.244206] UDP hash table entries: 512 (order: 2, 16384 bytes) [ 0.244273] UDP-Lite hash table entries: 512 (order: 2, 16384 bytes) [ 0.244522] NET: Registered protocol family 1 [ 0.244891] RPC: Registered named UNIX socket transport module. [ 0.244923] RPC: Registered udp transport module. [ 0.244951] RPC: Registered tcp transport module. [ 0.244978] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.499843] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available [ 0.501237] futex hash table entries: 1024 (order: 4, 65536 bytes) [ 0.514403] VFS: Disk quotas dquot_6.6.0 [ 0.514744] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes) [ 0.516650] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ 0.517153] FS-Cache: Netfs 'nfs' registered for caching [ 0.518056] NFS: Registering the id_resolver key type [ 0.518128] Key type id_resolver registered [ 0.518156] Key type id_legacy registered [ 0.519889] aufs 4.4-20160912 [ 0.521345] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252) [ 0.521501] io scheduler noop registered [ 0.521537] io scheduler deadline registered [ 0.521605] io scheduler cfq registered (default) [ 0.524215] BCM2708FB: allocated DMA memory fdc10000 [ 0.524263] BCM2708FB: allocated DMA channel 0 @ f3007000 [ 0.529430] Console: switching to colour frame buffer device 82x26 [ 0.607836] Serial: 8250/16550 driver, 1 ports, IRQ sharing disabled [ 0.610911] console [ttyS0] disabled [ 0.612602] 3f215040.uart: ttyS0 at MMIO 0x3f215040 (irq = 59, base_baud = 31250000) is a 16550 [ 1.351198] console [ttyS0] enabled [ 2.342984] bcm2835-rng 3f104000.rng: hwrng registered [ 2.350152] vc-cma: Videocore CMA driver [ 2.355881] vc-cma: vc_cma_base = 0x00000000 [ 2.362328] vc-cma: vc_cma_size = 0x00000000 (0 MiB) [ 2.369453] vc-cma: vc_cma_initial = 0x00000000 (0 MiB) [ 2.376750] vc-mem: phys_addr:0x00000000 mem_base=0x3ea00000 mem_size:0x3f000000(1008 MiB) [ 2.402945] brd: module loaded [ 2.416363] loop: module loaded [ 2.421958] vchiq: vchiq_init_state: slot_zero = 0xbdc80000, is_master = 0 [ 2.431945] Loading iSCSI transport class v2.0- 870. [ 2.439091] tun: Universal TUN/TAP device driver, 1.6 [ 2.445880] tun: (C) 1999-2004 Max Krasnyansky <ma xk@q ualc omm. com> [ 2.454093] usbcore: registered new interface driver smsc95xx [ 2.461584] dwc_otg: version 3.00a 10-AUG-2012 (platform bus) [ 2.669293] Core Release: 2.80a [ 2.674094] Setting default values for core params [ 2.680641] Finished setting default values for core params [ 2.888300] Using Buffer DMA mode [ 2.893340] Periodic Transfer Interrupt Enhancement - disabled [ 2.900980] Multiprocessor Interrupt Enhancement - disabled [ 2.908339] OTG VER PARAM: 0, OTG VER FLAG: 0 [ 2.914428] Dedicated Tx FIFOs mode [ 2.919865] WARN::dwc_otg_hcd_init:1047: FIQ DMA bounce buffers: virt = 0xbdc04000 dma = 0xfdc04000 len=9024 [ 2.933170] FIQ FSM acceleration enabled for : Non-periodic Split Transactions Periodic Split Transactions High-Speed Isochronous Endpoints Interrupt/Control Split Transaction hack enabled [ 2.964168] dwc_otg: Microframe scheduler enabled [ 2.964229] WARN::hcd_init_fiq:413: FIQ on core 1 at 0x80481ef8 [ 2.971952] WARN::hcd_init_fiq:414: FIQ ASM at 0x80482258 length 36 [ 2.979974] WARN::hcd_init_fiq:439: MPHI regs_base at 0xbe87e000 [ 2.987783] dwc_otg 3f980000.usb: DWC OTG Controller [ 2.994534] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1 [ 3.003694] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000 [ 3.011068] Init: Port Power? op_state=1 [ 3.016708] Init: Power Port (0) [ 3.021786] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002 [ 3.030361] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1 [ 3.039371] usb usb1: Product: DWC OTG Controller [ 3.045792] usb usb1: Manufacturer: Linux 4.4.48 dwc_otg_hcd [ 3.053178] usb usb1: SerialNumber: 3f980000.usb [ 3.060187] hub 1-0:1.0: USB hub found [ 3.065630] hub 1-0:1.0: 1 port detected [ 3.071726] dwc_otg: FIQ enabled [ 3.071735] dwc_otg: NAK holdoff enabled [ 3.071742] dwc_otg: FIQ split-transaction FSM enabled [ 3.071772] Module dwc_common_port init [ 3.072020] usbcore: registered new interface driver usb- storage [ 3.079955] mousedev: PS/2 mouse device common for all mice [ 3.087879] bcm2835-cpufreq: min=600000 max=1200000 [ 3.094683] sdhci: Secure Digital Host Controller Interface driver [ 3.102565] sdhci: Copyright(c) Pierre Ossman [ 3.108808] sdhost: log_buf @ bdc07000 (fdc07000) [ 3.174858] mmc0: sdhost-bcm2835 loaded - DMA enabled (>1) [ 3.184314] mmc-bcm2835 3f300000.mmc: mmc_debug:0 mmc_debug2:0 [ 3.191851] mmc-bcm2835 3f300000.mmc: DMA channel allocated [ 3.254943] sdhci-pltfm: SDHCI platform and OF driver helper [ 3.262666] ledtrig-cpu: registered to indicate activity on CPUs [ 3.270471] Indeed it is in host mode hprt0 = 00021501 [ 3.295045] hidraw: raw HID events driver (C) Jiri Kosina [ 3.302346] usbcore: registered new interface driver usbhid [ 3.309643] usbhid: USB HID core driver [ 3.316276] nf_conntrack version 0.5.0 (15499 buckets, 61996 max) [ 3.337759] ip_tables: (C) 2000-2006 Netfilter Core Team [ 3.344991] Initializing XFRM netlink socket [ 3.347127] mmc0: host does not support reading read- only switch, assuming write-enable [ 3.350467] mmc0: new high speed SDXC card at address aaaa [ 3.351173] mmcblk0: mmc0:aaaa SL64G 59.5 GiB [ 3.368775] mmcblk0: p1 p2 p3 p4 < p5 p6 > [ 3.383344] NET: Registered protocol family 10 [ 3.386935] mmc1: queuing unknown CIS tuple 0x80 (2 bytes) [ 3.388488] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 3.390042] mmc1: queuing unknown CIS tuple 0x80 (3 bytes) [ 3.392838] mmc1: queuing unknown CIS tuple 0x80 (7 bytes) [ 3.419647] NET: Registered protocol family 17 [ 3.425795] bridge: automatic filtering via arp/ip/ip6tables has been deprecated. Update your scripts to load br_netfilter if you need this. [ 3.441979] Key type dns_resolver registered [ 3.448408] Registering SWP/SWPB emulation handler [ 3.454874] usb 1-1: new high-speed USB device number 2 using dwc_otg [ 3.455014] Indeed it is in host mode hprt0 = 00001101 [ 3.470876] registered taskstats version 1 [ 3.476866] vc-sm: Videocore shared memory driver [ 3.483289] [vc_sm_connected_init]: start [ 3.483387] mmc1: new high speed SDIO card at address 0001 [ 3.505074] vc_vchi_sm_init: failed to open VCHI service (-1) [ 3.510815] [vc_sm_connected_init]: failed to initialize shared memory service [ 3.521606] [vc_sm_connected_init]: end - returning -1 [ 3.529758] 3f201000.uart: ttyAMA0 at MMIO 0x3f201000 (irq = 87, base_baud = 0) is a PL011 rev2 [ 3.542381] of_cfs_init [ 3.546538] of_cfs_init: OK [ 3.556218] Freeing unused kernel memory: 3524K (808cf000 - 80c40000) [ 3.655220] usb 1-1: New USB device found, idVendor=0424, idProduct=9514 [ 3.664274] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 [ 3.674620] hub 1-1:1.0: USB hub found [ 3.680578] hub 1-1:1.0: 5 ports detected [ 3.964918] usb 1-1.1: new high-speed USB device number 3 using dwc_otg [ 4.085270] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00 [ 4.094280] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0 [ 4.104314] random: udevd: uninitialized urandom read (16 bytes read, 65 bits of entropy available) [ 4.107092] smsc95xx v1.0.4 [ 4.110606] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.110869] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.110981] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.111393] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.111799] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.112199] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.113772] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.114238] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.114788] random: udevadm: uninitialized urandom read (16 bytes read, 66 bits of entropy available) [ 4.168446] smsc95xx 1-1.1:1.0 eth0: register 'smsc95xx' at usb- 3f980000.usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:8e:10:ef [ 4.244874] usb 1-1.2: new high-speed USB device number 4 using dwc_otg [ 4.346726] usb 1-1.2: New USB device found, idVendor=2109, idProduct=2813 [ 4.356346] usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=0 [ 4.366269] usb 1-1.2: Product: USB2.0 Hub [ 4.372809] usb 1-1.2: Manufacturer: VIA Labs, Inc. [ 4.381150] hub 1-1.2:1.0: USB hub found [ 4.387810] hub 1-1.2:1.0: 4 ports detected [ 4.684914] usb 1-1.2.1: new high-speed USB device number 5 using dwc_otg [ 4.806707] usb 1-1.2.1: New USB device found, idVendor=2109, idProduct=2813 [ 4.816319] usb 1-1.2.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0 [ 4.828320] usb 1-1.2.1: Product: USB2.0 Hub [ 4.834803] usb 1-1.2.1: Manufacturer: VIA Labs, Inc. [ 4.844192] hub 1-1.2.1:1.0: USB hub found [ 4.851478] hub 1-1.2.1:1.0: 4 ports detected [ 5.071690] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null) [ 5.122129] EXT4-fs (mmcblk0p5): mounted filesystem with ordered data mode. Opts: (null) [ 5.440757] systemd[1]: System time before build time, advancing clock. [ 5.495438] systemd[1]: systemd 230 running in system mode. (- PAM -AUDIT -SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN) [ 5.520088] systemd[1]: Detected architecture arm. [ 5.558280] systemd[1]: Set hostname to <raspberrypi3>. [ 5.915955] systemd[1]: brcm43438.service: Cannot add dependency job, ignoring: Unit brcm43438.service is masked. [ 5.934618] systemd[1]: Listening on Syslog Socket. [ 5.965144] systemd[1]: Listening on udev Kernel Socket. [ 6.013951] systemd[1]: Reached target Swap. [ 6.036703] systemd[1]: Created slice User and Session Slice. [ 6.065247] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ 6.095032] systemd[1]: Reached target Remote File Systems. [ 6.125239] systemd[1]: Listening on Journal Socket. [ 6.155232] systemd[1]: Listening on udev Control Socket. [ 6.185135] systemd[1]: Listening on /dev/initctl Compatibility Named Pipe. [ 6.215100] systemd[1]: Listening on Journal Socket (/dev/log). [ 6.245643] systemd[1]: Created slice System Slice. [ 6.275737] systemd[1]: Created slice system- getty.slice. [ 6.335211] systemd[1]: Mounting POSIX Message Queue File System... [ 6.354647] systemd[1]: Starting Create list of required static device nodes for the current kernel... [ 6.397755] systemd[1]: Starting Apply Kernel Variables... [ 6.428238] systemd[1]: Mounting Temporary Directory... [ 6.441175] systemd[1]: Created slice system- resin\x2dinfo.slice. [ 6.475808] systemd[1]: Created slice system- serial\x2dgetty.slice. [ 6.535185] systemd[1]: Mounting Configuration File System... [ 6.567876] systemd[1]: Starting Journal Service... [ 6.598113] systemd[1]: Mounting Debug File System... [ 6.627682] systemd[1]: Starting Remount Root and Kernel File Systems... [ 6.642643] systemd[1]: Reached target Slices. [ 6.652408] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null) [ 6.678043] systemd[1]: Starting Setup Virtual Console... [ 6.715769] systemd[1]: Mounted Configuration File System. [ 6.745141] systemd[1]: Mounted POSIX Message Queue File System. [ 6.775074] systemd[1]: Mounted Debug File System. [ 6.805059] systemd[1]: Mounted Temporary Directory. [ 6.835426] systemd[1]: Started Journal Service. [ 7.460913] random: nonblocking pool is initialized [ 7.511711] bcm2835-wdt 3f100000.watchdog: Broadcom BCM2835 watchdog timer [ 7.521140] bcm2708_i2c 3f804000.i2c: BSC1 Controller at 0x3f804000 (irq 83) (baudrate 100000) [ 7.618164] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000 [ 7.924559] usbcore: registered new interface driver brcmfmac [ 8.071455] brcmfmac: brcmf_c_preinit_dcmds: Firmware version = wl0: Aug 29 2016 20:48:16 version 7.45.41.26 (r640327) FWID 01- 4527cfab [ 8.115653] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code [ 8.171708] brcmfmac: brcmf_cfg80211_reg_notifier: not a ISO3166 code [ 8.180085] cfg80211: World regulatory domain updated: [ 8.187070] cfg80211: DFS Master region: unset [ 8.191563] cfg80211: (start_freq - end_freq @ bandwidth), (max_antenna_gain, max_eirp), (dfs_cac_time) [ 8.206654] cfg80211: (2402000 KHz - 2472000 KHz @ 40000 KHz), (N/A, 2000 mBm), (N/A) [ 8.218500] cfg80211: (2457000 KHz - 2482000 KHz @ 20000 KHz, 92000 KHz AUTO), (N/A, 2000 mBm), (N/A) [ 8.231899] cfg80211: (2474000 KHz - 2494000 KHz @ 20000 KHz), (N/A, 2000 mBm), (N/A) [ 8.244070] cfg80211: (5170000 KHz - 5250000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (N/A) [ 8.257930] cfg80211: (5250000 KHz - 5330000 KHz @ 80000 KHz, 160000 KHz AUTO), (N/A, 2000 mBm), (0 s) [ 8.272011] cfg80211: (5490000 KHz - 5730000 KHz @ 160000 KHz), (N/A, 2000 mBm), (0 s) [ 8.284778] cfg80211: (5735000 KHz - 5835000 KHz @ 80000 KHz), (N/A, 2000 mBm), (N/A) [ 8.297509] cfg80211: (57240000 KHz - 63720000 KHz @ 2160000 KHz), (N/A, 0 mBm), (N/A) [ 8.728734] FAT-fs (mmcblk0p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck. [ 11.034879] usb 1-1.2.1.4: new high-speed USB device number 6 using dwc_otg [ 11.163270] usb 1-1.2.1.4: New USB device found, idVendor=1bc7, idProduct=1010 [ 11.173591] usb 1-1.2.1.4: New USB device strings: Mfr=3, Product=2, SerialNumber=0 [ 11.186183] usb 1-1.2.1.4: Product: Telit HS-USB Modem [ 11.193822] usb 1-1.2.1.4: Manufacturer: Telit Wireless Solutions [ 11.298375] usbcore: registered new interface driver usbserial [ 11.306974] usbcore: registered new interface driver usbserial_generic [ 11.310874] i2c /dev entries driver [ 11.322683] usbserial: USB Serial support registered for generic [ 11.457307] usbcore: registered new interface driver option [ 11.465653] usbserial: USB Serial support registered for GSM modem (1-port) [ 11.476030] option 1-1.2.1.4:1.0: GSM modem (1- port) converter detected [ 11.485725] usb 1-1.2.1.4: GSM modem (1-port) converter now attached to ttyUSB0 [ 11.495740] option 1-1.2.1.4:1.1: GSM modem (1- port) converter detected [ 11.505452] usb 1-1.2.1.4: GSM modem (1-port) converter now attached to ttyUSB1 [ 11.515829] option 1-1.2.1.4:1.2: GSM modem (1- port) converter detected [ 11.525445] usb 1-1.2.1.4: GSM modem (1-port) converter now attached to ttyUSB2 [ 11.535416] option 1-1.2.1.4:1.3: GSM modem (1- port) converter detected [ 11.545109] usb 1-1.2.1.4: GSM modem (1-port) converter now attached to ttyUSB3 [ 11.850674] brcmfmac: power management disabled [ 12.755171] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 12.817140] smsc95xx 1-1.1:1.0 eth0: hardware isn't capable of remote wakeup [ 12.826826] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready [ 12.859391] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 12.907950] brcmfmac: brcmf_add_if: ERROR: netdev:wlan0 already exists [ 12.916649] brcmfmac: brcmf_add_if: ignore IF event [ 12.925860] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 12.933950] brcmfmac: power management disabled [ 13.461267] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 13.469380] brcmfmac: power management disabled [ 14.036469] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready [ 27.920076] PPP generic driver version 2.4.2 [ 27.998212] PPP BSD Compression module registered [ 28.043248] PPP Deflate Compression module registered [ 111.945594] EXT4-fs (mmcblk0p6): mounted filesystem with ordered data mode. Opts: (null) [ 113.227019] Bridge firewalling registered [ 113.797830] IPv6: ADDRCONF(NETDEV_UP): docker0: link is not ready [ 113.993171] aufs au_opts_verify:1597:docker[903]: dirperm1 breaks the protection by the permission bits on the lower branch [ 115.797146] EXT4-fs (mmcblk0p6): Unrecognized mount option "mode=755" or missing value [ 116.533554] systemd-udevd[49]: starting version 215 [ 116.957152] systemd-journald[41]: Received request to flush runtime journal from PID 1 [ 127.553331] uart-pl011 3f201000.uart: no DMA platform data _______________________________________________ networkmanager-list mailing list networkmanager-list gnome org https://mail.gnome.org/mailman/listinfo/networkmanage r-li st