kernel shuts down USB connection to modem on incoming call

DESCRIPTION: During at least two different incoming phone calls, the kernel has shut down the USB connection to the modem, effectively preventing the call from taking place, despite eg25-manager having and implementing the recommended rule for setting power/control to on for the USB to the modem. Logs are provided here for one successful call, and one failed call three minutes later.

INTERPRETATION: The kernel shuts down the modem despite eg25-manager supposedly having control.

POSSIBLE SOLUTION: Find a way to stop the kernel from shutting down the USB during phone calls.

POSSIBLY RELATED:

https://github.com/the-modem-distro/pinephone_modem_sdk/issues/203 - the bug appears identical
https://github.com/the-modem-distro/pinephone_modem_sdk/issues/183

CONTEXT:

PinePhone v1.2 running Mobian/trixie
openqti 0.7.2, ADSP 01.003.01.003
kernels:
- modem: Linux mdm9607 3.18.140 #1 PREEMPT Tue Jun 28 05:34:35 UTC 2022 armv7l GNU/Linux
- phone: Linux mobian 6.1-sunxi64 #1 SMP Tue Aug 1 12:51:53 UTC 2023 aarch64 GNU/Linux

$ dpkg -l |grep -E "linux-image|callaudiod|eg25-manager|modemmanager|systemd"
ii  callaudiod                            0.1.9-1-DEBUG                        arm64        Call audio routing daemon
ii  dbus-user-session                     1.14.8-2                             arm64        simple interprocess messaging system (systemd --user integration)
ii  eg25-manager                          0.4.6-1                              arm64        Manager daemon for the Quectel EG25 modem
ii  libnss-resolve:arm64                  254.1-2                              arm64        nss module to resolve names via systemd-resolved
ii  libnss-systemd:arm64                  254.1-2                              arm64        nss module providing dynamic user and group name resolution
ii  libpam-systemd:arm64                  254.1-2                              arm64        system and service manager - PAM module
ii  libsystemd-dev:arm64                  254.1-2                              arm64        systemd utility library - development files
ii  libsystemd-shared:arm64               254.1-2                              arm64        systemd shared private library
ii  libsystemd0:arm64                     254.1-2                              arm64        systemd utility library
ii  linux-image-5.10-sunxi64              5.10.56+sunxi64-9                    arm64        Linux 5.10 for Allwinner A64 devices
ii  linux-image-6.1-sunxi64               6.1.42+sunxi64-1                     arm64        Linux 6.1 for sunxi64 devices
ii  modemmanager                          1.20.6-2                             arm64        D-Bus service for managing modems
ii  modemmanager-dev:arm64                1.20.6-2                             arm64        D-Bus service for managing modems - development files
ii  systemd                               254.1-2                              arm64        system and service manager
ii  systemd-dev                           254.1-2                              all          systemd development files
ii  systemd-resolved                      254.1-2                              arm64        systemd DNS resolver
ii  systemd-sysv                          254.1-2                              arm64        system and service manager - SysV compatibility symlinks
ii  systemd-zram-generator                1.1.2-3                              arm64        Systemd unit generator for zram devices
ii  wake-mobile                           1.8-1                                arm64        Proof-of-concept alarm app that uses systemd timers to wake up the system

$ dpkg -l |grep -iE "network(| |-)manager|libnm"
ii  gir1.2-nm-1.0:arm64                   1.44.0-1                             arm64        GObject introspection data for the libnm library
ii  libnm-dev:arm64                       1.44.0-1                             arm64        GObject-based client library for NetworkManager (development files)
ii  libnm0:arm64                          1.44.0-1                             arm64        GObject-based client library for NetworkManager
ii  libnma-common                         1.10.6-1                             all          NetworkManager GUI library - translations
ii  libnma-gtk4-0:arm64                   1.10.6-1                             arm64        NetworkManager GUI GTK4 library
ii  libnma0:arm64                         1.10.6-1                             arm64        NetworkManager GUI library
ii  libproxy1-plugin-networkmanager:arm64 0.4.18-1.2                           arm64        automatic proxy configuration management library (Network Manager plugin)
ii  network-manager                       1.44.0-1                             arm64        network management framework (daemon and userspace tools)
ii  network-manager-gnome                 1.32.0-3                             arm64        network management framework (GNOME frontend)

callaudiod 0.1.9-1-DEBUG is identical to commit 0bb10da debian/0.1.9-1 except that all instances of g_debug, g_info, g_warning, g_error are changed to g_critical in order to force them to be logged by journalctl. I couldn't find a more elegant way of doing this, e.g. using GDK_DEBUG=debug, because callaudiod seems to be started automatically by the user's systemd and I didn't see a systemd way of doing this cleanly.

DIAGNOSIS:

The logs of CALL0 (succeeded) and CALL1 (failed) show the kernel shutting off the USB connections, without further explanation.
- journalctl @ pp : https://paste.debian.net/hidden/2f80d67c
- openqti @ modem: https://paste.debian.net/hidden/f6267126
- dmesg modem + dmesg pp: https://paste.debian.net/hidden/f2cf34ea
USB settings

https://github.com/the-modem-distro/pinephone_modem_sdk/blob/kirkstone/docs/SETTINGS.md suggests that the kernel being "too aggresive" in shutting down the USB to the modem can be overcome with eg25-manager udev rules.

$ cat /usr/lib/udev/rules.d/80-modem-eg25.rules
ACTION=="add", SUBSYSTEM=="usb", DRIVERS=="usb", ENV{DEVTYPE}=="usb_device", GOTO="eg25_start"
GOTO="eg25_end"

# Default attributes values
LABEL="eg25_start"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/control}="auto"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/autosuspend_delay_ms}="3000"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/wakeup}="enabled"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/persist}="0"

# power/control needs to be "on" for the community-maintained firmware
# 2023-05-28 - not sure if 'community_fw' attribute is set, so be less conservative, as per https://github.com/the-modem-distro/pinephone_modem_sdk/blob/honister/docs/SETTINGS.md
# ATTRS{serial}=="community_fw", ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/control}="on"
ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", ATTR{power/control}="on"

# Special trick for the PinePhone Pro: set power/persist to 1 *only* with the community FW
# We can identify the PPP by looking for the string "pinephone-pro" in the device tree "compatible" property
ATTRS{serial}=="community_fw", ATTRS{idVendor}=="2c7c", ATTRS{idProduct}=="0125", PROGRAM=="/bin/grep pine64,pinephone-pro /proc/device-tree/compatible", ATTR{power/persist}="1"

LABEL="eg25_end"

Check the actual effect of the settings - power/control is on (the following more command was run around 6 h after the calls CALL0 and CALL1; the active_duration value indicates 15785.384 seconds of power, i.e. about 4.4 hours):

