ANN: ModemManager 1.18.4 released / Avoiding PPP
Aleksander Morgado
aleksander at aleksander.es
Wed Jan 12 15:01:06 UTC 2022
Hey,
> >>> Also, please note that if you fully disable the PPP usage (maybe
> >>> making sure that data_at_primary is always NULL in
> >>> mm_base_modem_organize_ports()), what you will achieve is that the
> >>> modem ends up not usable ("Failed to find a data port in the modem").
> >>> You need to decide whether that's better than falling back to PPP. As
> >>> said in an earlier email, the key would be to understand why you don't
> >>> have a valid QMI+NET pair, not really to disable the PPP usage (IMO).
> >>
> >> Well, it took me a while to get this; it requires a specific setup. What I can
> >> say is that it most often happens at OpenWrt boot, but by no means always.
> >>
> >
> > There's a problem in that log, and the problem is exclusively
> > happening on system boots.
>
> I'll take your word for it, *but* the problem with triggering PPP happens
> other times too, but it's just most likely at boot. The end result is much
> the same.
>
As said earlier, then it could also be due to failed QMI port
probings. In the log you posted below in this email, the QMI port is
correctly detected, and correctly probed:
Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] QMI Device
supports 28 services:
> It's worth pointing out that if there's loss of connectivity on the modem
> (unplug the antenna for example), it will completely cycle the USB and the
> ports will vanish and then come back. I don't know if this is normal, but
> the effect is much like (but not identical) to that of boot.
That looks like a firmware crash in the modem; the modem goes away
from USB and comes back, and full port probing is restarted in MM.
>
> As a digression, the "45 second" issue to which I put the retries in for
> would most often happen at "first boot" where it's setting up the flash,
> but MM hadn't started yet.
>
> In any case, I have a script which power cycles the modem and the USB
> hub, which closely emulates the power on cycle/signal loss, but is obviously not
> 100% identical. I use this for some of my testing.
>
> Here's a log where the system does come up properly; I think this is worth
> considering to make sure this is OK:
>
It looks ok to me; as per the message I referenced above, the QMI port
is correctly detected and the port probing has succeeded.
>
>
> ue Jan 11 18:13:57 2022 user.notice ModemManager: hotplug: add network interface
> ip6tnl0: event processed
> Tue Jan 11 18:13:57 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:13:57 2022 user.notice ModemManager: hotplug: add network
> interface gre0: event processed
> Tue Jan 11 18:13:57 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.616720] mtk_soc_eth
> 1e100000.ethernet: PPE started
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.638877] br-lan: port 1(eth0.1)
> entered blocking state
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.649726] br-lan: port 1(eth0.1)
> entered disabled state
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.661516] device eth0.1 entered
> promiscuous mode
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.671169] device eth0 entered
> promiscuous mode
> Tue Jan 11 18:13:58 2022 user.notice ModemManager: hotplug: add network
> interface gretap0: event processed
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.686813] br-lan: port 1(eth0.1)
> entered blocking state
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.697655] br-lan: port 1(eth0.1)
> entered forwarding state
> Tue Jan 11 18:13:58 2022 kern.info kernel: [ 30.709392] IPv6:
> ADDRCONF(NETDEV_UP): br-lan: link is not ready
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'lan' is enabled
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'lan' is setting up now
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'lan' is now up
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: bridge 'br-lan' link is up
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'lan' has link connectivity
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: VLAN 'eth0.1' link is up
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'loopback' is enabled
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'loopback' is setting
> up now
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'loopback' is now up
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'wwan' is setting up now
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Network device 'eth0' link is up
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Network device 'lo' link is up
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: Interface 'loopback' has link
> connectivity
> Tue Jan 11 18:13:58 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: wwan (2328): error: couldn't get
> bus: Could not connect: No such file or directory
> Tue Jan 11 18:13:58 2022 daemon.notice netifd: wwan (2328): Device not managed
> by ModemManager
> Tue Jan 11 18:13:58 2022 user.notice firewall: Reloading firewall due to ifup of
> lan (br-lan)
> Tue Jan 11 18:13:59 2022 daemon.notice netifd: wwan (2400): stopping network
> Tue Jan 11 18:13:59 2022 daemon.notice netifd: wwan (2400): error: couldn't get
> bus: Could not connect: No such file or directory
> Tue Jan 11 18:13:59 2022 daemon.notice netifd: wwan (2400): couldn't load bearer
> path
> Tue Jan 11 18:13:59 2022 daemon.notice netifd: Interface 'wwan' is now down
> Tue Jan 11 18:13:59 2022 kern.info kernel: [ 31.643038] IPv6:
> ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
> Tue Jan 11 18:13:59 2022 user.notice ModemManager: hotplug: add network
> interface erspan0: event processed
> Tue Jan 11 18:13:59 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:13:59 2022 daemon.err procd: failed to open pidfile for writing: :
> No such file or directory
> Tue Jan 11 18:14:00 2022 daemon.err odhcpd[1992]: Failed to send to
> ff02::1%lan at br-lan (Address not available)
> Tue Jan 11 18:14:00 2022 user.notice ModemManager: hotplug: add network
> interface ip6gre0: event processed
> Tue Jan 11 18:14:00 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:01 2022 user.notice ModemManager: hotplug: checking if
> ModemManager is available...
> Tue Jan 11 18:14:01 2022 daemon.info [2603]: <info> [1641924841.257035]
> ModemManager (version 1.18.4) starting in system bus...
> Tue Jan 11 18:14:01 2022 user.notice ModemManager: hotplug: ModemManager not yet
> available
> Tue Jan 11 18:14:01 2022 user.notice ModemManager: hotplug: add network
> interface wwan0: event processed
> Tue Jan 11 18:14:01 2022 user.notice ModemManager: hotplug: interface 'wwan' is
> set to configure device '/sys/devices/platform/1e1c0000.xhci/usb2/2-1'
> Tue Jan 11 18:14:01 2022 user.notice ModemManager: hotplug: now waiting for
> modem at sysfs path /sys/devices/platform/1e1c0000.xhci/usb2/2-1
> Tue Jan 11 18:14:01 2022 user.notice ModemManager: hotplug: add cdc interface
> cdc-wdm0: custom event processed
> Tue Jan 11 18:14:02 2022 user.notice ModemManager: hotplug: checking if
> ModemManager is available...
> Tue Jan 11 18:14:02 2022 user.notice ModemManager: hotplug: add serial interface
> ttyUSB0: event processed
> Tue Jan 11 18:14:02 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=console, subsystem=tty, sysfspath=/sys/devices/virtual/tty/console
> Tue Jan 11 18:14:02 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:02 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ttyS2, subsystem=tty,
> sysfspath=/sys/devices/platform/serial8250/tty/ttyS2
> Tue Jan 11 18:14:02 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:02 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ttyS0, subsystem=tty,
> sysfspath=/sys/devices/platform/1e000000.palmbus/1e000c00.uartlite/tty/ttyS0
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ttyS1, subsystem=tty,
> sysfspath=/sys/devices/platform/serial8250/tty/ttyS1
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ip6tnl0, subsystem=net, sysfspath=/sys/devices/virtual/net/ip6tnl0
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:03 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Opening device
> with flags 'version-info, proxy'...
> Tue Jan 11 18:14:03 2022 daemon.debug [2603]: [/dev/cdc-wdm0] created endpoint
> Tue Jan 11 18:14:03 2022 daemon.debug [2603]: cannot connect to proxy: Could not
> connect: Connection refused
> Tue Jan 11 18:14:03 2022 daemon.debug [2603]: spawning new qmi-proxy (try 1)...
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=gre0, subsystem=net, sysfspath=/sys/devices/virtual/net/gre0
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: add serial interface
> ttyUSB1: event processed
> Tue Jan 11 18:14:03 2022 daemon.debug [2603]: cannot connect to proxy: Could not
> connect: Connection refused
> Tue Jan 11 18:14:03 2022 daemon.debug [2603]: spawning new qmi-proxy (try 2)...
> Tue Jan 11 18:14:03 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:04 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Checking version
> info (45 retries)...
> Tue Jan 11 18:14:04 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=gretap0, subsystem=net, sysfspath=/sys/devices/virtual/net/gretap0
> Tue Jan 11 18:14:04 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:04 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=erspan0, subsystem=net, sysfspath=/sys/devices/virtual/net/erspan0
> Tue Jan 11 18:14:04 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:04 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ip6gre0, subsystem=net, sysfspath=/sys/devices/virtual/net/ip6gre0
> Tue Jan 11 18:14:04 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:04 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=wwan0, subsystem=net,
> sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.4/net/wwan0
> Tue Jan 11 18:14:05 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=cdc-wdm0, subsystem=usbmisc,
> sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.4/net/wwan0
> Tue Jan 11 18:14:05 2022 user.notice root: MCU Version check: Configured:
> vehicle Firmware Version: 0x03 config: 0x00
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] No transaction
> matched in received message
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] QMI Device
> supports 28 services:
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] ctl (1.5)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] wds (1.119)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] dms (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] nas (1.25)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] qos (1.12)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] wms (1.10)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] auth (1.3)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] at (1.4)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] voice (2.1)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] cat2 (2.24)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] uim (1.77)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] pbm (1.4)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] test (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] loc (2.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] sar (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] ts (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] tmd (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] wda (1.16)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] csvt (1.1)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] coex (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] pdc (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] rfrpe (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] dsd (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x30]
> (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x31]
> (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x36]
> (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x44]
> (1.0)
> Tue Jan 11 18:14:05 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x4a]
> (1.0)
> Tue Jan 11 18:14:05 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ttyUSB0, subsystem=tty,
> sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.0/ttyUSB0/tty/ttyUSB0
> Tue Jan 11 18:14:05 2022 user.notice ModemManager: hotplug: add serial interface
> ttyUSB2: event processed
> Tue Jan 11 18:14:05 2022 daemon.info [2603]: <info> [1641924845.629711] [device
> /sys/devices/platform/1e1c0000.xhci/usb2/2-1] creating modem with plugin
> 'quectel' and '4' ports
> Tue Jan 11 18:14:05 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ttyUSB1, subsystem=tty,
> sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.1/ttyUSB1/tty/ttyUSB1
> Tue Jan 11 18:14:06 2022 user.notice ModemManager: hotplug: cached event found:
> action=add, name=ttyUSB2, subsystem=tty,
> sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.2/ttyUSB2/tty/ttyUSB2
> Tue Jan 11 18:14:06 2022 daemon.info [2603]: <info> [1641924846.191458]
> [base-manager] modem for device '/sys/devices/platform/1e1c0000.xhci/usb2/2-1'
> successfully created
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Opening device
> with flags 'version-info, proxy'...
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] created endpoint
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Checking version
> info (45 retries)...
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] QMI Device
> supports 28 services:
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] ctl (1.5)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] wds (1.119)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] dms (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] nas (1.25)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] qos (1.12)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] wms (1.10)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] auth (1.3)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] at (1.4)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] voice (2.1)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] cat2 (2.24)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] uim (1.77)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] pbm (1.4)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] test (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] loc (2.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] sar (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] ts (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] tmd (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] wda (1.16)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] csvt (1.1)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] coex (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] pdc (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] rfrpe (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] dsd (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x30]
> (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x31]
> (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x36]
> (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x44]
> (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] unknown [0x4a]
> (1.0)
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'wda'
> (version 1.16) client with ID '1'
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Releasing 'wda'
> client with flags 'release-cid'...
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Unregistered 'wda'
> client with ID '1'
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'dms'
> (version 1.0) client with ID '1'
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'nas'
> (version 1.25) client with ID '5'
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'wds'
> (version 1.119) client with ID '18'
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'wms'
> (version 1.10) client with ID '2'
> Tue Jan 11 18:14:06 2022 user.notice ModemManager: hotplug: add serial interface
> ttyUSB3: event processed
> Tue Jan 11 18:14:06 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'uim'
> (version 1.77) client with ID '3'
> Tue Jan 11 18:14:07 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'loc'
> (version 2.0) client with ID '1'
> Tue Jan 11 18:14:07 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'pdc'
> (version 1.0) client with ID '1'
> Tue Jan 11 18:14:07 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'voice'
> (version 2.1) client with ID '4'
> Tue Jan 11 18:14:07 2022 daemon.info procd: - init complete -
> Tue Jan 11 18:14:07 2022 user.notice ModemManager: hotplug: add network
> interface br-lan: event processed
> Tue Jan 11 18:14:07 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:08 2022 user.notice ModemManager: hotplug: add network
> interface eth0.1: event processed
> Tue Jan 11 18:14:08 2022 user.notice ModemManager: hotplug: error: parent device
> sysfspath not found
> Tue Jan 11 18:14:10 2022 daemon.warn [2603]: <warn> [1641924850.320900]
> [modem0/sim0] couldn't load list of emergency numbers: No AT port available to
> run command
> Tue Jan 11 18:14:10 2022 daemon.info [2603]: <info> [1641924850.569189]
> [base-manager] couldn't check support for device
> '/sys/devices/platform/1e100000.ethernet': not supported by any plugin
> Tue Jan 11 18:14:10 2022 daemon.warn [2603]: <warn> [1641924850.708098]
> [modem0] couldn't load UE mode of operation for EPS: No AT port available to run
> command
> Tue Jan 11 18:14:11 2022 daemon.warn [2603]: <warn> [1641924851.429237]
> [modem0] couldn't open ports during Modem SIM hot swap enabling: Couldn't get
> primary port
> Tue Jan 11 18:14:11 2022 daemon.info [2603]: <info> [1641924851.430371]
> [modem0] state changed (unknown -> disabled)
> Tue Jan 11 18:14:12 2022 user.notice ModemManager: hotplug: modem exported
> successfully at /sys/devices/platform/1e1c0000.xhci/usb2/2-1
> Tue Jan 11 18:14:12 2022 user.notice ModemManager: hotplug: setting interface
> 'wwan' as available
> Tue Jan 11 18:14:12 2022 daemon.notice netifd: Interface 'wwan' is setting up now
> Tue Jan 11 18:14:12 2022 daemon.notice netifd: wwan (4900): modem available at
> /org/freedesktop/ModemManager1/Modem/0
> Tue Jan 11 18:14:12 2022 daemon.notice netifd: wwan (4900): starting connection
> with apn 'firstnet-broadband'...
> Tue Jan 11 18:14:12 2022 daemon.info [2603]: <info> [1641924852.763833]
> [modem0] simple connect started...
> Tue Jan 11 18:14:12 2022 daemon.info [2603]: <info> [1641924852.764102]
> [modem0] simple connect state (3/8): enable
> Tue Jan 11 18:14:12 2022 daemon.info [2603]: <info> [1641924852.764524]
> [modem0] state changed (disabled -> enabling)
> Tue Jan 11 18:14:12 2022 daemon.info [2603]: <info> [1641924852.983603]
> [modem0] autoconnect explicitly disabled
> Tue Jan 11 18:14:13 2022 daemon.info [2603]: <info> [1641924853.105314]
> [modem0] power state updated: on
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.385721]
> [modem0] simple connect state (4/8): wait to get fully enabled
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.386581]
> [modem0] state changed (enabling -> enabled)
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.393321]
> [modem0] simple connect state (5/8): register
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.513488]
> [modem0] 3GPP registration state changed (unknown -> registering)
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.514782]
> [modem0] 3GPP registration state changed (registering -> home)
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.515336]
> [modem0] state changed (enabled -> registered)
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.642636]
> [modem0] simple connect state (6/8): bearer
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.655644]
> [modem0] simple connect state (7/8): connect
> Tue Jan 11 18:14:14 2022 daemon.info [2603]: <info> [1641924854.658590]
> [modem0] state changed (registered -> connecting)
> Tue Jan 11 18:14:14 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'wds'
> (version 1.119) client with ID '19'
> Tue Jan 11 18:14:15 2022 daemon.info [2603]: <info> [1641924855.472873]
> [modem0/bearer1] QMI IPv4 Settings:
> Tue Jan 11 18:14:15 2022 daemon.info [2603]: <info> [1641924855.473295]
> [modem0/bearer1] address: 10.99.10.66/30
> Tue Jan 11 18:14:15 2022 daemon.info [2603]: <info> [1641924855.473450]
> [modem0/bearer1] gateway: 10.99.10.65
> Tue Jan 11 18:14:15 2022 daemon.info [2603]: <info> [1641924855.473612]
> [modem0/bearer1] DNS #1: 107.112.229.135
> Tue Jan 11 18:14:15 2022 daemon.info [2603]: <info> [1641924855.473796]
> [modem0/bearer1] DNS #2: failed (Field 'Secondary IPv4 DNS Address' was not
> found in the message)
> Tue Jan 11 18:14:15 2022 daemon.info [2603]: <info> [1641924855.473973]
> [modem0/bearer1] MTU: 1342
> Tue Jan 11 18:14:15 2022 daemon.debug [2603]: [/dev/cdc-wdm0] Registered 'wds'
> (version 1.119) client with ID '20'
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.368787]
> [modem0/bearer1] QMI IPv6 Settings:
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.369119]
> [modem0/bearer1] address: 2600:380:fea3:a19a:909e:981f:304f:61ac/64
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.369336]
> [modem0/bearer1] gateway: 2600:380:fea3:a19a:948e:bc6:5528:a2c7/64
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.369548]
> [modem0/bearer1] DNS #1: 2600:300:2050:1e05::7
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.369743]
> [modem0/bearer1] DNS #2: failed (Field 'IPv6 Secondary DNS Address' was not
> found in the message)
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.369923]
> [modem0/bearer1] MTU: 1342
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.373960]
> [modem0] state changed (connecting -> connected)
> Tue Jan 11 18:14:16 2022 daemon.info [2603]: <info> [1641924856.377581]
> [modem0] simple connect state (8/8): all done
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): successfully
> connected the modem
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): signal refresh rate
> is not set
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): network operator
> name: FirstNet
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): network operator
> MCCMNC: 313100
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): registration type: home
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): access technology: lte
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): signal quality: 100%
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): IPv4 connection
> setup required in interface wwan: static
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): adding IPv4 address
> 10.99.10.66, netmask 255.255.255.252
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): adding default IPv4
> route via 10.99.10.65
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): adding primary DNS
> at 107.112.229.135
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: Interface 'wwan' is now up
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: reading
> /tmp/resolv.conf.d/resolv.conf.auto
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: Network device 'wwan0' link is up
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using nameserver
> 107.112.229.135#53
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for test
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for onion
> Tue Jan 11 18:14:16 2022 daemon.notice netifd: wwan (4900): IPv6 connection
> setup required in interface wwan: static
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for localhost
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for local
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for invalid
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for bind
> Tue Jan 11 18:14:16 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for lan
> Tue Jan 11 18:14:17 2022 daemon.notice netifd: wwan (4900): adding IPv6 address
> 2600:380:fea3:a19a:909e:981f:304f:61ac, prefix 64
> Tue Jan 11 18:14:17 2022 daemon.notice netifd: wwan (4900): adding default IPv6
> route via 2600:380:fea3:a19a:948e:bc6:5528:a2c7
> Tue Jan 11 18:14:17 2022 daemon.notice netifd: wwan (4900): adding primary DNS
> at 2600:300:2050:1e05::7
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: reading
> /tmp/resolv.conf.d/resolv.conf.auto
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using nameserver
> 107.112.229.135#53
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using nameserver
> 2600:300:2050:1e05::7#53
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for test
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for onion
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for localhost
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for local
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for invalid
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for bind
> Tue Jan 11 18:14:17 2022 daemon.info dnsmasq[1582]: using only locally-known
> addresses for lan
> Tue Jan 11 18:14:17 2022 user.notice firewall: Reloading firewall due to ifup of
> wwan (wwan0)
> Tue Jan 11 18:14:17 2022 user.notice firewall: Reloading firewall due to
> ifupdate of wwan (wwan0)
> Tue Jan 11 18:14:18 2022 daemon.warn odhcpd[1992]: A default route is present
> but there is no public prefix on lan thus we don't announce a default route!
> Tue Jan 11 18:14:19 2022 daemon.info dnsmasq[1582]: read /etc/hosts - 4 addresses
> Tue Jan 11 18:14:19 2022 daemon.info dnsmasq[1582]: read
> /tmp/hosts/dhcp.cfg01411c - 0 addresses
--
Aleksander
https://aleksander.es
More information about the ModemManager-devel
mailing list