I’ve updated to Byzantium today, and it seems that calling is now almost unusable for me. I wanted to post this here not to rant, but to see if others are experiencing similar problems and might have pointers to get this resolved or to existing related tickets I can monitor.
Minor Problems with Amber
With Amber, calling mostly worked fine. I ran into an issue yesterday with Amber where someone tried calling me, but the phone never registered someone calling - I had very good reception at the time. What’s worse, the call was never registered as missed either. I killed and restarted the modem using the hardware kill switch, after which I could properly call and receive calls again - note that the missed call was still never added to the calls overview, so if the person hadn’t told me, I wouldn’t have known at all (unfortunately this also was an important call from work, as I use the Librem professionally).
Major Problems With Byzantium
Because Byzantium was released, I figured it was time to update today since there might be fixes not being backported to Amber. I did so today, immediately started testing basic calling, and it is… abysmal, without exaggerating. It might partially be related to the fact that I live in a place where reception is generally poor, but at certain spots it usually works fine. Even so, I’d expect the GUI and software to be able to deal with that and at least stay in a consistent state. The list below shows my initial experience with Byzantium; I had two bars of reception and 4G continuously and did not move my location:
-
I started a call from my contacts list by clicking the phone icon. The GUI never switched to the calling screen. I tried tapping it a couple of times, but to no avail. Since I was calling the fixed phone in the home I was in, the phone suddenly started ringing - it was me, calling, but the Librem phone never indicated it started calling. Because of this, there was also no way to stop calling.
-
I restarted the modem and tried again, this time using the dial page. The Librem phone went to the calling screen, and my fixed phone started ringing. After four seconds, the Librem phone bailed and went back to my calls overview for some reason. The fixed phone was still ringing, mind you, again with no way to cancel the call.
-
I restarted the modem and tried calling myself from the fixed phone. It immediately went to voice mail. I tried this three times. (This could be due to bad reception, though I had proper reception according to the Librem.)
-
In one case the call never went through to my fixed phone - it never started ringing -, but I was on the calling screen on the Librem, and pressing the red phone icon to stop the call did nothing… until about a minute later, when it jumped back to the calls overview (there were errors in the logs, see also below).
-
I tried restarting the phone in the above situations too, to no avail.
-
After restarting the phone, I tried calling myself again. This time it went through. I managed to do two calls in both directions and it worked fine this time (great!).
-
I tried doing another call from another location in my home where there was slightly better reception. The call went through, but again the Librem went to the overview by itself after a couple of rings, and the fixed phone kept ringing, again with no way to cancel the call.
-
I tried that again, again after a restart of the phone, and, after picking up the fixed phone, I could hear the other person speak, but they could not hear me. They were hearing all kinds of tapping noises instead. I think these tapping noises might be noises I was making 10 minutes earlier, to test calls when I was handling both phones myself, but I’m not sure, which could indicate a sound buffer issue.
-
Even when the call went through, the Librem often did not give a ringing sound.
Maybe I flashed the wrong Byzantium? I have a Librem phone from January 2021, and I just flashed using ./scripts/librem5-flash-image --variant luks --skip-cleanup
, so I assume it selected the appropriate model. The flash also succeeded without issues.
(Obviously I don’t have the microphone killed or anything during this test.)
For some of these issues, I captured journal logs, which hopefully can be helpful to someone. I’m very happy a Linux phone exists, know some things are still WIP, but I at least expect (need) calling to be working in a somewhat stable fashion, so I’d be happy to report these to their respective projects if someone wishes me to, or to aid in debugging the issues further.
Logs 1 - Call Not Going Through, Screen Stuck
I stared a call, the Librem phone went to the calling screen:
ec 04 18:42:06 librem ModemManager[717]: <info> [modem2/call0] user request to start call
dec 04 18:42:06 librem ModemManager[717]: <info> [modem2/call0] call state changed: unknown -> dialing (outgoing-started)
dec 04 18:42:07 librem gsd-color[984]: unable to get EDID for xrandr-DSI-1: unable to get EDID for output
dec 04 18:42:18 librem ModemManager[717]: <info> [modem2] 3GPP registration state changed (home -> idle)
dec 04 18:42:18 librem ModemManager[717]: <info> [modem2] 3GPP registration state changed (idle -> registering)
dec 04 18:42:18 librem ModemManager[717]: <info> [modem2] 3GPP registration state changed (registering -> home)
dec 04 18:42:20 librem phosh[1589]: The XKEYBOARD keymap compiler (xkbcomp) reports:
dec 04 18:42:20 librem phosh[1589]: > Warning: Unsupported maximum keycode 569, clipping.
dec 04 18:42:20 librem phosh[1589]: > X11 cannot support keycodes above 255.
dec 04 18:42:20 librem phosh[1589]: Errors from xkbcomp are not fatal to the X server
dec 04 18:42:21 librem pulseaudio[777]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
dec 04 18:42:21 librem pulseaudio[777]: Most likely this is a bug in the ALSA driver 'snd_soc_simple_card'. Please report this issue to the ALSA developers.
dec 04 18:42:21 librem pulseaudio[777]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
dec 04 18:42:31 librem gnome-calls[1144]: Error starting outgoing call ModemManager call to `<NUMBER>': Tijd is verlopen
(Note the ALSA and PulseAudio errors. “Tijd is verlopen” is Dutch for “Expired”.)
The call never goes through at this point, even though the Librem pretends it’s ringing. I press the red phone icon to stop calling. It doesn’t do anything, I see this in the logs every time I press it:
<info> [modem2/call0] user request to hangup call but never happened, screen stuck
After a minute or so, the call finally stops with the following logs:
dec 04 18:43:37 librem ModemManager[717]: <warn> [modem2/call0] couldn't start call: Serial command timed out
dec 04 18:43:37 librem ModemManager[717]: <info> [modem2/call0] call state changed: dialing -> terminated (unknown)
dec 04 18:43:37 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 2 consecutive times
dec 04 18:43:40 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:42 librem ModemManager[717]: <warn> [modem2] couldn't load call list: Serial command timed out
dec 04 18:43:42 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 3 consecutive times
dec 04 18:43:42 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:43 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:43 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:43 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:43 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:44 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 4 consecutive times
dec 04 18:43:44 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:44 librem gnome-calls[1144]: Error hanging up ModemManager call to `<NUMBER>': Tijd is verlopen
dec 04 18:43:46 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 5 consecutive times
dec 04 18:43:48 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 6 consecutive times
dec 04 18:43:50 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 7 consecutive times
dec 04 18:43:52 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 8 consecutive times
dec 04 18:43:54 librem ModemManager[717]: <warn> [modem2] port ttyUSB1 timed out 9 consecutive times
dec 04 18:43:56 librem ModemManager[717]: <error> [modem2] port ttyUSB1 timed out 10 consecutive times, marking modem as invalid
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'wds' client with ID '2'
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'wds' client with ID '1'
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'voice' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'voice' client with ID '2'
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'pdc' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'pdc' client with ID '1'
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'loc' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'loc' client with ID '1'
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'uim' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'uim' client with ID '1'
dec 04 18:43:56 librem NetworkManager[500]: <info> [1638639836.0716] device (cdc-wdm0): state change: activated -> unmanaged (reason 'removed', sys-iface-state: 'removed')
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'wms' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'wms' client with ID '1'
dec 04 18:43:56 librem systemd-networkd[407]: wwan0: Link DOWN
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'nas' client with flags 'release-cid'...
dec 04 18:43:56 librem systemd-networkd[407]: wwan0: Lost carrier
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'nas' client with ID '1'
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Releasing 'dms' client with flags 'release-cid'...
dec 04 18:43:56 librem ModemManager[717]: [/dev/cdc-wdm0] Unregistered 'dms' client with ID '1'
dec 04 18:43:56 librem dbus-daemon[496]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.11' (uid=0 pid=500 comm="/usr/sbin/NetworkManager --no-daemon ")
dec 04 18:43:56 librem systemd[1]: Starting Network Manager Script Dispatcher Service...
dec 04 18:43:56 librem NetworkManager[500]: <warn> [1638639836.1511] modem-broadband[cdc-wdm0]: failed to disconnect modem: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface “org.freedesktop.ModemManager1.Modem.Simple” on object at path /org/freedesktop/ModemManager1/Modem/2
dec 04 18:43:56 librem dbus-daemon[496]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
dec 04 18:43:56 librem systemd[1]: Started Network Manager Script Dispatcher Service.
dec 04 18:43:59 librem ModemManager[717]: transaction 0x10 aborted, but message is not abortable
dec 04 18:43:59 librem ModemManager[717]: transaction 0x11 aborted, but message is not abortable
dec 04 18:43:59 librem ModemManager[717]: transaction 0x12 aborted, but message is not abortable
dec 04 18:43:59 librem ModemManager[717]: transaction 0x13 aborted, but message is not abortable
dec 04 18:43:59 librem ModemManager[717]: transaction 0x14 aborted, but message is not abortable
dec 04 18:43:59 librem ModemManager[717]: transaction 0x15 aborted, but message is not abortable
dec 04 18:43:59 librem ModemManager[717]: transaction 0x16 aborted, but message is not abortable
dec 04 18:43:59 librem ModemManager[717]: transaction 0x17 aborted, but message is not abortable
Logs 2 - PulseAudio Errors
During some calls, when I was not talking, a large amount of PulseAudio errors were being spammed:
98]: unable to get EDID for xrandr-DSI-1: unable to get EDID for output
dec 04 18:54:34 librem pulseaudio[772]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
dec 04 18:54:34 librem pulseaudio[772]: Most likely this is a bug in the ALSA driver 'snd_soc_simple_card'. Please report this issue to the ALSA developers.
dec 04 18:54:34 librem pulseaudio[772]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
dec 04 18:54:36 librem ModemManager[593]: <info> [modem0/call0] user request to accept call
dec 04 18:54:36 librem ModemManager[593]: <warn> [modem0] unexpected incoming call to number 'n/a' reported in call list: state active
dec 04 18:54:36 librem ModemManager[593]: <info> [modem0/call0] call is accepted
dec 04 18:54:36 librem ModemManager[593]: <info> [modem0/call0] call state changed: ringing-in -> active (accepted)
dec 04 18:54:36 librem pulseaudio[772]: Configured maximum latency is smaller than latency, using latency instead
dec 04 18:54:36 librem pulseaudio[772]: Cannot set requested sink latency of 50,00 ms, adjusting to 100,00 ms
dec 04 18:54:36 librem pulseaudio[772]: Cannot set requested source latency of 50,00 ms, adjusting to 100,00 ms
dec 04 18:54:36 librem pulseaudio[772]: Configured maximum latency is smaller than latency, using latency instead
dec 04 18:54:36 librem pulseaudio[772]: Cannot set requested sink latency of 50,00 ms, adjusting to 100,00 ms
dec 04 18:54:36 librem pulseaudio[772]: Cannot set requested source latency of 50,00 ms, adjusting to 100,00 ms
dec 04 18:54:36 librem pulseaudio[772]: Doing resync
dec 04 18:54:36 librem pulseaudio[772]: Playback after capture (-72845), drop sink 28048
dec 04 18:54:36 librem pulseaudio[772]: Configured latency of 200,00 ms is smaller than minimum latency, using minimum instead
dec 04 18:54:36 librem pulseaudio[772]: ALSA woke us up to read new data from the device, but there was actually nothing to read.
dec 04 18:54:36 librem pulseaudio[772]: Most likely this is a bug in the ALSA driver 'snd_soc_simple_card'. Please report this issue to the ALSA developers.
dec 04 18:54:36 librem pulseaudio[772]: Cannot set requested source latency of 60,75 ms, adjusting to 100,00 ms
dec 04 18:54:36 librem pulseaudio[772]: We were woken up with POLLIN set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
dec 04 18:54:36 librem pulseaudio[772]: Cannot set requested sink latency of 50,00 ms, adjusting to 100,00 ms
dec 04 18:54:36 librem callaudiod[968]: no available input found!
dec 04 18:54:36 librem callaudiod[968]: no available output found!
dec 04 18:54:36 librem callaudiod[968]: no available input found!
dec 04 18:54:36 librem pulseaudio[772]: Doing resync
dec 04 18:54:36 librem pulseaudio[772]: Playback too far ahead (1138), drop source 216
dec 04 18:54:37 librem pulseaudio[772]: Playback too far ahead (76176), drop source 14624
dec 04 18:54:38 librem pulseaudio[772]: Playback too far ahead (32204), drop source 6180
dec 04 18:54:39 librem pulseaudio[772]: Playback too far ahead (8162), drop source 1564
dec 04 18:54:40 librem pulseaudio[772]: Playback too far ahead (7195), drop source 1380
dec 04 18:54:41 librem pulseaudio[772]: Playback too far ahead (7789), drop source 1492
dec 04 18:54:42 librem pulseaudio[772]: Playback too far ahead (7978), drop source 1528
dec 04 18:54:43 librem pulseaudio[772]: Playback too far ahead (8395), drop source 1608
dec 04 18:54:44 librem pulseaudio[772]: Playback too far ahead (7814), drop source 1500
dec 04 18:54:45 librem pulseaudio[772]: Playback too far ahead (6930), drop source 1328
dec 04 18:54:46 librem pulseaudio[772]: Playback too far ahead (6205), drop source 1188
dec 04 18:54:47 librem pulseaudio[772]: Playback too far ahead (8064), drop source 1548
dec 04 18:54:48 librem pulseaudio[772]: Playback too far ahead (9949), drop source 1908
dec 04 18:54:49 librem pulseaudio[772]: Playback too far ahead (10102), drop source 1936
dec 04 18:54:50 librem pulseaudio[772]: Playback too far ahead (10147), drop source 1948
dec 04 18:54:51 librem pulseaudio[772]: Playback too far ahead (9986), drop source 1916
dec 04 18:54:52 librem pulseaudio[772]: Playback too far ahead (10082), drop source 1932
dec 04 18:54:53 librem pulseaudio[772]: Playback too far ahead (9918), drop source 1904
Logs 3 - ModemManager Errors
Scrolling through the logs of all my testing, I also see quite a few of these warnings passing by:
dec 04 19:07:56 librem gnome-calls[1165]: Error starting outgoing call ModemManager call to `<PHONE NUMBER>': GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Failed: Couldn't start the call: Unhandled response '$GNGNS,,,,,, <TRUNCATED>
dec 04 19:07:54 librem ModemManager[593]: <info> [modem1/call2] call state changed: dialing -> terminated (unknown)
dec 04 19:07:56 librem gnome-calls[1165]: Error starting outgoing call ModemManager call to `<PHONE NUMBER>': GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Failed: Couldn't start the call: Unhandled response '$GNGNS,,,,,, <TRUNCATED>
dec 04 19:07:54 librem ModemManager[593]: <info> [modem1/call2] call state changed: unknown -> dialing (outgoing-started)
dec 04 19:07:54 librem ModemManager[593]: <info> [modem1/call2] user request to start call
I didn’t post the entire response, as I’m not sure if it contains private information or not, but it’s a fairly long response that seems to be delimited by markers such as $GPVTG
, $GNGNS
, and so on. It seems that it’s not able to parse some response sent back by the operator or something, but I don’t know enough about the subject to be sure.
Logs 4 - Errors During Idle
Whilst leaving the phone idle for over an hour, with cellular reception on, I see large amounts of the following errors logged:
dec 04 20:26:11 librem kernel: dwc3 38100000.usb: request 00000000c8eeeff1 was not queued to ep1in
dec 04 20:26:11 librem kernel: dwc3 38100000.usb: failed to send remote wakeup
dec 04 20:26:10 librem kernel: dwc3 38100000.usb: request 00000000c8eeeff1 was not queued to ep1in
dec 04 20:26:04 librem kernel: dwc3 38100000.usb: request 00000000c8eeeff1 was not queued to ep1in
dec 04 20:25:59 librem kernel: dwc3 38100000.usb: failed to send remote wakeup
dec 04 20:25:59 librem kernel: dwc3 38100000.usb: request 00000000c8eeeff1 was not queued to ep1in
dec 04 20:25:54 librem kernel: dwc3 38100000.usb: failed to send remote wakeup
dec 04 20:25:53 librem kernel: dwc3 38100000.usb: request 00000000c8eeeff1 was not queued to ep1in
dec 04 20:25:48 librem kernel: dwc3 38100000.usb: failed to send remote wakeup
dec 04 20:25:47 librem kernel: dwc3 38100000.usb: request 00000000c8eeeff1 was not queued to ep1in
dec 04 20:25:42 librem kernel: dwc3 38100000.usb: failed to send remote wakeup
dec 04 20:25:42 librem kernel: dwc3 38100000.usb: request 00000000c8eeeff1 was not queued to ep1in
dec 04 20:25:36 librem kernel: dwc3 38100000.usb: request 00000000607799dd was not queued to ep1in
They’re usually about 10 seconds apart.