more /sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/*
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/active_duration
::::::::::::::
15785384
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/async
::::::::::::::
enabled
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/autosuspend
::::::::::::::
3
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/autosuspend_delay_ms
::::::::::::::
3000
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/connected_duration
::::::::::::::
15787360
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/control
::::::::::::::
on
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/level
::::::::::::::
on
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/persist
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/runtime_active_kids
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/runtime_active_time
::::::::::::::
15794017
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/runtime_enabled
::::::::::::::
forbidden
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/runtime_status
::::::::::::::
active
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/runtime_suspended_time
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/runtime_usage
::::::::::::::
2
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup
::::::::::::::
enabled
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_abort_count
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_active
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_active_count
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_count
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_expire_count
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_last_time_ms
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_max_time_ms
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_prevent_sleep_time_ms
::::::::::::::
0
::::::::::::::
/sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/wakeup_total_time_ms
::::::::::::::
0

Kernel modules:

$ lsmod |grep -E "usb|wwan|cdc"
qmi_wwan               36864  0
cdc_wdm                28672  2 qmi_wwan
usb_wwan               24576  1 option
usbnet                 40960  1 qmi_wwan
usbserial              45056  6 usb_wwan,option
mii                    16384  1 usbnet
usb_f_ecm              24576  2
u_ether                28672  1 usb_f_ecm
libcomposite           61440  10 usb_f_ecm
configfs               45056  3 usb_f_ecm,libcomposite
axp20x_usb_power       20480  0
industrialio           73728  12 stk3310,axp20x_battery,industrialio_triggered_buffer,st_sensors,inv_mpu6050,kfifo_buf,st_magn_i2c,st_magn,axp20x_usb_power,af8133j,axp20x_adc,st_magn_spi
musb_hdrc             114688  1 sunxi
udc_core               53248  4 u_ether,usb_f_ecm,libcomposite,musb_hdrc

PS: There are many good reason to https://giveupgithub.org .

If this bug is not the fault of the modem software, then I could post this as a linux-image-6.1-sunxi64 bug at https://salsa.debian.org/Mobian-team/devices/kernels/sunxi64-linux/-/issues .

Some points from discussion at https://matrix.to/#/#pinephone_modem_sdk-issue-9:matrix.org based on the logs:

the modem was running during the whole time of the incoming call and USB disconnections
the pinephone (SOC) was also running (not suspended) during the period
for the non-experts: USB power states include: active, suspended, disconnected
the kernel guide to USB is here: https://www.kernel.org/doc/Documentation/usb/power-management.txt
so far there are no good hypotheses as to why the kernel decided to disconnect the USB (except for a possible hardware problem)

The frequency of occurrence of the USB disconnecting on an incoming call is not well established. Volunteers' patience for doing test calls cannot be stretched too far... :P Today I did a pair of calls: outgoing and incoming: both went well (echo at the remote end was strong for the outgoing call; it was weak for the incoming call).

OCCURRENCE on an independent pinephone in April 2023:

The log at https://github.com/the-modem-distro/pinephone_modem_sdk/issues/203 (mentioned above) looks like the same bug: incoming call and USB disconnect messages in journalctl that look similar to my case.

Differences in software/system:
- @tiol11 is (was) on "OG PP on Mobian bookworm" - I'm on Mobian/trixie, although I do feel that I had this bug occur earlier, when I was less ambitious in trying to get calls to work fully and didn't check logs so much
- "FW 0.7.4" - I'm on 0.7.2
- "environment Plasma mobile" - I'm on phosh+phoc
  - the logs show that 203 has ksmserver and hdf-service for the session manager and feedback service - I have phosh and feedbackd
- @tiol11 's phone rebooted after the incoming call - I haven't had any forced reboot following the USB disconnections.
Commonalities:
- we're both on ADSP 01.003.01.003

REPEAT OCCURRENCE and non-occurrences:

In a small handful of tests over the last few days, I've had three successful outgoing calls, and:

two successful incoming calls
one incoming call with the same USB disconnection bug as here (based on browsing the journalctl log)

HOW TO NOT FIX THE BUG:

Two days ago I did

# echo "on" > /sys/devices/platform/soc/1c1b000.usb/usb2/power/control
# echo "on" > /sys/devices/platform/soc/1c1b000.usb/power/control

based on the hypothesis that despite suspension apparently not being the problem, it couldn't hurt to try to prevent the kernel from suspending the 1c1b000.usb2 hub overall, rather than just the 1c1b000.usb2/usb2/2-1 part that goes directly to the 6 "devices". I checked that the 2-1 part was correctly set too:

$ cat /sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/control
on

I'm reasonably sure (98%) that today's incoming call with the USB disconnection happened while these settings were unchanged.

POSSIBLY RELATED:

Power problem? other devices (not PP), similar disconnection messages:

2010: solved by giving more power to the usb dongle - https://ubuntuforums.org/archive/index.php/t-1382507.html
quectel March 2022: solved by apt remove modemmanager - https://forums.quectel.com/t/bg95-m3minipcie-converter-detected-converter-now-disconnected/13764
Jul 2020: https://forum.khadas.com/t/modem-usb-gets-disconnected/9038
Jan 2020: https://community.nxp.com/t5/i-MX-Processors/ttyUSB-device-driver-is-not-stable/m-p/1044142
Dec 2022: reset after sending an AT command - sounds like a current or voltage problem: https://www.spinics.net/lists/linux-usb/msg234806.html

Based on my understanding of https://www.kernel.org/doc/Documentation/usb/persist.txt, it seems that

echo "1" > /sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/persist

should be safe, since the modem is not physically unplugged and plugged. Currently I have

$ cat /sys/devices/platform/soc/1c1b000.usb/usb2/2-1/power/persist 
0

But I'd like advice from someone who understands this properly before trying it. I wouldn't want the phone kernel to intervene in the modem in a dangerous way. update: still true, in principle, but I'll probably try it anyway given that it's advised for the PinePhonePro and the chance of my modem being physically unplugged and another modem being plugged back in is extremely tiny.

Could this prevent the disconnections?

Based on irc discussion, it seems that using the PPP udev settings recommended in the kirkstone branch of SETTINGS.md on a PP may have prevented USB disconnections (phone behaviour, without checking logs): https://github.com/the-modem-distro/pinephone_modem_sdk/blame/kirkstone/docs/SETTINGS.md .

This includes both a rule to write 1 to power/persist and an edit to /usr/share/eg25-manager/pine64,pinephone-1.2.toml to prevent creation of monitor_udev (I presume that this means files in /sys/devices/platform/soc/1c1b000.usb/usbmon/usbmon2/ .)

I've implemented this on my PP and will now see how tests go: https://gitlab.com/broukema/eg25-manager/-/compare/master...master?from_project_id=23025315

If all is OK, I'll propose it as a MR.

@Biktorgj - you should wait for feedback from me to see if this works on my phone, but comments from you about whether it's reasonable to include in the sense that it is likely to be safe and unlikely to introduce any bugs would help the eg25-manager people come to a decision.

@tiol11 - the files you need to edit may be placed in somewhat different places - you'll have to adapt directory names between Debian/trixie and your system. Feedback about whether this solves your bug would be welcome.

There's a reponse from @Biktorgj on matrix - power/persist should work most of the time, but will sometimes lead to a bug in the usb controller. It's unclear to me if that means that turning the phone off and on will necessarily solve that, or in some cases cannot solve that. There is an idea of what might be able to be a solution. It's up to Biktorgj to write this (or not) in this bug report for others to read as a summary.

In any case, the two changes in the eg25-manager commit (power/persist + disable monitor_udev) did not give functioning audio calls (though I didn't get any USB disconnects on incoming calls - so it may have been effective in the sense of preventing the USB disconnects, but with apparent side effects). Now I cannot get back to the previous semi-functionality of audio calls...

Do USB disconnections by the PP kernel or msm_hsusb events on the modem occur if eg25-manager is disabled? (test recommended by @biktorgj)

On the PP:

$ sudo systemctl disable eg25-manager
Removed "/etc/systemd/system/multi-user.target.wants/eg25-manager.service".
$ sudo mv -iv /usr/bin/eg25-manager /usr/bin/eg25-manager_disabled
renamed '/usr/bin/eg25-manager' -> '/usr/bin/eg25-manager_disabled'
$ sudo killall -9 eg25-manager
$
$ ps -A uf|grep eg25 |grep -v grep
$

On the PP lockscreen, the modem icons remained in place.

Eleven incoming calls (call33 .. call44) were made. Apart from audio issues, the calls themselves were "successful" in the sense that the USB to the modem was not disconnected according to the touchscreen display. Audio was recovered after pipewire restarted itself and related services and I restored a previously recorded set of alsa settings.

PP journalctl:

$ sudo journalctl -n 5000 |grep -E "modem[0-9]*/call[0-9]*[0-9]|USB.*disc|creating modem|eg25|reset modem"
Sep 10 17:37:26 mobian sudo[14808]:   mobian : TTY=pts/1 ; PWD=/home/mobian ; USER=root ; COMMAND=/usr/bin/systemctl disable eg25-manager
Sep 10 17:37:39 mobian sudo[14926]:   mobian : TTY=pts/1 ; PWD=/home/mobian ; USER=root ; COMMAND=/usr/bin/mv -iv /usr/bin/eg25-manager /usr/bin/eg25-manager_disabled
Sep 10 17:37:47 mobian sudo[14937]:   mobian : TTY=pts/1 ; PWD=/home/mobian ; USER=root ; COMMAND=/usr/bin/killall -9 eg25-manager
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Main process exited, code=killed, status=9/KILL
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Failed with result 'signal'.
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Consumed 1.039s CPU time.
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Scheduled restart job, restart counter is at 1.
Sep 10 17:37:47 mobian systemd[1]: Started eg25-manager.service - Quectel EG25 modem.
Sep 10 17:37:47 mobian (-manager)[14946]: eg25-manager.service: Failed to locate executable /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:47 mobian (-manager)[14946]: eg25-manager.service: Failed at step EXEC spawning /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Main process exited, code=exited, status=203/EXEC
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Failed with result 'exit-code'.
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Scheduled restart job, restart counter is at 2.
Sep 10 17:37:47 mobian systemd[1]: Started eg25-manager.service - Quectel EG25 modem.
Sep 10 17:37:47 mobian (-manager)[14951]: eg25-manager.service: Failed to locate executable /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:47 mobian (-manager)[14951]: eg25-manager.service: Failed at step EXEC spawning /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Main process exited, code=exited, status=203/EXEC
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Failed with result 'exit-code'.
Sep 10 17:37:47 mobian systemd[1]: eg25-manager.service: Scheduled restart job, restart counter is at 3.
Sep 10 17:37:47 mobian systemd[1]: Started eg25-manager.service - Quectel EG25 modem.
Sep 10 17:37:48 mobian (-manager)[14956]: eg25-manager.service: Failed to locate executable /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:48 mobian (-manager)[14956]: eg25-manager.service: Failed at step EXEC spawning /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Main process exited, code=exited, status=203/EXEC
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Failed with result 'exit-code'.
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Scheduled restart job, restart counter is at 4.
Sep 10 17:37:48 mobian systemd[1]: Started eg25-manager.service - Quectel EG25 modem.
Sep 10 17:37:48 mobian (-manager)[14960]: eg25-manager.service: Failed to locate executable /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:48 mobian (-manager)[14960]: eg25-manager.service: Failed at step EXEC spawning /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Main process exited, code=exited, status=203/EXEC
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Failed with result 'exit-code'.
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Scheduled restart job, restart counter is at 5.
Sep 10 17:37:48 mobian systemd[1]: Started eg25-manager.service - Quectel EG25 modem.
Sep 10 17:37:48 mobian (-manager)[14964]: eg25-manager.service: Failed to locate executable /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:48 mobian (-manager)[14964]: eg25-manager.service: Failed at step EXEC spawning /usr/bin/eg25-manager: No such file or directory
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Main process exited, code=exited, status=203/EXEC
Sep 10 17:37:48 mobian systemd[1]: eg25-manager.service: Failed with result 'exit-code'.
Sep 10 17:37:49 mobian systemd[1]: eg25-manager.service: Scheduled restart job, restart counter is at 6.
Sep 10 17:37:49 mobian systemd[1]: eg25-manager.service: Start request repeated too quickly.
Sep 10 17:37:49 mobian systemd[1]: eg25-manager.service: Failed with result 'exit-code'.
Sep 10 17:37:49 mobian systemd[1]: Failed to start eg25-manager.service - Quectel EG25 modem.
Sep 10 17:40:24 mobian ModemManager[782]: <info>  [modem17/call33] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 17:40:26 mobian ModemManager[782]: <info>  [modem17/call33] user request to accept call
Sep 10 17:40:26 mobian ModemManager[782]: <info>  [modem17/call33] call is accepted
Sep 10 17:40:26 mobian ModemManager[782]: <info>  [modem17/call33] call state changed: ringing-in -> active (accepted)
Sep 10 17:40:37 mobian ModemManager[782]: <info>  [modem17/call33] user request to hangup call
Sep 10 17:40:37 mobian ModemManager[782]: <info>  [modem17/call33] call state changed: active -> terminated (terminated)
Sep 10 17:41:15 mobian ModemManager[782]: <info>  [modem17/call34] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 17:41:19 mobian ModemManager[782]: <info>  [modem17/call34] user request to accept call
Sep 10 17:41:19 mobian ModemManager[782]: <info>  [modem17/call34] call is accepted
Sep 10 17:41:19 mobian ModemManager[782]: <info>  [modem17/call34] call state changed: ringing-in -> active (accepted)
Sep 10 17:41:36 mobian ModemManager[782]: <info>  [modem17/call34] user request to hangup call
Sep 10 17:41:36 mobian ModemManager[782]: <info>  [modem17/call34] call state changed: active -> terminated (unknown)
Sep 10 17:41:48 mobian ModemManager[782]: <info>  [modem17/call35] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 17:41:50 mobian ModemManager[782]: <info>  [modem17/call35] user request to accept call
Sep 10 17:41:50 mobian ModemManager[782]: <info>  [modem17/call35] call is accepted
Sep 10 17:41:50 mobian ModemManager[782]: <info>  [modem17/call35] call state changed: ringing-in -> active (accepted)
Sep 10 17:42:10 mobian ModemManager[782]: <info>  [modem17/call35] call state changed: active -> terminated (unknown)
Sep 10 17:43:38 mobian ModemManager[782]: <info>  [modem17/call36] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 17:43:40 mobian ModemManager[782]: <info>  [modem17/call36] user request to accept call
Sep 10 17:43:40 mobian ModemManager[782]: <info>  [modem17/call36] call is accepted
Sep 10 17:43:40 mobian ModemManager[782]: <info>  [modem17/call36] call state changed: ringing-in -> active (accepted)
Sep 10 17:43:55 mobian ModemManager[782]: <info>  [modem17/call36] user request to hangup call
Sep 10 17:43:55 mobian ModemManager[782]: <info>  [modem17/call36] call state changed: active -> terminated (terminated)
Sep 10 17:44:10 mobian ModemManager[782]: <info>  [modem17/call37] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 17:44:13 mobian ModemManager[782]: <info>  [modem17/call37] user request to accept call
Sep 10 17:44:13 mobian ModemManager[782]: <info>  [modem17/call37] call is accepted
Sep 10 17:44:13 mobian ModemManager[782]: <info>  [modem17/call37] call state changed: ringing-in -> active (accepted)
Sep 10 17:44:24 mobian ModemManager[782]: <info>  [modem17/call37] call state changed: active -> terminated (unknown)
Sep 10 18:50:34 mobian ModemManager[782]: <info>  [modem17/call38] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 18:50:36 mobian ModemManager[782]: <info>  [modem17/call38] user request to accept call
Sep 10 18:50:36 mobian ModemManager[782]: <info>  [modem17/call38] call is accepted
Sep 10 18:50:36 mobian ModemManager[782]: <info>  [modem17/call38] call state changed: ringing-in -> active (accepted)
Sep 10 18:50:45 mobian ModemManager[782]: <info>  [modem17/call38] call state changed: active -> terminated (unknown)
Sep 10 18:51:40 mobian ModemManager[782]: <info>  [modem17/call39] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 18:51:42 mobian ModemManager[782]: <info>  [modem17/call39] user request to accept call
Sep 10 18:51:42 mobian ModemManager[782]: <info>  [modem17/call39] call is accepted
Sep 10 18:51:42 mobian ModemManager[782]: <info>  [modem17/call39] call state changed: ringing-in -> active (accepted)
Sep 10 18:52:28 mobian ModemManager[782]: <info>  [modem17/call39] call state changed: active -> terminated (unknown)
Sep 10 18:52:52 mobian ModemManager[782]: <info>  [modem17/call40] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 18:52:54 mobian ModemManager[782]: <info>  [modem17/call40] user request to accept call
Sep 10 18:52:54 mobian ModemManager[782]: <info>  [modem17/call40] call is accepted
Sep 10 18:52:54 mobian ModemManager[782]: <info>  [modem17/call40] call state changed: ringing-in -> active (accepted)
Sep 10 18:53:19 mobian ModemManager[782]: <info>  [modem17/call40] call state changed: active -> terminated (unknown)
Sep 10 18:56:31 mobian ModemManager[782]: <info>  [modem17/call41] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 18:56:33 mobian ModemManager[782]: <info>  [modem17/call41] user request to accept call
Sep 10 18:56:33 mobian ModemManager[782]: <info>  [modem17/call41] call is accepted
Sep 10 18:56:33 mobian ModemManager[782]: <info>  [modem17/call41] call state changed: ringing-in -> active (accepted)
Sep 10 19:00:28 mobian ModemManager[782]: <info>  [modem17/call41] user request to hangup call
Sep 10 19:00:28 mobian ModemManager[782]: <info>  [modem17/call41] call state changed: active -> terminated (terminated)
Sep 10 19:00:55 mobian ModemManager[782]: <info>  [modem17/call42] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 19:00:57 mobian ModemManager[782]: <info>  [modem17/call42] user request to accept call
Sep 10 19:00:57 mobian ModemManager[782]: <info>  [modem17/call42] call is accepted
Sep 10 19:00:57 mobian ModemManager[782]: <info>  [modem17/call42] call state changed: ringing-in -> active (accepted)
Sep 10 19:01:08 mobian ModemManager[782]: <info>  [modem17/call42] call state changed: active -> terminated (unknown)
Sep 10 19:01:51 mobian ModemManager[782]: <info>  [modem17/call43] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 19:02:06 mobian ModemManager[782]: <info>  [modem17/call43] user request to accept call
Sep 10 19:02:06 mobian ModemManager[782]: <info>  [modem17/call43] call is accepted
Sep 10 19:02:06 mobian ModemManager[782]: <info>  [modem17/call43] call state changed: ringing-in -> active (accepted)
Sep 10 19:02:23 mobian ModemManager[782]: <info>  [modem17/call43] user request to hangup call
Sep 10 19:02:23 mobian ModemManager[782]: <info>  [modem17/call43] call state changed: active -> terminated (terminated)
Sep 10 19:42:17 mobian ModemManager[782]: <info>  [modem17/call44] call state changed: unknown -> ringing-in (incoming-new)
Sep 10 19:42:20 mobian ModemManager[782]: <info>  [modem17/call44] user request to accept call
Sep 10 19:42:20 mobian ModemManager[782]: <info>  [modem17/call44] call is accepted
Sep 10 19:42:20 mobian ModemManager[782]: <info>  [modem17/call44] call state changed: ringing-in -> active (accepted)
Sep 10 19:42:31 mobian ModemManager[782]: <info>  [modem17/call44] call state changed: active -> terminated (unknown)

