ANN: ModemManager 1.18.4 released / Avoiding PPP
Peter Naulls
peter at chocky.org
Tue Jan 11 18:25:39 UTC 2022
> 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.
Full log below, but perhaps here's some salient pieces:
Tue Jan 11 18:09:02 2022 daemon.warn [2757]: <warn> [1641924542.939644]
[modem0/sim0] couldn't load list of preferred networks: Operation not allowed
Tue Jan 11 18:09:05 2022 daemon.info [2757]: <info> [1641924545.174757]
[modem0] state changed (unknown -> disabled)
At the end of the log, you can see PPP failures which is of course where
I've disabled stuff (not enough, apparently, but it's too late at that
point anyway. But then it'll restart, and eventually reconnect. Anyway.
Tue Jan 11 18:08:46 2022 user.notice ModemManager: hotplug: add network
interface ip6tnl0: event processed
Tue Jan 11 18:08:46 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:47 2022 user.notice ModemManager: hotplug: add network
interface gre0: event processed
Tue Jan 11 18:08:47 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: bonding
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: 8021ad
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: 8021q
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: macvlan
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: veth
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: bridge
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: Network device
Tue Jan 11 18:08:47 2022 user.notice : Added device handler type: tunnel
Tue Jan 11 18:08:47 2022 user.notice ModemManager: hotplug: add network
interface gretap0: event processed
Tue Jan 11 18:08:47 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:48 2022 user.notice ModemManager: hotplug: add network
interface erspan0: event processed
Tue Jan 11 18:08:48 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.873270] mtk_soc_eth
1e100000.ethernet: PPE started
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.893726] br-lan: port 1(eth0.1)
entered blocking state
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.904624] br-lan: port 1(eth0.1)
entered disabled state
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.916624] device eth0.1 entered
promiscuous mode
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.926267] device eth0 entered
promiscuous mode
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.944946] br-lan: port 1(eth0.1)
entered blocking state
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.955838] br-lan: port 1(eth0.1)
entered forwarding state
Tue Jan 11 18:08:49 2022 kern.info kernel: [ 30.967643] IPv6:
ADDRCONF(NETDEV_UP): br-lan: link is not ready
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'lan' is enabled
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'lan' is setting up now
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'lan' is now up
Tue Jan 11 18:08:49 2022 daemon.notice netifd: bridge 'br-lan' link is up
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'lan' has link connectivity
Tue Jan 11 18:08:49 2022 daemon.notice netifd: VLAN 'eth0.1' link is up
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'loopback' is enabled
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'loopback' is setting
up now
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'loopback' is now up
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'wwan' is setting up now
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Network device 'eth0' link is up
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Network device 'lo' link is up
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'loopback' has link
connectivity
Tue Jan 11 18:08:49 2022 user.notice ModemManager: hotplug: add network
interface ip6gre0: event processed
Tue Jan 11 18:08:49 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:49 2022 daemon.notice netifd: wwan (2500): error: couldn't get
bus: Could not connect: No such file or directory
Tue Jan 11 18:08:49 2022 daemon.notice netifd: wwan (2500): Device not managed
by ModemManager
Tue Jan 11 18:08:49 2022 daemon.notice netifd: wwan (2564): stopping network
Tue Jan 11 18:08:49 2022 user.notice firewall: Reloading firewall due to ifup of
lan (br-lan)
Tue Jan 11 18:08:49 2022 daemon.notice netifd: wwan (2564): error: couldn't get
bus: Could not connect: No such file or directory
Tue Jan 11 18:08:49 2022 daemon.notice netifd: wwan (2564): couldn't load bearer
path
Tue Jan 11 18:08:49 2022 daemon.notice netifd: Interface 'wwan' is now down
Tue Jan 11 18:08:50 2022 kern.info kernel: [ 31.882612] IPv6:
ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
Tue Jan 11 18:08:50 2022 user.notice ModemManager: hotplug: add network
interface wwan0: event processed
Tue Jan 11 18:08:50 2022 user.notice ModemManager: hotplug: interface 'wwan' is
set to configure device '/sys/devices/platform/1e1c0000.xhci/usb2/2-1'
Tue Jan 11 18:08:50 2022 user.notice ModemManager: hotplug: now waiting for
modem at sysfs path /sys/devices/platform/1e1c0000.xhci/usb2/2-1
Tue Jan 11 18:08:50 2022 user.notice ModemManager: hotplug: add cdc interface
cdc-wdm0: custom event processed
Tue Jan 11 18:08:50 2022 daemon.err procd: failed to open pidfile for writing: :
No such file or directory
Tue Jan 11 18:08:50 2022 daemon.err odhcpd[2159]: Failed to send to
ff02::1%lan at br-lan (Address not available)
Tue Jan 11 18:08:51 2022 user.notice ucitrack: Setting up /etc/config/network
reload dependency on /etc/config/dhcp
Tue Jan 11 18:08:51 2022 user.notice ucitrack: Setting up /etc/config/wireless
reload dependency on /etc/config/network
Tue Jan 11 18:08:51 2022 user.notice ModemManager: hotplug: add serial interface
ttyUSB0: event processed
Tue Jan 11 18:08:51 2022 user.notice ModemManager: hotplug: interface 'wwan' is
set to configure device '/sys/devices/platform/1e1c0000.xhci/usb2/2-1'
Tue Jan 11 18:08:51 2022 user.notice ModemManager: hotplug: now waiting for
modem at sysfs path /sys/devices/platform/1e1c0000.xhci/usb2/2-1
Tue Jan 11 18:08:51 2022 user.notice ucitrack: Setting up /etc/config/firewall
reload dependency on /etc/config/luci-splash
Tue Jan 11 18:08:51 2022 user.notice ucitrack: Setting up /etc/config/firewall
reload dependency on /etc/config/qos
Tue Jan 11 18:08:51 2022 user.notice ucitrack: Setting up /etc/config/firewall
reload dependency on /etc/config/miniupnpd
Tue Jan 11 18:08:51 2022 user.notice ModemManager: hotplug: checking if
ModemManager is available...
Tue Jan 11 18:08:51 2022 user.notice ucitrack: Setting up /etc/config/dhcp
reload dependency on /etc/config/odhcpd
Tue Jan 11 18:08:51 2022 user.notice ModemManager: hotplug: ModemManager not yet
available
Tue Jan 11 18:08:51 2022 daemon.info [2757]: <info> [1641924531.992302]
ModemManager (version 1.18.4) starting in system bus...
Tue Jan 11 18:08:52 2022 user.notice ucitrack: Setting up non-init
/etc/config/fstab reload handler: /sbin/block mount
Tue Jan 11 18:08:52 2022 user.notice ucitrack: Setting up /etc/config/system
reload trigger for non-procd /etc/init.d/led
Tue Jan 11 18:08:52 2022 user.notice ModemManager: hotplug: add serial interface
ttyUSB1: event processed
Tue Jan 11 18:08:52 2022 user.notice ucitrack: Setting up /etc/config/system
reload dependency on /etc/config/luci_statistics
Tue Jan 11 18:08:52 2022 user.notice ucitrack: Setting up /etc/config/system
reload dependency on /etc/config/dhcp
Tue Jan 11 18:08:52 2022 user.notice ModemManager: hotplug: checking if
ModemManager is available...
Tue Jan 11 18:08:53 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=console, subsystem=tty, sysfspath=/sys/devices/virtual/tty/console
Tue Jan 11 18:08:53 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:53 2022 user.notice ModemManager: hotplug: add serial interface
ttyUSB2: event processed
Tue Jan 11 18:08:53 2022 daemon.err insmod: module is already loaded - qmi_wwan
Tue Jan 11 18:08:53 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:08:53 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:53 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:08:53 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:54 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:08:54 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:54 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=ip6tnl0, subsystem=net, sysfspath=/sys/devices/virtual/net/ip6tnl0
Tue Jan 11 18:08:54 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:54 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=gre0, subsystem=net, sysfspath=/sys/devices/virtual/net/gre0
Tue Jan 11 18:08:54 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:54 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=gretap0, subsystem=net, sysfspath=/sys/devices/virtual/net/gretap0
Tue Jan 11 18:08:55 2022 user.notice ModemManager: hotplug: add serial interface
ttyUSB3: event processed
Tue Jan 11 18:08:55 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:55 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=erspan0, subsystem=net, sysfspath=/sys/devices/virtual/net/erspan0
Tue Jan 11 18:08:55 2022 daemon.info [2757]: <info> [1641924535.408371] [device
/sys/devices/platform/1e1c0000.xhci/usb2/2-1] creating modem with plugin
'quectel' and '2' ports
Tue Jan 11 18:08:55 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:55 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=ip6gre0, subsystem=net, sysfspath=/sys/devices/virtual/net/ip6gre0
Tue Jan 11 18:08:55 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:56 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:08:56 2022 daemon.info [2757]: <info> [1641924536.122148]
[base-manager] modem for device '/sys/devices/platform/1e1c0000.xhci/usb2/2-1'
successfully created
Tue Jan 11 18:08:56 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:08:56 2022 daemon.info dnsmasq[4293]: started, version 2.86
cachesize 150
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: DNS service limited to local
subnets
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: compile time options: IPv6
GNU-getopt no-DBus UBus no-i18n no-IDN DHCP no-DHCPv6 no-Lua TFTP no-conntrack
no-ipset no-auth no-cryptohash no-DNSSEC no-ID loop-detect inotify dumpfile
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: UBus support enabled:
connected to system bus
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq-dhcp[4293]: DHCP, IP range
192.168.113.100 -- 192.168.113.249, lease time 12h
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: using only locally-known
addresses for test
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: using only locally-known
addresses for onion
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: using only locally-known
addresses for localhost
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: using only locally-known
addresses for local
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: using only locally-known
addresses for invalid
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: using only locally-known
addresses for bind
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: using only locally-known
addresses for lan
Tue Jan 11 18:08:56 2022 daemon.warn dnsmasq[4293]: no servers found in
/tmp/resolv.conf.d/resolv.conf.auto, will retry
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: read /etc/hosts - 4 addresses
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: read
/tmp/hosts/dhcp.cfg01411c - 1 addresses
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq-dhcp[4293]: read /etc/ethers - 0
addresses
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: read /etc/hosts - 4 addresses
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq[4293]: read
/tmp/hosts/dhcp.cfg01411c - 1 addresses
Tue Jan 11 18:08:56 2022 daemon.info dnsmasq-dhcp[4293]: read /etc/ethers - 0
addresses
Tue Jan 11 18:08:56 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:08:57 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:08:57 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:08:57 2022 user.notice ModemManager: hotplug: cached event found:
action=add, name=ttyUSB3, subsystem=tty,
sysfspath=/sys/devices/platform/1e1c0000.xhci/usb2/2-1/2-1:1.3/ttyUSB3/tty/ttyUSB3
Tue Jan 11 18:08:57 2022 user.notice ModemManager: hotplug: add network
interface br-lan: event processed
Tue Jan 11 18:08:57 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:08:58 2022 daemon.info procd: - init complete -
Tue Jan 11 18:08:58 2022 user.notice ModemManager: hotplug: add network
interface eth0.1: event processed
Tue Jan 11 18:08:58 2022 user.notice ModemManager: hotplug: error: parent device
sysfspath not found
Tue Jan 11 18:09:00 2022 daemon.info [2757]: <info> [1641924540.245461]
[base-manager] couldn't check support for device
'/sys/devices/platform/1e100000.ethernet': not supported by any plugin
Tue Jan 11 18:09:02 2022 daemon.warn [2757]: <warn> [1641924542.428207]
[modem0/sim0] couldn't load operator name: Failed to parse CRSM query result
'+CRSM: 106,130,""'
Tue Jan 11 18:09:02 2022 daemon.warn [2757]: <warn> [1641924542.668036]
[modem0/sim0] couldn't load list of emergency numbers: Failed to parse CRSM
query result '+CRSM: 148,8,""'
Tue Jan 11 18:09:02 2022 daemon.warn [2757]: <warn> [1641924542.939644]
[modem0/sim0] couldn't load list of preferred networks: Operation not allowed
Tue Jan 11 18:09:05 2022 daemon.info [2757]: <info> [1641924545.174757]
[modem0] state changed (unknown -> disabled)
Tue Jan 11 18:09:06 2022 user.notice ModemManager: hotplug: modem exported
successfully at /sys/devices/platform/1e1c0000.xhci/usb2/2-1
Tue Jan 11 18:09:06 2022 user.notice ModemManager: hotplug: setting interface
'wwan' as available
Tue Jan 11 18:09:06 2022 daemon.notice netifd: Interface 'wwan' is setting up now
Tue Jan 11 18:09:06 2022 daemon.notice netifd: wwan (5009): modem available at
/org/freedesktop/ModemManager1/Modem/0
Tue Jan 11 18:09:06 2022 daemon.notice netifd: wwan (5009): starting connection
with apn 'firstnet-broadband'...
Tue Jan 11 18:09:06 2022 daemon.info [2757]: <info> [1641924546.735943]
[modem0] simple connect started...
Tue Jan 11 18:09:06 2022 daemon.info [2757]: <info> [1641924546.736259]
[modem0] simple connect state (3/8): enable
Tue Jan 11 18:09:06 2022 daemon.info [2757]: <info> [1641924546.736777]
[modem0] state changed (disabled -> enabling)
Tue Jan 11 18:09:06 2022 daemon.info [2757]: <info> [1641924546.818012]
[modem0] power state updated: on
Tue Jan 11 18:09:07 2022 user.notice ModemManager: hotplug: modem exported
successfully at /sys/devices/platform/1e1c0000.xhci/usb2/2-1
Tue Jan 11 18:09:07 2022 user.notice ModemManager: hotplug: setting interface
'wwan' as available
Tue Jan 11 18:09:10 2022 daemon.info [2757]: <info> [1641924550.390604]
[modem0] simple connect state (4/8): wait to get fully enabled
Tue Jan 11 18:09:10 2022 daemon.info [2757]: <info> [1641924550.391444]
[modem0] state changed (enabling -> enabled)
Tue Jan 11 18:09:10 2022 daemon.info [2757]: <info> [1641924550.394616]
[modem0] simple connect state (5/8): register
Tue Jan 11 18:09:10 2022 daemon.info [2757]: <info> [1641924550.566647]
[modem0] 3GPP registration state changed (unknown -> registering)
Tue Jan 11 18:09:11 2022 daemon.info [2757]: <info> [1641924551.187335]
[modem0] 3GPP registration state changed (registering -> home)
Tue Jan 11 18:09:11 2022 daemon.info [2757]: <info> [1641924551.187914]
[modem0] state changed (enabled -> registered)
Tue Jan 11 18:09:11 2022 daemon.info [2757]: <info> [1641924551.511168]
[modem0] simple connect state (6/8): bearer
Tue Jan 11 18:09:11 2022 daemon.info [2757]: <info> [1641924551.531261]
[modem0] simple connect state (7/8): connect
Tue Jan 11 18:09:11 2022 daemon.info [2757]: <info> [1641924551.533952]
[modem0] state changed (registered -> connecting)
Tue Jan 11 18:09:12 2022 daemon.info [2757]: <info> [1641924552.154726]
[modem0] state changed (connecting -> connected)
Tue Jan 11 18:09:12 2022 daemon.info [2757]: <info> [1641924552.158055]
[modem0] simple connect state (8/8): all done
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5009): successfully
connected the modem
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5009): signal refresh rate
is not set
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5009): network operator
name: FirstNet
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5009): network operator
MCCMNC: 313100
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5009): registration type: home
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5009): access technology: lte
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5009): signal quality: 100%
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5218): stopping network
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5218): IPv4 connection
teardown required in interface wwan: ppp
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5218): IPv6 connection
teardown required in interface wwan: ppp
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5218): running
disconnection (ppp method)
Tue Jan 11 18:09:12 2022 daemon.notice netifd: wwan (5218): pppd result code not
given
More information about the ModemManager-devel
mailing list