Unable to connect to network with new version

prenex · 18 December 2021 06:23

Hi!

I used to be going with plasma mobile (did not try other OSes yet) and despite modem sometimes did turn off, it worked “most of the time”.

I am not on testing and all - just regular pinephone main. However now after latest update modem does not work at all. I see you changed to use modem manager and I also expected it to work better, but it now does not work at all…

I use the phone as daily driver so this is bad for me. Maybe something broke on update when upgrading from the previous networking setup? Or maybe they do not support T-Com in europe with the new one?

This is what journald is saying:

...
Dec 18 05:41:52 plasma-mobile systemd[1]: Starting Hostname Service...
Dec 18 05:41:52 plasma-mobile eg25manager[3212]: Executed power-on/off sequence
Dec 18 05:41:52 plasma-mobile dbus-daemon[3194]: [system] Activating via systemd: service name='org.freedesktop.ModemManager1' unit='dbus-org.freedesktop.ModemManager1.service' requested by ':1.7' (uid=0 pid=3212 comm="/usr/bin/eg25manager ")
Dec 18 05:41:52 plasma-mobile eg25manager[3212]: taking systemd sleep inhibitor
Dec 18 05:41:52 plasma-mobile eg25manager[3212]: oFono vanished from D-Bus
Dec 18 05:41:52 plasma-mobile eg25manager[3212]: inhibitor sleep fd is 20
...

^^ Btw, I uninstalled ofono manually because I thought maybe the two got mixed up. It was me uninstalling ofono and telephony-ofono. Should I put those back now with modem manager and eg25manager? I see now that I copy the messages here that is says oFono got vanished from D-bus. Is that normal?

...
Dec 18 05:41:53 plasma-mobile ModemManager[3373]: <info>  ModemManager (version 1.18.4-1) starting in system bus...
Dec 18 05:41:53 plasma-mobile NetworkManager[3207]: <info>  [1639802513.7209] ovsdb: Could not connect: No such file or directory
Dec 18 05:41:53 plasma-mobile NetworkManager[3207]: <info>  [1639802513.7211] ovsdb: disconnected from ovsdb
Dec 18 05:41:53 plasma-mobile NetworkManager[3207]: <info>  [1639802513.7325] modem-manager: oFono is not available
Dec 18 05:41:53 plasma-mobile NetworkManager[3207]: <info>  [1639802513.7381] manager: startup complete
Dec 18 05:41:54 plasma-mobile dbus-daemon[3194]: [system] Successfully activated service 'org.freedesktop.ModemManager1'
Dec 18 05:41:54 plasma-mobile NetworkManager[3207]: <info>  [1639802514.4988] modem-manager: ModemManager not available
Dec 18 05:41:54 plasma-mobile systemd[1]: Started Modem Manager.
Dec 18 05:41:54 plasma-mobile systemd[1]: Reached target Multi-User System.
Dec 18 05:41:54 plasma-mobile systemd[1]: Reached target Graphical Interface.
Dec 18 05:41:54 plasma-mobile eg25manager[3212]: ModemManager appeared on D-Bus
Dec 18 05:41:54 plasma-mobile systemd[1]: Starting Hide bootsplash after starting the system...
Dec 18 05:41:54 plasma-mobile NetworkManager[3207]: <info>  [1639802514.6862] modem-manager: ModemManager now available
Dec 18 05:41:54 plasma-mobile systemd[1]: systemd-rfkill.service: Deactivated successfully.
Dec 18 05:41:57 plasma-mobile ModemManager[3373]: <info>  [base-manager] couldn't check support for device '/sys/devices/platform/soc/1c10000.mmc/mmc_host/mmc1/mmc1:0001/mmc1:0001:1': not supported by any plugin
...

Then:

...
Dec 18 05:42:02 plasma-mobile systemd[3436]: Started D-Bus User Message Bus.
Dec 18 05:42:02 plasma-mobile eg25manager[3212]: Response: [RDY]
Dec 18 05:42:02 plasma-mobile eg25manager[3212]: taking systemd sleep inhibitor (blocking)
Dec 18 05:42:02 plasma-mobile eg25manager[3212]: inhibitor block fd is 21
Dec 18 05:42:02 plasma-mobile eg25manager[3212]: Response: [+CFUN: 1]
Dec 18 05:42:02 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:42:02 plasma-mobile eg25manager[3212]: Response: [+CPIN: SIM PIN]
Dec 18 05:42:02 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
...

^^It looks like it went forward and asked for pin as needed (the window for pin came up too at this point and I enter pin code [The GOOD one])

We seem to progress good (I have very limited understanding what is to happen though):