MODEM dmesg:

sh-5.1# dmesg |grep msm_hsusb
[    0.437987] msm_hsusb msm_hsusb: ITC is configured to 0 
[    1.241991] msm_hsusb msm_hsusb: [ci13xxx_start] hw_ep_max = 32
[    1.242055] msm_hsusb msm_hsusb: CI13XXX_CONTROLLER_RESET_EVENT received
[    1.242090] msm_hsusb msm_hsusb: CI13XXX_CONTROLLER_UDC_STARTED_EVENT received
[   14.799832] msm_hsusb msm_hsusb: CI13XXX_CONTROLLER_CONNECT_EVENT received
sh-5.1# date 
Sun Sep 10 22:36:34 UTC 2023
sh-5.1# date > /dev/kmsg 
sh-5.1# dmesg |tail -n 30
[ 2477.633275] afe_open: port_id 0x100d rate 8000
[ 6461.599090] mdm_auxpcm_mode_put: mdm_auxpcm_mode = 0 ucontrol->value = 1
[ 6461.604577] mdm_sec_auxpcm_mode_put: mdm_sec_auxpcm_mode = 0 ucontrol->value = 1
[ 6461.631293] afe_open: port_id 0x100c rate 8000
[ 6461.641826] afe_open: port_id 0x100d rate 8000
[ 6527.492007] mdm_auxpcm_mode_put: mdm_auxpcm_mode = 0 ucontrol->value = 1
[ 6527.494711] mdm_sec_auxpcm_mode_put: mdm_sec_auxpcm_mode = 0 ucontrol->value = 1
[ 6527.524884] afe_open: port_id 0x100c rate 8000
[ 6527.534851] afe_open: port_id 0x100d rate 8000
[ 6598.959095] mdm_auxpcm_mode_put: mdm_auxpcm_mode = 0 ucontrol->value = 1
[ 6598.963744] mdm_sec_auxpcm_mode_put: mdm_sec_auxpcm_mode = 0 ucontrol->value = 1
[ 6598.990079] afe_open: port_id 0x100c rate 8000
[ 6598.999831] afe_open: port_id 0x100d rate 8000
[ 6818.334613] mdm_auxpcm_mode_put: mdm_auxpcm_mode = 0 ucontrol->value = 1
[ 6818.337267] mdm_sec_auxpcm_mode_put: mdm_sec_auxpcm_mode = 0 ucontrol->value = 1
[ 6818.366654] afe_open: port_id 0x100c rate 8000
[ 6818.375730] afe_open: port_id 0x100d rate 8000
[ 7082.460011] mdm_auxpcm_mode_put: mdm_auxpcm_mode = 0 ucontrol->value = 1
[ 7082.463330] mdm_sec_auxpcm_mode_put: mdm_sec_auxpcm_mode = 0 ucontrol->value = 1
[ 7082.490592] afe_open: port_id 0x100c rate 8000
[ 7082.500076] afe_open: port_id 0x100d rate 8000
[ 7138.545818] mdm_auxpcm_mode_put: mdm_auxpcm_mode = 0 ucontrol->value = 1
[ 7138.548524] mdm_sec_auxpcm_mode_put: mdm_sec_auxpcm_mode = 0 ucontrol->value = 1
[ 7138.575820] afe_open: port_id 0x100c rate 8000
[ 7138.585535] afe_open: port_id 0x100d rate 8000
[ 9564.803729] mdm_auxpcm_mode_put: mdm_auxpcm_mode = 0 ucontrol->value = 1
[ 9564.807801] mdm_sec_auxpcm_mode_put: mdm_sec_auxpcm_mode = 0 ucontrol->value = 1
[ 9564.835310] afe_open: port_id 0x100c rate 8000
[ 9564.844665] afe_open: port_id 0x100d rate 8000
[20046.130611] Sun Sep 10 22:36:50 UTC 2023

