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.
To isolate this, I delayed docker start and let the system become quiescent, and took all journalctl output since the “Activation successful” message.
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.
Liam
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? Dan Liam
On 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.github
user
content.com/spicybits/afca83359e54c1edbc2973388e0821e7/raw/nm-mm-
debug.log
<https://gist.githubusercontent.com/spicybits/afca83359e54c1edbc2
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?
Dan
Liam
On 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.
Dan
and 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 <maxk@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/networkmanager-li
st
|