Dec 18 05:42:04 plasma-mobile kernel: usb 2-1: new high-speed USB device number 2 using ehci-platform
Dec 18 05:42:04 plasma-mobile systemd[1]: bootsplash-hide-when-booted.service: Deactivated successfully.
Dec 18 05:42:04 plasma-mobile systemd[1]: Finished Hide bootsplash after starting the system.
Dec 18 05:42:04 plasma-mobile systemd[1]: Startup finished in 4.972s (kernel) + 22.370s (userspace) = 27.343s.
Dec 18 05:42:04 plasma-mobile mtp-probe[3510]: checking bus 2, device 2: "/sys/devices/platform/soc/1c1b000.usb/usb2/2-1"
Dec 18 05:42:04 plasma-mobile mtp-probe[3510]: bus: 2, device: 2 was not an MTP device
Dec 18 05:42:06 plasma-mobile kernel: usbcore: registered new interface driver cdc_wdm
Dec 18 05:42:06 plasma-mobile kernel: usbcore: registered new interface driver option
Dec 18 05:42:06 plasma-mobile kernel: usbserial: USB Serial support registered for GSM modem (1-port)
Dec 18 05:42:06 plasma-mobile kernel: option 2-1:1.0: GSM modem (1-port) converter detected
Dec 18 05:42:06 plasma-mobile kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB0
Dec 18 05:42:06 plasma-mobile kernel: option 2-1:1.1: GSM modem (1-port) converter detected
Dec 18 05:42:06 plasma-mobile kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB1
Dec 18 05:42:06 plasma-mobile kernel: option 2-1:1.2: GSM modem (1-port) converter detected
Dec 18 05:42:06 plasma-mobile kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB2
Dec 18 05:42:06 plasma-mobile kernel: qmi_wwan 2-1:1.4: cdc-wdm0: USB WDM device
Dec 18 05:42:06 plasma-mobile kernel: qmi_wwan 2-1:1.4 wwan0: register 'qmi_wwan' at usb-1c1b000.usb-1, WWAN/QMI device, 86:5f:f6:3e:c8:e0
Dec 18 05:42:06 plasma-mobile kernel: option 2-1:1.3: GSM modem (1-port) converter detected
Dec 18 05:42:06 plasma-mobile kernel: usbcore: registered new interface driver qmi_wwan
Dec 18 05:42:06 plasma-mobile kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB3
Dec 18 05:42:06 plasma-mobile mtp-probe[3592]: checking bus 2, device 2: "/sys/devices/platform/soc/1c1b000.usb/usb2/2-1"
Dec 18 05:42:06 plasma-mobile mtp-probe[3592]: bus: 2, device: 2 was not an MTP device
Dec 18 05:42:06 plasma-mobile systemd-udevd[2835]: Using default interface naming scheme 'v249'.
Dec 18 05:42:06 plasma-mobile manjaro:modem-setup[3618]: Modem already configured
Dec 18 05:42:06 plasma-mobile systemd[1]: pinephone-modem-scripts.pinephone-modem-setup.service: Deactivated successfully.
Dec 18 05:42:06 plasma-mobile systemd[1]: pinephone-modem-scripts.pinephone-modem-setup.service: Consumed 1.006s CPU time.
Dec 18 05:42:08 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
Dec 18 05:42:08 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] created endpoint
Dec 18 05:42:08 plasma-mobile ModemManager[3373]: cannot connect to proxy: Could not connect: Connection refused
Dec 18 05:42:08 plasma-mobile ModemManager[3373]: spawning new qmi-proxy (try 1)...
Dec 18 05:42:08 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Checking version info (45 retries)...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] QMI Device supports 31 services:
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    ctl (1.5)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    wds (1.67)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    dms (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    nas (1.25)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    qos (1.12)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    wms (1.10)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    auth (1.3)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    at (1.2)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    voice (2.1)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    cat2 (2.24)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    uim (1.46)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    pbm (1.4)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    test (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    loc (2.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    sar (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    ims (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    csd (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    ts (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    tmd (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    wda (1.16)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    csvt (1.1)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    imsp (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    imsa (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    coex (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    pdc (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    rfrpe (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    dsd (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x2d] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x30] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x32] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x36] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: <info>  [device /sys/devices/platform/soc/1c1b000.usb/usb2/2-1] creating modem with plugin 'quectel' and '6' ports
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: <info>  [base-manager] modem for device '/sys/devices/platform/soc/1c1b000.usb/usb2/2-1' successfully created
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] created endpoint
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Checking version info (45 retries)...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] QMI Device supports 31 services:
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    ctl (1.5)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    wds (1.67)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    dms (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    nas (1.25)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    qos (1.12)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    wms (1.10)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    auth (1.3)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    at (1.2)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    voice (2.1)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    cat2 (2.24)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    uim (1.46)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    pbm (1.4)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    test (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    loc (2.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    sar (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    ims (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    csd (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    ts (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    tmd (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    wda (1.16)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    csvt (1.1)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    imsp (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    imsa (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    coex (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    pdc (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    rfrpe (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    dsd (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x2d] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x30] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x32] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0]    unknown [0x36] (1.0)
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'wda' (version 1.16) client with ID '1'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'wda' client with flags 'release-cid'...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'wda' client with ID '1'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'dms' (version 1.0) client with ID '1'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'nas' (version 1.25) client with ID '3'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'wds' (version 1.67) client with ID '17'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'wms' (version 1.10) client with ID '1'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'uim' (version 1.46) client with ID '2'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'loc' (version 2.0) client with ID '1'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'pdc' (version 1.0) client with ID '1'
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Allocating new client ID...
Dec 18 05:42:09 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Registered 'voice' (version 2.1) client with ID '3'

Then there is surely some issue I think:

Dec 18 05:42:11 plasma-mobile kernel: ps: disabling
Dec 18 05:42:11 plasma-mobile kernel: dc1sw: disabling
Dec 18 05:42:11 plasma-mobile kernel: avdd-csi: disabling
Dec 18 05:42:11 plasma-mobile kernel: vcc-1v2-hsic: disabling
Dec 18 05:42:11 plasma-mobile kernel: usb-5v: disabling
Dec 18 05:42:11 plasma-mobile ModemManager[3373]: <warn>  [modem0] couldn't query SIM slots: QMI protocol error (94): 'NotSupported'
Dec 18 05:42:11 plasma-mobile ModemManager[3373]: <info>  [modem0] state changed (unknown -> locked)
Dec 18 05:42:11 plasma-mobile ModemManager[3373]: <warn>  [modem0/sim0] couldn't load IMSI: Couldn't read data from UIM: QMI protocol error (82): 'AccessDenied'
Dec 18 05:42:11 plasma-mobile ModemManager[3373]: <warn>  [modem0/sim0] couldn't load operator identifier: Couldn't get home network: QMI protocol error (37): 'UimUninitialized'
Dec 18 05:42:11 plasma-mobile ModemManager[3373]: <warn>  [modem0/sim0] couldn't load operator name: Couldn't get home network: QMI protocol error (37): 'UimUninitialized'
Dec 18 05:42:12 plasma-mobile ModemManager[3373]: <warn>  [modem0/sim0] couldn't load list of preferred networks: Couldn't get preferred networks: QMI protocol error (37): 'UimUninitialized'
Dec 18 05:42:12 plasma-mobile ModemManager[3373]: <warn>  [modem0] couldn't load list of own numbers: Couldn't get MSISDN: QMI protocol error (37): 'UimUninitialized'
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: ModemManager object `/org/freedesktop/ModemManager1/Modem/0' added
Dec 18 05:42:12 plasma-mobile NetworkManager[3207]: <info>  [1639802532.2846] device (cdc-wdm0): state change: unmanaged -> unavailable (reason 'none', sys-iface-state: 'external')
Dec 18 05:42:12 plasma-mobile NetworkManager[3207]: <info>  [1639802532.2873] device (cdc-wdm0): modem state 'locked'
Dec 18 05:42:12 plasma-mobile NetworkManager[3207]: <info>  [1639802532.2903] manager: (cdc-wdm0): new Broadband device (/org/freedesktop/NetworkManager/Devices/3)
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem' found on object `/org/freedesktop/ModemManager1/Modem/0'

But then as far as I can tell… a lot of AT-commands are coming with “OK” now:

Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Adding new modem `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Executed soft wake sequence
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGMR
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Simple' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [EG25GGBR07A08M2G_01.002.01.002\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QDAI?
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QDAI: 1,1,0,1,0,0,1,1\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="risignaltype"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "risignaltype","physical"\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="ims"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "ims",1,0\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="apready"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "apready",1,0,500\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="urc/ri/ring"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "urc/ri/ring","pulse",120,1000,5000,"off",1\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="urc/ri/smsincoming"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "urc/ri/smsincoming","pulse",120,1\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="urc/ri/other"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "urc/ri/other","off",1,1\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="urc/delay"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "urc/delay",0\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="urc/cache"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "urc/cache",0\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="urc/ri/pin"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QCFG: "urc/ri/pin",uart_ri\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QURCCFG="urcport"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QURCCFG: "urcport","all"\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QSCLK=1
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [OK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSXTRA?
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QGPSXTRA: 1\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="gnssconfig"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "gnssconfig",4\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="odpcontrol"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "odpcontrol",0\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="dpoenable"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "dpoenable",1\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="gpsnmeatype"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "gpsnmeatype",31\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="glonassnmeatype"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "glonassnmeatype",7\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="galileonmeatype"
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "galileonmeatype",0\r\n\r\nOK]
Dec 18 05:42:12 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="beidounmeatype"
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "beidounmeatype",0\r\n\r\nOK]
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSCFG="autogps"
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Response: [+QGPSCFG: "autogps",0\r\n\r\nOK]
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="fast/poweroff"
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Response: [+QCFG: "fast/poweroff",0\r\n\r\nOK]
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="sleepind/level"
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Response: [+QCFG: "sleepind/level",0\r\n\r\nOK]
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="wakeupin/level"
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Response: [+QCFG: "wakeupin/level",0,0\r\n\r\nOK]
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="ApRstLevel"
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Response: [+QCFG: "ApRstLevel",1\r\n\r\n\r\nOK]
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QCFG="ModemRstLevel"
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Response: [+QCFG: "ModemRstLevel",1\r\n\r\nOK]
Dec 18 05:42:13 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
...

Maybe it is just a capabilities list? I am not sure…
After these KDE starts up (so maybe only now comes up the pin GUI…)

Dec 18 05:42:20 plasma-mobile upowerd[3718]: did not recognise USB path /sys/devices/platform/soc/1f03400.rsb/sunxi-rsb-3a3/axp20x-usb-power-supply/power_supply/axp20x-usb, please report
Dec 18 05:42:20 plasma-mobile dbus-daemon[3194]: [system] Successfully activated service 'org.freedesktop.UPower'
Dec 18 05:42:20 plasma-mobile systemd[1]: Started Daemon for power management.
Dec 18 05:42:21 plasma-mobile eg25manager[3212]: Rescheduling upload since Location interface is not available, in 30s

^^Maybe last message is just normal, dunno.

But these look bad again - I think surely:

Dec 18 05:42:25 plasma-mobile modem-daemon[3779]: found new device: "/org/freedesktop/ModemManager1/Modem/0"
Dec 18 05:42:25 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::Modem3gppUssd, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:25 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::Modem3gppUssd, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:25 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::Modem3gppUssd, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:25 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::ModemMessaging, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:25 plasma-mobile kde-telephony-daemon[3781]: void DialerManager::setDialerUtils(DialerUtils*)
Dec 18 05:42:25 plasma-mobile kde-telephony-daemon[3781]: void NotificationManager::setCallUtils(org::kde::telephony::CallUtils*)
Dec 18 05:42:25 plasma-mobile modem-daemon[3779]: current database revision 2
Dec 18 05:42:25 plasma-mobile kde-telephony-daemon[3781]: Found card port  "[Out] Headphones"
Dec 18 05:42:25 plasma-mobile spacebar-daemon[3780]: current database revision 4
Dec 18 05:42:25 plasma-mobile kde-telephony-daemon[3781]: Found card port  "[Out] Earpiece"
Dec 18 05:42:25 plasma-mobile kde-telephony-daemon[3781]: Found card port  "[Out] Speaker"
Dec 18 05:42:25 plasma-mobile kde-telephony-daemon[3781]: Found card port  "[In] Headset"
Dec 18 05:42:25 plasma-mobile kde-telephony-daemon[3781]: Found card port  "[In] Mic"

Any idea what the nullptr parameter should have been?

Okay - now is when finally I entered the SIM code - as I see from the logs:

Dec 18 05:42:37 plasma-mobile kded5[3660]: plasma-nm: Sending unlock code
Dec 18 05:42:38 plasma-mobile eg25manager[3212]: Response: [+CPIN: READY\r\n\r\n+QUSIM: 1]
Dec 18 05:42:38 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:42:38 plasma-mobile eg25manager[3212]: Response: [+QIND: SMS DONE]
Dec 18 05:42:38 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:42:39 plasma-mobile eg25manager[3212]: Response: [+QIND: PB DONE]
Dec 18 05:42:39 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:42:40 plasma-mobile ModemManager[3373]: <info>  [modem0] state changed (locked -> initializing)
Dec 18 05:42:40 plasma-mobile kded5[3660]: plasma-nm: unlockRequired ==  3
Dec 18 05:42:40 plasma-mobile ModemManager[3373]: <warn>  [modem0] couldn't query SIM slots: QMI protocol error (94): 'NotSupported'
Dec 18 05:42:40 plasma-mobile ModemManager[3373]: <warn>  [modem0] couldn't load list of own numbers: Couldn't get MSISDN: QMI protocol error (16): 'NotProvisioned'
Dec 18 05:42:40 plasma-mobile ModemManager[3373]: <warn>  [modem0] couldn't load UE mode of operation for EPS: Couldn't parse UE mode of operation: '+CPIN: READY
                                                  
                                                  
                                                  +QIND: SMS DONE
                                                  
                                                  +QIND: PB DONE
                                                  
                                                  +CEMODE: 2' (value 0)
Dec 18 05:42:40 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' removed on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:40 plasma-mobile modem-daemon[3779]: found new device: "/org/freedesktop/ModemManager1/Modem/0"
Dec 18 05:42:40 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:40 plasma-mobile kded5[3660]: plasma-nm: unlockRequired ==  3
Dec 18 05:42:40 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::Modem3gppUssd, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:40 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::Modem3gppUssd, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:40 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::Modem3gppUssd, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:40 plasma-mobile modem-daemon[3779]: QObject::connect(ModemManager::ModemMessaging, ModemManagerController): invalid nullptr parameter
Dec 18 05:42:40 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.ProfileManager' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:40 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Modem3gpp.Ussd' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Location' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: Adding new modem with location capabilities `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Messaging' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Time' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile ModemManager[3373]: <info>  [modem0] state changed (initializing -> disabled)
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Signal' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' removed on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Voice' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' removed on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile eg25manager[3212]: ModemManager interface `org.freedesktop.ModemManager1.Modem.Firmware' found on object `/org/freedesktop/ModemManager1/Modem/0'
Dec 18 05:42:41 plasma-mobile NetworkManager[3207]: <info>  [1639802561.0895] modem["cdc-wdm0"]: modem state changed, 'locked' --> 'disabled' (reason: unknown)
Dec 18 05:42:48 plasma-mobile dbus-daemon[3194]: [system] Activating via systemd: service name='org.freedesktop.locale1' unit='dbus-org.freedesktop.locale1.service' requested by ':1.55' (uid=1002 pid=3789 comm="/usr/lib/DiscoverNotifier ")

^^ As you see… I get some warnings right after I enter the code…

Then:

Dec 18 05:42:51 plasma-mobile eg25manager[3212]: GNSS assistance upload started...
Dec 18 05:42:51 plasma-mobile eg25manager[3212]: GNSS assistance upload step (1/9): fetching assistance data
Dec 18 05:42:51 plasma-mobile eg25manager[3212]: Unable to fetch GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin: Could not resolve host: xtrapath4.izatcloud.net

^^Data is not turned on by default so likely this is fine…

Dec 18 05:44:03 plasma-mobile eg25manager[3212]: Modem is up for 120 seconds and fully ready
Dec 18 05:44:03 plasma-mobile eg25manager[3212]: dropping systemd sleep block inhibitor
Dec 18 05:44:18 plasma-mobile dbus-daemon[3194]: [system] Activating service name='org.kde.powerdevil.backlighthelper' requested by ':1.34' (uid=1002 pid=3723 comm="/usr/lib/org_kde_powerdevil ") (using servicehelper)

^^The “fully ready” and “up” shound good here, but no idea

Then some location relateed thing finally can heappem as I gained wifi carrier:

Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Response: [+QGPSURC: "xtradataexpire",0,"2021/12/17,22:00:00"]
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: GNSS assistance upload started...
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: GNSS assistance upload step (1/9): fetching assistance data
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Fetching GNSS assistance data from https://xtrapath4.izatcloud.net/xtra2.bin was successful
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: GNSS assistance upload step (2/9): disabling GNSS engine through ModemManager
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Unable to disable GNSS engine through ModemManager: GDBus.Error:org.freedesktop.ModemManager1.Error.Core.WrongState: Cannot setup location: device not yet enabled
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: GNSS assistance upload step (3/9): disabling GNSS engine through AT+QGPS
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Executed soft wake sequence
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPS?
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Response: [+QGPS: 0\r\n\r\nOK]
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: GNSS assistance upload step (4/9): initiating upload
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Executed soft wake sequence
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QFDEL="RAM:*"
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Response: [OK]
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:52:40 plasma-mobile eg25manager[3212]: Initiate GNSS assistance data upload: "RAM:xtra2.bin",60529,10
Dec 18 05:52:41 plasma-mobile eg25manager[3212]: Executed soft wake sequence
Dec 18 05:52:41 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QFUPL="RAM:xtra2.bin",60529,10
Dec 18 05:52:41 plasma-mobile eg25manager[3212]: Response: [CONNECT]
Dec 18 05:52:41 plasma-mobile eg25manager[3212]: Modem ready for GNSS assistance data upload
Dec 18 05:52:41 plasma-mobile eg25manager[3212]: GNSS assistance upload step (5/9): uploading assistance data
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Successfully uploaded 60529 bytes to the modem
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Response: [+QFUPL: 60529,31ff\r\n\r\nOK]
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: GNSS assistance upload step (6/9): finishing upload
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Setting GNSS assistance UTC clock to: 0,"2021/12/18,04:52:47"
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Setting GNSS assistance file to: "RAM:xtra2.bin"
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Executed soft wake sequence
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSXTRATIME=0,"2021/12/18,04:52:47"
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Response: [OK]
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Successfully sent command: AT+QGPSXTRADATA="RAM:xtra2.bin"
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Response: [OK]
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: GNSS assistance data upload finished
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: GNSS assistance upload step (7/9): re-enabling GNSS through ModemManager
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: Unable to enable GNSS engine through ModemManager: GDBus.Error:org.freedesktop.ModemManager1.Error.Core.WrongState: Cannot setup location: device not yet enabled
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: GNSS assistance upload step (8/9): re-enabling GNSS through AT+QGPS
Dec 18 05:52:47 plasma-mobile eg25manager[3212]: GNSS assistance upload step (9/9): finished

Then more stuff - not sure if good or bad:

Dec 18 05:54:26 plasma-mobile ModemManager[3373]: <info>  [sleep-monitor] system is about to suspend
Dec 18 05:54:26 plasma-mobile kded5[3660]: bluedevil: About to suspend
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'voice' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile eg25manager[3212]: system is about to suspend
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'voice' client with ID '3'
Dec 18 05:54:26 plasma-mobile eg25manager[3212]: Executed soft sleep sequence
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'pdc' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile eg25manager[3212]: Executed suspend sequence
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'pdc' client with ID '1'
Dec 18 05:54:26 plasma-mobile eg25manager[3212]: suspend sequence is over, drop inhibitor
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'loc' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile eg25manager[3212]: dropping systemd sleep delay inhibitor
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'loc' client with ID '1'
Dec 18 05:54:26 plasma-mobile NetworkManager[3207]: <info>  [1639803266.5191] manager: sleep: sleep requested (sleeping: no  enabled: yes)
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'uim' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile NetworkManager[3207]: <info>  [1639803266.5203] device (cdc-wdm0): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'external')
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'uim' client with ID '2'
Dec 18 05:54:26 plasma-mobile NetworkManager[3207]: <info>  [1639803266.5555] device (p2p-dev-wlan0): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'wms' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile plasmashell[3700]: QObject::connect(ModemManager::Modem, SignalIndicator): invalid nullptr parameter
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'wms' client with ID '1'
Dec 18 05:54:26 plasma-mobile plasmashell[3700]: QObject::connect(ModemManager::Modem3gpp, SignalIndicator): invalid nullptr parameter
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile plasmashell[3700]: QObject::connect(ModemManager::Modem, SignalIndicator): invalid nullptr parameter
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'wds' client with ID '17'
Dec 18 05:54:26 plasma-mobile NetworkManager[3207]: <info>  [1639803266.5796] manager: NetworkManager state is now ASLEEP
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'nas' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile modem-daemon[3779]: found new device: "/org/freedesktop/ModemManager1/Modem/0"
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'nas' client with ID '3'
Dec 18 05:54:26 plasma-mobile modem-daemon[3779]: Skipping 3GPP-related connections
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Releasing 'dms' client with flags 'release-cid'...
Dec 18 05:54:26 plasma-mobile modem-daemon[3779]: Skipping device without voice interface
Dec 18 05:54:26 plasma-mobile ModemManager[3373]: [/dev/cdc-wdm0] Unregistered 'dms' client with ID '1'
Dec 18 05:54:26 plasma-mobile NetworkManager[3207]: <info>  [1639803266.5898] device (wlan0): state change: activated -> deactivating (reason 'sleeping', sys-iface-state: 'managed')
Dec 18 05:54:26 plasma-mobile eg25manager[3212]: ModemManager object `/org/freedesktop/ModemManager1/Modem/0' removed
Dec 18 05:54:26 plasma-mobile kded5[3660]: plasma-nm: Unhandled active connection state change:  3
Dec 18 05:54:26 plasma-mobile dbus-daemon[3194]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.8' (uid=0 pid=3207 comm="/usr/bin/NetworkManager --no-daemon ")
Dec 18 05:54:26 plasma-mobile systemd[1]: Starting Network Manager Script Dispatcher Service...
Dec 18 05:54:26 plasma-mobile dbus-daemon[3194]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 18 05:54:26 plasma-mobile systemd[1]: Started Network Manager Script Dispatcher Service.
Dec 18 05:54:26 plasma-mobile systemd-networkd[2834]: wlan0: Lost carrier
Dec 18 05:54:26 plasma-mobile wpa_supplicant[4021]: wlan0: CTRL-EVENT-DISCONNECTED bssid=b8:66:85:fd:b1:e3 reason=3 locally_generated=1
Dec 18 05:54:26 plasma-mobile systemd-timesyncd[3166]: No network connectivity, watching for changes.
Dec 18 05:54:27 plasma-mobile wpa_supplicant[4021]: wlan0: CTRL-EVENT-REGDOM-CHANGE init=CORE type=WORLD
Dec 18 05:54:27 plasma-mobile NetworkManager[3207]: <info>  [1639803267.0777] device (wlan0): supplicant interface state: completed -> disconnected
Dec 18 05:54:27 plasma-mobile NetworkManager[3207]: <info>  [1639803267.0803] device (wlan0): state change: deactivating -> disconnected (reason 'sleeping', sys-iface-state: 'managed')
Dec 18 05:54:27 plasma-mobile NetworkManager[3207]: <info>  [1639803267.1331] dhcp4 (wlan0): canceled DHCP transaction
Dec 18 05:54:27 plasma-mobile NetworkManager[3207]: <info>  [1639803267.1333] dhcp4 (wlan0): state changed bound -> done
Dec 18 05:54:27 plasma-mobile NetworkManager[3207]: <info>  [1639803267.1352] dhcp6 (wlan0): canceled DHCP transaction
Dec 18 05:54:27 plasma-mobile NetworkManager[3207]: <info>  [1639803267.1354] dhcp6 (wlan0): state changed bound -> done
Dec 18 05:54:27 plasma-mobile NetworkManager[3207]: <info>  [1639803267.1652] device (wlan0): state change: disconnected -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Dec 18 05:54:27 plasma-mobile systemd-networkd[2834]: wlan0: Link DOWN
Dec 18 05:54:27 plasma-mobile kded5[3660]: plasma-nm: Not emitting connection deactivated notification as we're about to suspend
Dec 18 05:54:27 plasma-mobile wpa_supplicant[4021]: nl80211: deinit ifname=wlan0 disabled_11b_rates=0
Dec 18 05:54:28 plasma-mobile PackageKit[3799]: get-updates transaction /6_ebdecccc from uid 1002 finished with success after 1545ms
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0xd aborted, but message is not abortable
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0xe aborted, but message is not abortable
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0xf aborted, but message is not abortable
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0x10 aborted, but message is not abortable
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0x11 aborted, but message is not abortable
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0x12 aborted, but message is not abortable
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0x13 aborted, but message is not abortable
Dec 18 05:54:29 plasma-mobile ModemManager[3373]: transaction 0x14 aborted, but message is not abortable
Dec 18 05:54:30 plasma-mobile systemd[1]: Reached target Sleep.
Dec 18 05:54:30 plasma-mobile systemd[1]: Starting System Suspend...

It kind of look “normal-ish” but when I tried to call I never could. Also I guess that is because the “nullpointeres” as seen above too…

Then again something “ofono” related - so should I reinstall it?

Dec 18 05:54:30 plasma-mobile [4136]: /usr/lib/systemd/system-sleep/ofono-fast-dormancy.sh failed with exit status 1.
Dec 18 05:54:30 plasma-mobile systemd-sleep[4134]: Entering sleep state 'suspend'...
Dec 18 05:54:30 plasma-mobile kernel: PM: suspend entry (deep)

Then I come out of deep sleep and pretty muich all the above happens again. The biggest warning I think is that one where it says sim slots cannot be queried and cannot load list of own numbers errors, but I also see this here:

Dec 18 05:55:20 plasma-mobile ModemManager[3373]: <warn>  [modem1] couldn't reset QMI port 'cdc-wdm0' with data interface 'wwan0': netlink operation failed: Netlink message with transaction 1 failed

^^and this comes a bit earlier than the other two warnings. Any ideas?

prenex · 18 December 2021 06:35

Ok I figured I have my company tablet around and it has a sim-card so I called my phone and to my amazement I am sure it was callable.

I also saw that the phone “did something” - the screen got to a high brightness for a moment and it made the sound as if you charge it - I saw that happening before with previous releases when it was on charger and someone call me: first it always sounds like as if I unplug / plugin the charger repeatedly, then the call sound.

So I am sure the call got to the modem hardware in some way and even there was some interaction - but the screen to pick up the call did not come up and there was not any regular ringtone neither.

I guess either there is something “stateful” going on and the states of the modem and the linux side differ for some reason OR maybe things do work on the lower level actually, but on the UI there is huge confusion (maybe because migration to modem-manager was not flawless in my case and some stuff got stuck in???)

I hope this latter helps.

prenex · 18 December 2021 16:21

Update:

I successfully made a call with manually doing the “AT” commands in atinout…

I also collected debug logs of NetworkManager and ModemManager too, but then it looks like it is some high level issue by higher level things interacting with these badly?

How to upload files here - like log files?

andreas85 · 19 December 2021 17:55

You can include logs into your post by using 3 backticks, then a newline, then your log, then a newlin and again 3 backtticks 3x(`)

prenex · 20 December 2021 18:33

Files are too big for that and seriously the forum engine was slow while I was copy-pasting in the last messages already…

So I put the files here - I changed the sensitive datas (like phone numbers):
https://ballmerpeak.web.elte.hu/nmdebug.txt

https://ballmerpeak.web.elte.hu/mmdebug.txt

^^I was being called and I made the call with AT commands are also visible in the log. I can again say the phone went up from sleep on someone calling me, but I got no other indication (so it did not ring or show anything that I can pick up).

I guess with AT commands I could pick up. Talking when I did my call went good too, so I guess the modem works, the driver I guess works but some upper layer has problems.

What is the architecture exactly? I am not familiar with how things are put together or what pieces could go wrong.

I am happy to answer more questions if there is any, but is there any idea what might be wrong?

prenex · 25 December 2021 01:03

I also have further updates (alongside above logs)!!!

TL;DR: go for (***) for possible workaround / fix direction…

** Bad direction / trying all kind of stuff first:**

I tried:

mmcli -L # tells modennum
mmcli -m modemnum # told me locked: sim-pin2 (but not 1!)
# also above told me that state is "disabled"

mmcli --simple-connect="pin=1234,apn=internet"
# above told me "Cancelled"

However after the above told operation cancelled (of course pin code was mine) the GUI came up again to enter the pin code… Also after a new “'mmcli -L” I found out that the modem number changed and got incremented. I guess it did restart?

Also worth to mention: modem number always gets incremented in the “-L” (list) operation of mmcli whenever I woke up the phone after a deep sleep!!! I know it only happens on deep sleep as when I just use the power button for a moment, then turn the screen back again I still have the same modem.

Then I realized that “why don’t I just enable the modem if that is what the status says? It says it is disabled!” and I did the following:

(***) Possible fix direction / workaround direction:

mmcli -L # to get current moden number (I guess I can sed-script it out too)
mmcli -m 20 -e  # where instead of "20" you enter current modem-number

^^After this, all of a sudden I got the sms that dad have sent me in the morning! Then I figured I tell someone to call me and it worked (properly, with GUI) and I could pick up the phone!!! Hurray! I did not test mobile net, but maybe even that can be turned on now!

Caveat (a big one):

I had a bad feeling so I waited enough time so that the pinephone go into deep sleep mode. Then I unlocked the phone and I saw the GUI shows connection percentage not as it should be showing (no date near it). I went to “mmcli -L” and found that the modem number got incremented and it is again in a disabled state…

So now it does not work - unless I manually do the enablement again… This however is really bad… worse than what you might think, because I think (did not try yet, but I am pretty sure) that in case someone calls me while the phone is in deep sleep, the pinephone gets up from the sleep and it likely runs some program or scripts but that fails to enable the modem… then it will not ring, but the caller will hear it as if it rings out for me…

So this means I am still not callable - unless I unlocked my phone right now and enabled modem and you call me that very minute…

Question:

Please someone tell me: is there a place where I can put a script after the OS / pinephone gets up from a deep sleep and always run it there? If that is possible, then likely I can add a little script that sed-out the modem number and enables the modem and I become callable… so I will have a proper workaround…

Also I would be happy if someone can tell what the “real” and “normal” solution would be to the issue…

What I know:

Modem works (I was able to both call with AT commands, but now also from GUI after enabling the phone)
Modem-manager, GUI integrations “mostly” working: After enabling the modem with “-m 20 -e” it worked from the GUI (albeit I keep getting the last sms from my father from the morning and some apps now show as if I got it three times already - so maybe there are some minor stuff with higher integration too)
The pin code was in the modem from the GUI - so that step did succeed always for me as far as I can tell - some later steps failed…
The modem was disabled… not sure what causes this - maybe a missed step or a failure / unexpected something that code does not expects prohibit the control flow reaching the code that would call enable while the error is pretty much not a big thing???

Should I write about my issues here or should I write on pinephone forums? I currently use plasma mobile on the pinephone. The firmware for the modem is I guess the stock one (the mmcli -m 20 command told me exact version and it seemed like one made by original creator of modem, not some open stuff).

Even if you cannot help my case I hope this already might help someone else. But it would really help if someone would told me what happens when the pinephone comes up from a deep sleep - what does run then? How can I add things to that moment?

PS.: I did not need to run the mmcli commands as root… regular user was enough. Just mentioning.

prenex · 25 December 2021 01:28

Okay… I have “some guesses” that I can run scripts coming from suspend:

https://forum.pine64.org/showthread.php?tid=13145

^^I will test that… I am not sure if that is outdated or not, but to me it seems usable or nearly usable because I know we do systemd and it is pretty much just systemd configing… also even if it does not work, it will be only some renames or such maybe…

So at least there is hope for a clunky dirty workaround in my peasant-ways…

Also maybe I can look at what the hell is happening “normally” when I come from suspend by looking up systemd stuff that seem related to it maybe… Will see if that helps analysing the issue further.