INTERPRETATION:

The logs appear to confirm that there were no USB disconnections during the five hours since eg25-manager was disabled, at around 17:37:47 which is about 2046 s in the modem dmesg log. 2477 s corresponds to 17:44:58 (between call37 and call38).

The CI13XXXCONTROLLER* events occurred around 17:03:42 and 17:03:56, when I earlier stopped and started eg25-manager (with monitor_udev = false in /usr/share/eg25-manager/pine64,pinephone-1.2.toml).

Do USB disconnections by the PP kernel or msm_hsusb events on the modem occur if eg25-manager is enabled but manage_udev = false ? (test recommended by @Biktorgj)

I restored eg25-manager to its normal state, setting _manageudev = false in /usr/share/eg25-manager/pine64,pinephone-1.2.toml and stopped and restarted eg25-manager:

sudo systemctl stop eg25-manager
sudo systemctl start eg25-manager

My PP was

on its charging cable (attached to a desktop computer for 7 hours), received 3 incoming calls;
was being transported freely (allowing suspension) for an hour
was another hour suspended
several hours off cable
3 incoming calls and 2 outgoing calls [1]

[1] The second call audio failed with [modem21/call49] call state changed: ringing-in -> terminated (error); and call50..call52 all failed in the sense that outgoing audio was not heard. However, these are (probably) not related to monitor_udev = false.

~~PROPOSAL:~~ I'll keep my PP running with monitor_udev = false in /usr/share/eg25-manager/pine64,pinephone-1.2.toml. If a week or so passes with no USB disconnections occurring on incoming phone calls (or on times when the phone is not allowed to suspend - charging on connected to a desktop computer), then we could propose this upstream for eg25-manager as a workaround.

The USB initial disconnects have re-occurred on incoming phone calls with monitor_udev = false. So proposing monitor_udev = false for the PP as a workaround is pointless, since it doesn't solve the bug. I browsed all the log files - the lines around the times of the disconnections look similar to the earlier events. I don't see any new clues.

However, the "second" disconnection series of events of the pattern in https://paste.debian.net/hidden/2f80d67c of 5 Sep (see above)

Sep 05 17:30:40 mobian eg25-manager[51115]: Trying to reset modem with USB ID '2-1'
Sep 05 17:30:40 mobian kernel: option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Sep 05 17:30:40 mobian kernel: option 2-1:1.0: device disconnected
Sep 05 17:30:40 mobian kernel: option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Sep 05 17:30:40 mobian kernel: option 2-1:1.1: device disconnected
Sep 05 17:30:40 mobian kernel: option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Sep 05 17:30:40 mobian kernel: option 2-1:1.2: device disconnected
Sep 05 17:30:40 mobian ModemManager[51135]: <info>  [device /sys/devices/platform/soc/1c1b000.usb/usb2/2-1] creating modem with plugin 'quectel' and '6' ports
Sep 05 17:30:40 mobian kernel: option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3
Sep 05 17:30:40 mobian kernel: option 2-1:1.3: device disconnected

that occurs about 3 seconds after the initial USB disconnections did not occur with monitor_udev = false in /usr/share/eg25-manager/pine64,pinephone-1.2.toml, e.g.

grep "Trying to reset modem"

on the journalctl log file shows no results.

I had a USB-disconnection-on-incoming-phone-call event with power/persist = 1 and monitor_udev = false. Only the "first" disconnection series occurred, not the "second" one; I interpret the non-occurrence of the "second" disconnection as a result of monitor_udev = false. Here's the log: https://paste.debian.net/hidden/c6e69e3c

The extra callaudiod lines are hacks I did to report more info, including the battery voltage. In particular, the lines that report the first step in the overall disconnection sequence

Sep 20 09:37:58 mobian callaudiod[1075]: SINK: idx=204 name='alsa_output.platform-sound.Voice_Call__hw_PinePhone_0__sink'
Sep 20 09:37:58 mobian kernel: usb 2-1: USB disconnect, device number 3
Sep 20 09:37:58 mobian kernel: option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Sep 20 09:37:58 mobian kernel: option 2-1:1.0: device disconnected
Sep 20 09:37:58 mobian kernel: option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Sep 20 09:37:58 mobian kernel: option 2-1:1.1: device disconnected
Sep 20 09:37:58 mobian kernel: option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Sep 20 09:37:58 mobian kernel: option 2-1:1.2: device disconnected
Sep 20 09:37:58 mobian callaudiod[1075]: axp20x-battery voltage = 3580000

include the 09:37:58 mobian callaudiod[1075]: axp20x-battery voltage = 3580000 line that is executed immediately after the 09:37:58 mobian callaudiod[1075]: SINK: idx=204 name='alsa_output.platform-sound.Voice_Call__hw_PinePhone_0__sink' line by callaudiod. The small delay for opening, reading and closing /sys/class/power_supply/axp20x-battery/voltage_now is apparently long enough to allow the kernel messages to be logged by journalctl in between the SINK output line and the voltage output line.

According to the log, the battery voltage drops from 3609 mV to 3561 mV (after modem1/call6 accepted the call), goes back up to 3580 mV after the sink and source are removed and card 47 is changed, and then sits at 3580 mV before and after the USB disconnection.

Interpretation: I tend to agree that callaudiod is probably not the culprit. I currently suspect Sep 20 09:37:56 mobian eg25-manager[684]: Executed soft sleep sequence in eg25-manager. I've hacked related lines to report more details about what happens there. Now the problem is to keep trying incoming calls until another disconnection event occurs and the info gets logged properly. I currently suspect one of the lines around 132-151 in

https://salsa.debian.org/DebianOnMobile-team/eg25-manager/-/blob/debian/latest/src/at.c

so I've hacked these to become more verbose.

Voltage ('voltage_now') vs potential energy ('capacity'):

Based on checking the values of

/sys/class/power_supply/axp20x-battery/voltage_now
/sys/class/power_supply/axp20x-battery/capacity

it appears that my PP tries to keep voltage_now at a constant level of around 3600 to 3800mV independent of the capacity (which actually seems to mean the fraction of total capacity in potential energy).

An incoming phone call with capacity at around 20 and my phosh torch on 100% (to try to lower the voltage) caused (appeared to be the cause of) my phone shutting down.
With voltage_now around 3570 mV, I got a USB disconnection event on an incoming call.

LOG Journalctl excerpt of the USB disconnection event of a few hours ago:

Sep 22 14:23:07 mobian callaudiod[1020]: axp20x-battery voltage = 3528000
Sep 22 14:23:07 mobian callaudiod[1020]: SINK:   speaker_port='[Out] Speaker'
Sep 22 14:23:07 mobian callaudiod[1020]: SINK:   earpiece_port='[Out] Earpiece'
Sep 22 14:23:07 mobian callaudiod[1020]: <redacted>oking for available output excluding '(null)'
Sep 22 14:23:07 mobian callaudiod[1020]: axp20x-battery voltage = 3528000
Sep 22 14:23:07 mobian callaudiod[1020]: found available output '[Out] Speaker'
Sep 22 14:23:07 mobian callaudiod[1020]: axp20x-battery voltage = 3528000
Sep 22 14:23:07 mobian callaudiod[1020]:   Using sink port '[Out] Speaker'
Sep 22 14:23:07 mobian callaudiod[1020]: SOURCE: idx=96 name='alsa_input.platform-sound.HiFi__hw_PinePhone_0__source'
Sep 22 14:23:07 mobian callaudiod[1020]: <redacted>oking for available input excluding '(null)'
Sep 22 14:23:07 mobian callaudiod[1020]: found available input '[In] Mic'
Sep 22 14:23:07 mobian callaudiod[1020]: card 44 changed
Sep 22 14:23:07 mobian callaudiod[1020]: axp20x-battery voltage = 3528000
Sep 22 14:23:13 mobian sm.puri.OSK0.desktop[1451]: Info: Loaded layout Path: "/home/mobian/.<redacted>cal/share/squeekboard/keyboards/terminal/us.yaml"
Sep 22 14:23:36 mobian ModemManager[739]: <info>  [modem1/call1] call state changed: unknown -> ringing-in (incoming-new)
Sep 22 14:23:37 mobian sm.puri.OSK0.desktop[1451]: Debug: Tried file "/home/mobian/.<redacted>cal/share/squeekboard/keyboards/us.yaml", but it's missing: No such file or directory (os error 2)
Sep 22 14:23:37 mobian sm.puri.OSK0.desktop[1451]: Info: Loaded layout Resource: us
Sep 22 14:23:37 mobian eg25-manager[633]: Response: [RING]
Sep 22 14:23:37 mobian eg25-manager[633]: Will call gpio_sequence_sleep.
Sep 22 14:23:37 mobian eg25-manager[633]: Executed soft sleep sequence
Sep 22 14:23:37 mobian eg25-manager[633]: No extra work to do for soft sleep; manager->modem_state = 6
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [modem1/call1] user request to accept call
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [modem1/call1] call is accepted
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [modem1/call1] call state changed: ringing-in -> active (accepted)
Sep 22 14:23:38 mobian callaudiod[1020]: Select mode: 1
Sep 22 14:23:38 mobian callaudiod[1020]: card has voice profile, using it
Sep 22 14:23:38 mobian callaudiod[1020]: axp20x-battery voltage = 3514000
Sep 22 14:23:38 mobian callaudiod[1020]: switching to voice profile
Sep 22 14:23:38 mobian callaudiod[1020]: axp20x-battery voltage = 3514000
Sep 22 14:23:38 mobian callaudiod[1020]: sink 95 removed
Sep 22 14:23:38 mobian gsd-media-keys[1290]: Unable to get default sink
Sep 22 14:23:38 mobian gsd-media-keys[1290]: Unable to get default source
Sep 22 14:23:38 mobian callaudiod[1020]: source 96 removed
Sep 22 14:23:38 mobian callaudiod[1020]: operation returned 1
Sep 22 14:23:38 mobian callaudiod[1020]: card 44 changed
Sep 22 14:23:38 mobian callaudiod[1020]: axp20x-battery voltage = 3514000
Sep 22 14:23:38 mobian callaudiod[1020]: new sink 108
Sep 22 14:23:38 mobian callaudiod[1020]: new source 108
Sep 22 14:23:38 mobian callaudiod[1020]: new source 109
Sep 22 14:23:38 mobian kernel: usb 2-1: USB disconnect, device number 3
Sep 22 14:23:38 mobian kernel: option1 ttyUSB0: GSM modem (1-port) converter now disconnected from ttyUSB0
Sep 22 14:23:38 mobian kernel: option 2-1:1.0: device disconnected
Sep 22 14:23:38 mobian kernel: option1 ttyUSB1: GSM modem (1-port) converter now disconnected from ttyUSB1
Sep 22 14:23:38 mobian kernel: option 2-1:1.1: device disconnected
Sep 22 14:23:38 mobian kernel: option1 ttyUSB2: GSM modem (1-port) converter now disconnected from ttyUSB2
Sep 22 14:23:38 mobian kernel: option 2-1:1.2: device disconnected
Sep 22 14:23:38 mobian kernel: option1 ttyUSB3: GSM modem (1-port) converter now disconnected from ttyUSB3
Sep 22 14:23:38 mobian kernel: option 2-1:1.3: device disconnected
Sep 22 14:23:38 mobian callaudiod[1020]: SINK: idx=108 name='alsa_output.platform-sound.Voice_Call__hw_PinePhone_0__sink'
Sep 22 14:23:38 mobian kernel: qmi_wwan 2-1:1.4 wwan0: unregister 'qmi_wwan' usb-1c1b000.usb-1, WWAN/QMI device
Sep 22 14:23:38 mobian systemd-networkd[452]: wwan0: Link DOWN
Sep 22 14:23:38 mobian systemd-networkd[452]: wwan0: Lost carrier
Sep 22 14:23:38 mobian callaudiod[1020]: axp20x-battery voltage = 3514000
Sep 22 14:23:38 mobian callaudiod[1020]: SINK:   speaker_port='[Out] Speaker'
Sep 22 14:23:38 mobian callaudiod[1020]: SINK:   earpiece_port='[Out] Earpiece'
Sep 22 14:23:38 mobian callaudiod[1020]: <redacted>oking for available output excluding '(null)'
Sep 22 14:23:38 mobian callaudiod[1020]: axp20x-battery voltage = 3514000
Sep 22 14:23:38 mobian callaudiod[1020]: found available output '[Out] Earpiece'
Sep 22 14:23:38 mobian callaudiod[1020]: axp20x-battery voltage = 3502000
Sep 22 14:23:38 mobian callaudiod[1020]:   Using sink port '[Out] Earpiece'
Sep 22 14:23:38 mobian callaudiod[1020]: SOURCE: idx=109 name='alsa_input.platform-sound.Voice_Call__hw_PinePhone_0__source'
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [base-manager] port ttyUSB1 released by device '/sys/devices/platform/soc/1c1b000.usb/usb2/2-1'
Sep 22 14:23:38 mobian callaudiod[1020]: <redacted>oking for available input excluding '(null)'
Sep 22 14:23:38 mobian ModemManager[739]: <warn>  Cannot read from istream: connection broken
Sep 22 14:23:38 mobian callaudiod[1020]: found available input '[In] Mic'
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [modem1] port 'cdc-wdm0' no <redacted>nger controllable, reprobing
Sep 22 14:23:38 mobian callaudiod[1020]: card 44 changed
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [base-manager] port ttyUSB0 released by device '/sys/devices/platform/soc/1c1b000.usb/usb2/2-1'
Sep 22 14:23:38 mobian NetworkManager[650]: <warn>  [1695385418.8897] platform-linux: do-add-ip4-address[4: <redacted>]: failure 19 (No such device)
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [base-manager] port ttyUSB2 released by device '/sys/devices/platform/soc/1c1b000.usb/usb2/2-1'
Sep 22 14:23:38 mobian NetworkManager[650]: <warn>  [1695385418.8902] l3cfg[<redacted>,ifindex=4]: unable to configure IPv4 route: type unicast 0.0.0.0/0 via <redacted> dev 4 metric 700 mss 0 rt-src wwan
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [base-manager] port ttyUSB3 released by device '/sys/devices/platform/soc/1c1b000.usb/usb2/2-1'
Sep 22 14:23:38 mobian callaudiod[1020]: axp20x-battery voltage = 3504000
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [base-manager] port cdc-wdm0 released by device '/sys/devices/platform/soc/1c1b000.usb/usb2/2-1'
Sep 22 14:23:38 mobian NetworkManager[650]: <info>  [1695385418.9337] device (cdc-wdm0): state change: activated -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Sep 22 14:23:38 mobian ModemManager[739]: <info>  [base-manager] port wwan0 released by device '/sys/devices/platform/soc/1c1b000.usb/usb2/2-1'
Sep 22 14:23:38 mobian eg25-manager[633]: ModemManager object `/org/freedesktop/ModemManager1/Modem/1' removed
Sep 22 14:23:39 mobian eg25-manager[633]: Lost modem, resetting...
Sep 22 14:23:39 mobian dbus-daemon[631]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.9' (uid=0 pid=650 comm="/usr/sbin/NetworkManager --no-daemon")
Sep 22 14:23:39 mobian NetworkManager[650]: <warn>  [1695385419.1576] modem-broadband[cdc-wdm0]: failed to disconnect modem: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: Object does not exist at path “/org/freedesktop/ModemManager1/Modem/1”
Sep 22 14:23:39 mobian systemd[1]: Starting NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service...
Sep 22 14:23:39 mobian kernel: usb 2-1: new high-speed USB device number 4 using ehci-platform
Sep 22 14:23:39 mobian NetworkManager[650]: <warn>  [1695385419.2184] dns-sd-resolved[6150fb07b2a4d7c2]: send-updates SetLinkDomains@4 failed: GDBus.Error:org.freedesktop.resolve1.NoSuchLink: Link 4 not known
Sep 22 14:23:39 mobian dbus-daemon[631]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Sep 22 14:23:39 mobian systemd[1]: Started NetworkManager-dispatcher.service - Network Manager Script Dispatcher Service.
Sep 22 14:23:39 mobian kernel: usb 2-1: New USB device found, idVendor=2c7c, idProduct=0125, bcdDevice= 3.18
Sep 22 14:23:39 mobian kernel: usb 2-1: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Sep 22 14:23:39 mobian kernel: usb 2-1: Product: LTE Module
Sep 22 14:23:39 mobian kernel: usb 2-1: Manufacturer: Quectel, Incorporated
Sep 22 14:23:39 mobian kernel: usb 2-1: SerialNumber: community_fw
Sep 22 14:23:39 mobian kernel: option 2-1:1.0: GSM modem (1-port) converter detected
Sep 22 14:23:39 mobian kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB0
Sep 22 14:23:39 mobian kernel: option 2-1:1.1: GSM modem (1-port) converter detected
Sep 22 14:23:39 mobian kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB1
Sep 22 14:23:39 mobian kernel: option 2-1:1.2: GSM modem (1-port) converter detected
Sep 22 14:23:39 mobian kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB2
Sep 22 14:23:39 mobian kernel: option 2-1:1.3: GSM modem (1-port) converter detected
Sep 22 14:23:39 mobian kernel: usb 2-1: GSM modem (1-port) converter now attached to ttyUSB3
Sep 22 14:23:39 mobian kernel: qmi_wwan 2-1:1.4: cdc-wdm0: USB WDM device
Sep 22 14:23:39 mobian kernel: qmi_wwan 2-1:1.4 wwan0: register 'qmi_wwan' at usb-1c1b000.usb-1, WWAN/QMI device, <redacted>

My hacked version of eg25-manager to give extra diagnostics, in particular: https://codeberg.org/boud/eg25-manager/src/branch/extra_g_messages/src/at.c#L162

Interpretation/questions: The two lines

Sep 22 14:23:37 mobian eg25-manager[633]: Executed soft sleep sequence
Sep 22 14:23:37 mobian eg25-manager[633]: No extra work to do for soft sleep; manager->modem_state = 6

show with line 52 of manager.h https://salsa.debian.org/DebianOnMobile-team/eg25-manager/-/blob/debian/latest/src/manager.h#L52 that the soft sleep 'sequence' (really a state rather than a sequence, it seems to me) was started and the manager->modem_state was 6 == EG25_STATE_CONNECTED, // Modem is connected (data connection active). So apart from setting manager->gpio_out[GPIO_OUT_DTR] == manager->gpio_out[0] to 1, see https://salsa.debian.org/DebianOnMobile-team/eg25-manager/-/blob/debian/latest/src/gpio.c#L96, eg25-manager apparently didn't intervene any more.

The value of voltage_now changes from 14:23:06 to 14:23:38 from 3528 mV to 3520 mV to 3528 mV to 3514 mV to 3502 mV to 3504 mV. This is consistent with the hypothesis that USB disconnection events occur when voltage_now is below around 3600 mV and a sudden surge in power usage - for the ringing in sound - occurs.

Does setting manager->gpio_out[GPIO_OUT_DTR] to 1 have an effect on settings in the USB hardware? or is it just in the RAM used by eg25-manager to keep track of things?

Scrolling later in the log and grepping for voltage gives

Sep 22 14:34:42 mobian kernel: axp20x-usb-power-supply axp20x-usb-power-supply: Increasing Vbus hold voltage to 4.5V
Sep 22 14:36:25 mobian callaudiod[1029]: axp20x-battery voltage = 3930000
Sep 22 14:36:25 mobian callaudiod[1029]: axp20x-battery voltage = 3930000
Sep 22 14:36:25 mobian callaudiod[1029]: axp20x-battery voltage = 3930000
Sep 22 14:52:36 mobian callaudiod[1029]: axp20x-battery voltage = 4012000
Sep 22 14:52:36 mobian callaudiod[1029]: axp20x-battery voltage = 4012000

The first line here is presumably the kernel's method of trying to keep a nearly constant voltage.

Clarification: that first line is followed a few lines later, within the same second, by

Sep 22 14:34:42 mobian kernel: anx7688 0-0028: cable inserted

which corresponded to me plugging in the charging cable (I forgot that).

Incoming calls only: The fact that the USB modem disconnection has only been detected (by me) on incoming calls, not outgoing calls, is consistent with the hypothesis that this is related to a power issue. By default, incoming calls require power usage for the ringing sound through the speaker; outgoing calls only give a low-power ringing sound to the earpiece.

cat /sys/class/power_supply/axp20x-battery/voltage_now; fbcli --event phone-incoming-call;cat /sys/class/power_supply/axp20x-battery/voltage_now

gives me a drop of about 40-50 mV with amixer having Master at 63%, 63%.

Looks like the two main kernel files (for Mobian v6.1.52) are:

There's a warning there that AXP20x can be set up to 4360 mV but for Lithium battery safety, should better be only set up to 4200 mV max.

Should callaudiod call the axp20x_usb_power_set_voltage_min() in the kernel module axp20x_usb_power to the maximum recommended voltage before starting the ringing sound? Or at least a value well above the 3500-3600 mV range that seems to be when the USB disconnections occur?

Followup proposed as a wishlist item (or bug, depending on your point of view) to gnome-calls:

https://gitlab.gnome.org/GNOME/calls/-/issues/600

The evidence is so far only circumstantial, rather than watertight, and this issue here (213) could be a good place for listing workarounds. But if nothing changes over the next few weeks, this bug could probably be closed here. It seems unlikely that the USB disconnection is caused by the FLOSS modem software, and if the voltage explanation is correct, then there's nothing that the modem software/OS could do to prevent the disconnection, since it can't decide to use 0 volts or current for the USB connection while keeping it open, and it can't tell gnome-calls to not do a ringing sound, nor can it convince the phone kernel to ignore the low voltage.

My wishlist item at https://gitlab.gnome.org/GNOME/calls/-/issues/600 was rejected (too hacky, especially in the context of apparent long-term unsustainability of kernel patches for the OG PP - lack of kernel developers with sufficient time/motivation/skills to integrate over a hundred patches upstream to linux), so I think that it's better to keep this item open, even if it's very likely not really the fault of the modem FLOSS firmware.

An update to my comments over at gnome/calls 600 is that for a new battery (EB-BJ700CBE Galaxy J7), I've had two USB disconnections with _voltagenow just below 3800 mV, on incoming calls. This was on the second and fourth of a series of calls, within a minute or so of each other. These seem to imply an gnome/calls|callaudio bug - after a USB disconnection, the next call (maybe next few?) do not set the VoiceCall.conf alsa settings. I'm testing this hypothesis to see how best to report it as a bug...

Battery condition/voltage does seem to be a factor in the USB disconnections, but the idea of disabling ringing led to three methods that are less drastic: switch from ringing to an led flashing or to a VibraRumble - feedbackd allows three sorts of feedbacks) - or wait a million microseconds or so between the end of the ringing sound (which presumably sends current to things that make sounds) and starting the audio call (which activates things that can make sounds). Having two processes try to handle the audio parts of the SOC sounds ;) like it could be the cause of the USB disconnection.

Full details: https://gitlab.gnome.org/GNOME/calls/-/issues/605

So I'm closing this bug. Gnome-calls seems like a natural place for this to be handled. Someone else can bounce it back here if they think that it's a modem FLOSS fw issue.

the-modem-distro / pinephone_modem_sdk

kernel shuts down USB connection to modem on incoming call #213