After having closed all applications and then having selected "Power Off..." in the menu, sometimes a dialog pops up saying this:
"Some applications are busy or have unsaved work", "Unknown application"
Two problems:
Questions:
The dialog works properly in other cases, for example if I have the text editor open with some unsaved text, then the dialog properly shows that, and the application name "Text Editor" is shown properly in that case.
This is on a Librem 5 running the default PureOS byzantium, current phosh version is 0.32.0-1pureos1~byz1.
@martin.kepplinger I tested echo 'on' | sudo tee /sys/bus/usb/devices/1-1.2/power/control
and can confirm that the error does not appear then.
I also did some more testing and found out the following. As described earlier, when this issue has been triggered the behavior is that network packets can be sent from the L5 to the outside world, but no incoming packets seem to arrive.
It is possible to see more details about what is happening via some counters:
mmcli -m any
will show which bearers exist, one of them will be the one that is actually used and information for that specific bearer can be shown using mmcli -m any -b x
with x being the bearer number.
The information shown then includes a "Statistics" part, with counters called "bytes rx" and "bytes tx". Example:
purism@pureos:~$ sudo mmcli -m 2 -b 4
[...]
------------------------------------
Statistics | duration: 2400
| bytes rx: 38934
| bytes tx: 5692
| attempts: 1
| total-duration: 2400
| total-bytes rx: 38934
| total-bytes tx: 5692
When looking at those values and comparing them over time, be aware that the information is only updated once every 300 seconds, you can see that from when the "duration" value changes. (I assume that is because ModemManager fetches the information from the modem once every 300 seconds.) So the values might appear constant, but wait 300 seconds and you will see them changing.
I did tests in the following way, after the error had happened:
Interestingly, such a test shows that both tx and rx counters are actually increasing, with amounts corresponding to the ping packets.
But the received (rx) packets have not reached the Linux kernel, which can be seen by observing the counters under /sys/
here:
cat /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2/1-1.2:1.4/net/wwan0/statistics/rx_packets
cat /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2/1-1.2:1.4/net/wwan0/statistics/tx_packets
(or rx_bytes
and tx_bytes
if you want)
Based on this, I think what happens is the following:
Normal (working) condition:
ping request sent
|
|
Linux kernel sends packet
|
|
modem receives packet from kernel and sends it out
|
|
outside world answers with ping reply
|
|
modem receives packet and sends it to kernel
|
|
Linux kernel receives ping reply packet
|
|
OK ping reply received
After error happened:
ping request sent
|
|
Linux kernel sends packet
|
|
modem receives packet from kernel and sends it out
|
|
outside world answers with ping reply
|
|
modem receives packet and sends it to kernel
|
| ERROR HERE, KERNEL DOES NOT RECEIVE PACKET
|
Linux kernel does not receive ping reply packet
I guess the communication between the kernel and the modem is handled by the cdc-wdm driver in https://source.puri.sm/Librem5/linux/-/blob/pureos/latest/drivers/usb/class/cdc-wdm.c -- maybe that is where something goes wrong.
What could explain why communication works in one direction but not the other?
Is it possible to somehow probe the current status of the connection created by the cdc-wdm driver? To ask "is this connection alive?", regarding the USB connection between the kernel and the modem?
Maybe increasing autosuspend_delay_ms
to a larger value than 500 milliseconds can help as a workaround. See discussion in #328 - #328 (comment 249432)
@janvlug @primalmotion thanks for testing!
Based on that the problem seems related to USB suspend behavior, I tested the following change which seems to help.
There is a parameter that says how long time the device needs to be idle before the kernel will consider suspending the device. I think the default value is set by a udev rule here:
where autosuspend_delay_ms
is set to 500 milliseconds.
This means fairly aggressive suspend behavior, the kernel will try to suspend the device already after half a second.
The value can be accessed at a specific path somewhere under /sys/devices/
, to be exact the value seems to be here:
/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2/power/autosuspend_delay_ms
So to check the current value we can do
$ cat /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2/power/autosuspend_delay_ms
500
and to set another value we can do (as root)
echo 5000 > /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2/power/autosuspend_delay_ms
I tried with the value 5000 (so, 5 seconds instead of the default 0.5 seconds) and with the value 5000 the error does not seem to appear any longer. Tested some other values as well and it seems like the error goes away if the value is set to at least 1000.
I suppose it should work with any value, and the reason we get problems for the value 500 is some bug(s) somewhere. As a workaround, using a larger value seems to help a lot, at least in my tests I have not seen the error happen even a single time when the value has been set to 5000.
Of course, using a larger value means spending less time suspended, so it could affect battery life. But if there are longer idle times we will still get the suspend happening, for example with the value 5000, if there is 30 seconds of idle time then suspend will happen after 5 seconds and then it will be suspended for 25 seconds so you still get suspend the majority of the time. Of course that will depend on network activity, what programs are running and what they are doing. Anyway I did not notice any difference regarding battery life (there could be a difference, I did not try to measure that carefully).
@sebastian.krzyszkowiak it looks like you commited changes affecting that autosuspend_delay_ms
value before, would you agree that is seems like a good idea to increase it from 500 to something larger, maybe back to 2000 as it was earlier, or maybe even 5000? (I have no idea what exact value is best, but it does seem like 500 is too small)
@trescott2000 thanks for the idea. I checked memory usage when this happened, and there was no problem with that, lots of memory available.
I found a way to reproduce the issue, by using a wget
command with the --limit-rate
option, like this:
wget --limit-rate=5k http://example.org/some_large_file_from_internet.tar.gz
(replace the http://example.org/... url with some file available to download)
The wget
command shows progress while downloading the file, and it shows the current download speed. First it will show "5.00KB/s
" for a while, then suddenly the speed will start to drop and the download will stall, after a while wget will give up. The problem does not appear immediately, it often takes 10-20 minutes, but rarely more than 30 minutes.
The --limit-rate
value is important, setting it too high means the error does not appear at all. I tested several times with --limit-rate=20k
and then the error never appeared. Using either --limit-rate=5k
or --limit-rate=10k
makes the problem appear, but apparently 20k is too much.
I don't (yet) know the reason but a theory is that this has something to do with Linux USB suspend functionality, at least that would explain why the problem does not appear for high download rate because then presumably there is a steady stream of packets so that suspend does not happen. A lower download speed means longer time between packets, and more likely for suspend to happen in the idle time between packets.
The last few days, the apt update
command on my Librem 5 says: "Could not connect to repo.pureos.net:443
"
Is something wrong with the repo.pureos.net server?
Librem 5 running PureOS.
It happens quite often (maybe about once a day on average) that the mobile data connection suddenly stops working, while calls and SMS still work.
Mobile data seems to stop working while it is being used, for example today I was playing a video clip on a web page in Firefox and that video suddenly stopped playing, because mobile data had stopped working.
Trying to find out what goes wrong I have looked at mmcli -m any
and also mmcli -m any -b x
with x being bearer number, and things look normal there. As far as I can tell there is no error indication anywhere. Also nmcli con show
shows the connection as working, and ip route
and ip addr
output looks normal, it looks the same as when things are working. So both ModemManager and NetworkManager seem to think that everything is fine. But things are not fine, I can no longer communicate using the mobile data connection.
Trying to ping something in the outside world fails, but when I tried pinging my own server I could see the ping request packets from the Librem 5 arriving at the server, and the server sent an echo reply packet back each time. So in this situation the Librem 5 can send ping request packets, but the replies to not arrive. So the mobile data connection is not totally broken, it works in the outgoing direction but not in the incoming direction.
Trying to ping the gateway IP also fails. (Pinging the phone's own IP works though.)
Doing mmcli -m any --reset
followed by service NetworkManager restart
makes things work again.
Ideas on how to troubleshoot this further? One thing that would be interesting it to get some more low-level info from the kernel driver(s) involved, to see if there is any activity at all when incoming packets arrive.
Could it be related to suspend functionality?
@mohammed.sadiq thanks, I can see the account in seahorse
and I can delete it from there. After deleting using seahorse the account is really gone, it does not reappear after reboot.
However, trying to delete from inside chatty sometimes fails. Earlier it seemed to always fail but the last time I tried it succeeded. The scenario when it failed was when there were duplicate accounts as described in #804 -- maybe the account deletion from inside chatty gets confused when there are duplicate accounts? I will try to test it some more to figure out what happens.
This seems related to that in DNS there is a CNAME record for the matrix homeserver name in this case, giving a different name, and for some reason chatty creates accounts for both names in the keychain.
The homeserver name I entered is on the form matrix.mydomain.se
and for that name there is a CNAME record pointing to matrix-01.mydomain.se
so doing nslookup for matrix.mydomain.se
gives something like the following:
$ nslookup matrix.mydomain.se
[...]
matrix.mydomain.se canonical name = matrix-01.mydomain.se.
Name: matrix-01.mydomain.se
Seahorse shows both in the keychain, one entry for matrix.mydomain.se
and another entry for matrix-01.mydomain.se
(with the same username and password for both, only the homeserver info differs). After reboot, chatty apparently finds both of them and treats them as two separate accounts, even though they are in reality the same account.
To solve this, I guess that chatty would need to decide to use one of the two names and just add that one to the keychain, instead of adding both of them.
This is on a Librem 5 running PureOS byzantium with chatty (Chats) 0.7.2.
Deleting a matrix account (using the "Delete Account" button after selecting the account in Preferences) seems to work at first, the deleted account is no longer listed under "Accounts" in Preferences. However, after reboot the account appears again.
I tried to figure out in which file the account information is stored, I thought it was in /home/purism/.purple/chatty/db/matrix.db
but even if I kill chatty (twice) and then delete that file, the account still appears again the next time chatty is started, and then the file is recreated. Where is the account info stored, and is there a way to forcibly delete some file(s) to workaround the account deletion problem?
This is on a Librem 5 running PureOS byzantium with chatty (Chats) 0.7.2.
Creating a matrix account works at first, after creating it there is one account shown under "Accounts" in Preferences, as expected.
However, after rebooting the phone there are suddenly two almost identical accounts. Checking "Advanced information" for each of them shows that they have different "Device ID", but the Homeserver and Matrix ID info is identical for the two accounts.
I added a /etc/apt/sources.list.d/debug.list
file as described in developer.puri.sm#181 hoping that this would let me install *-dbgsym packages with debug symbols, to see more useful info from stack traces, coredumps etc.
So my /etc/apt/sources.list.d/debug.list file looks as follows:
root@pureos:~# cat /etc/apt/sources.list.d/debug.list
deb https://repo.pureos.net/pureos-debug/ byzantium-debug main
deb https://repo.pureos.net/pureos-debug/ landing-debug main
deb http://debug.mirrors.debian.org/debian-debug/ bullseye-debug main
and I ran apt update
after adding that file.
But it does not work; there are *-dbgsym packages, but trying to install them fails due to dependency problems.
Example:
root@pureos:~# apt install modemmanager-dbgsym
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
Some packages could not be installed. This may mean that you have
requested an impossible situation or if you are using the unstable
distribution that some required packages have not yet been created
or been moved out of Incoming.
The following information may help to resolve the situation:
The following packages have unmet dependencies:
modemmanager-dbgsym : Depends: modemmanager (= 1.18.6-1pureos4) but 1.18.6-1pureos3 is to be installed
E: Unable to correct problems, you have held broken packages.
root@pureos:~#
There are two variants of the package:
root@pureos:~# apt list -a modemmanager-dbgsym
Listing... Done
modemmanager-dbgsym/landing-debug 1.18.6-1pureos4 arm64
modemmanager-dbgsym/stable-debug 1.14.12-0.2 arm64
But neither of them can be installed:
root@pureos:~# apt install modemmanager-dbgsym/landing-debug
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
Selected version '1.18.6-1pureos4' (PureOS Debug:landing-debug [arm64]) for 'modemmanager-dbgsym'
Some packages could not be installed. This may mean that you have
requested an impossible situation or if you are using the unstable
distribution that some required packages have not yet been created
or been moved out of Incoming.
The following information may help to resolve the situation:
The following packages have unmet dependencies:
modemmanager-dbgsym : Depends: modemmanager (= 1.18.6-1pureos4) but 1.18.6-1pureos3 is to be installed
E: Unable to correct problems, you have held broken packages.
root@pureos:~# apt install modemmanager-dbgsym/stable-debug
Reading package lists... Done
Building dependency tree... Done
Reading state information... Done
Selected version '1.14.12-0.2' (Debian debug:11.7/stable-debug [arm64]) for 'modemmanager-dbgsym'
Some packages could not be installed. This may mean that you have
requested an impossible situation or if you are using the unstable
distribution that some required packages have not yet been created
or been moved out of Incoming.
The following information may help to resolve the situation:
The following packages have unmet dependencies:
modemmanager-dbgsym : Depends: modemmanager (= 1.14.12-0.2) but 1.18.6-1pureos3 is to be installed
E: Unable to correct problems, you have held broken packages.
root@pureos:~#
What to do, how to make this work?
I get lots of assertion failures like this:
apr 29 08:34:09 pureos chatty[1107]: gst_element_message_full_with_details: assertion 'GST_IS_ELEMENT (element)' failed
apr 29 08:34:09 pureos chatty[1107]: gst_element_message_full_with_details: assertion 'GST_IS_ELEMENT (element)' failed
This is reproducible: if I reboot and open chatty, those assertion failures appear again.
Librem 5 running PureOS and chatty version 0.7.2.
Trying to understans more what happens.
Looks like there are three USB hubs on the Librem 5:
purism@pureos:~$ sudo journalctl -b | grep "hub found"
Jan 26 04:46:44 pureos kernel: hub 1-0:1.0: USB hub found
Jan 26 04:46:44 pureos kernel: hub 2-0:1.0: USB hub found
Jan 26 04:46:44 pureos kernel: hub 1-1:1.0: USB hub found
and two of those hubs are involved regarding the modem. The modem seems to be connected as follows:
host
|
hub 1-0:1.0 <-- root hub
|
usb 1-1 <-- port having hub 1-0:1.0 as its parent
|
hub 1-1:1.0 <-- non-root hub
|
usb 1-1.2 <-- port having hub 1-1:1.0 as its parent
|
qmi_wwan 1-1.2:1.4 <-- the modem
In the normal runtime suspend-resume case, when everything gets suspended and then resumed again, things happen in the following order:
qmi_wwan 1-1.2:1.4: qmi_wwan_suspend()
usb 1-1.2: usb_port_suspend()
hub 1-1:1.0: hub_suspend()
usb 1-1: usb_port_suspend()
hub 1-0:1.0: hub_suspend()
xhci-hcd xhci-hcd.4.auto: xhci_bus_suspend()
(at this point everything is suspended)
(now resume starts)
xhci-hcd xhci-hcd.4.auto: xhci_bus_resume()
hub 1-0:1.0: hub_resume()
usb 1-1: usb_port_resume() -- parent hub is hub 1-0:1.0
hub 1-1:1.0: hub_resume()
usb 1-1.2: usb_port_resume() -- parent hub is hub 1-1:1.0
qmi_wwan 1-1.2:1.4: qmi_wwan_resume()
When things happen as above it seems there is never any problem.
Then there are also cases when things start to suspend but it does not go all the way to the root hub, as follows:
qmi_wwan 1-1.2:1.4: qmi_wwan_suspend()
usb 1-1.2: usb_port_suspend()
hub 1-1:1.0: hub_suspend()
usb 1-1: This is usb_port_suspend()
(now normally the next step would be hub_suspend() for hub 1-0:1.0 but that does not happen, instead resume starts now)
usb 1-1: usb_port_resume()
hub 1-1:1.0: hub_resume()
usb 1-1.2: usb_port_resume()
qmi_wwan 1-1.2:1.4: qmi_wwan_resume()
That shorter path sometimes works, but sometimes it fails giving the "usb 1-1.2: reset high-speed USB device" problem.
So, in the normal (always working) case there is a rather long chain of things being suspended in order, and then each of them is resumed in reverse order. It seems like the troublesome case is when the suspend procedure gets interrupted halfway through the chain, some things were suspended but not yet the root hub.
Would it be possible to simplify things by connecting the modem directly to the root hub, to have only one hub involved instead of two?
@sebastian.krzyszkowiak thanks a lot for explaining. You don't think it could happen that when Linux just wants to suspends the USB link to the modem, the modem interprets that as a request to suspend the modem as a whole?
Anyway, an interesting experiment would be to turn off runtime suspend functionality for the USB link (so that it is always on, echo on > /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2/power/control
would be a way to do it I think) and then see if phonecall problems still happen.
Strange. For me, Wifi Hotspot works fine on the Librem 5, I have used it many times.
A theory: it could be that your mobile provider is doing something unusual that triggers this problem. To check that, you could try with a different SIM card, from a different provider. (the behavior you see could be explained, maybe, if the provider has some limitation on the number of TCP connections to the same destination or something like that)
You could also look at the traffic to and from the Librem 5 by running tcpdump
or tshark
or similar on the Librem 5. Then you might see some ICMP error packets or something else that could give clues.
Regarding which websites work and which don't work: could it be that the ones that work are ones you did not yet try from the Librem 5 itself? Like, the first N connections to a given destination succeeds and later connections to that destination fail? I guess that could happen if there is a limit on the number of allowed connections.
What's the issue there?
Hm, perhaps there is no issue other than me not understanding things.
I was under the impression that the modem is a USB device which can be suspended via the "runtime suspend" functionality in the kernel, and I thought that when the modem was suspended a phonecall could not work. I guess I was wrong, but then, what does it mean when the modem is suspended?
Is the modem a USB device or not? Should it be seen as two separate devices, one USB device that can be suspended, and at the same time another device that has nothing to do with USB? If so, which is the other device, is there another driver (not USB but other kind) for that somewhere?
Suppose there is a phonecall ongoing, and the USB runtime suspend happens, with the phonecall still ongoing. How does the audio data travel between the modem and the CPU, if not via the USB link?
I'm sorry if those are stupid questions.
(In defense of this issue being created, I think the runtime suspend/resume happening so many times during a phonecall probably increases the risk that the modem gets lost during a call so that you cannot hangup, you might close Calls but the phonecall is still active, things like that. As the runtime suspend/resume is buggy, perhaps it would make sense to avoid it during an active phonecall at least.)
This came up while trying different things related to modem "runtime suspend", related to #303
Using the current pureos/byzantium branch with the following dev_info() calls added in order to see when runtime suspend/resume happens:
dev_info(&intf->dev, "This is qmi_wwan_suspend()\n");
dev_info(&intf->dev, "This is qmi_wwan_resume()\n");
dev_info(&udev->dev, "This is usb_port_suspend()\n");
dev_info(&udev->dev, "This is usb_port_resume()\n");
Those calls were added in the following places in the code, in drivers/net/usb/qmi_wwan.c and drivers/usb/core/hub.c:
diff --git a/drivers/net/usb/qmi_wwan.c b/drivers/net/usb/qmi_wwan.c
index 554d4e2a84a4..14885e055447 100644
--- a/drivers/net/usb/qmi_wwan.c
+++ b/drivers/net/usb/qmi_wwan.c
@@ -889,6 +889,7 @@ static int qmi_wwan_suspend(struct usb_interface *intf, pm_message_t message)
struct usbnet *dev = usb_get_intfdata(intf);
struct qmi_wwan_state *info = (void *)&dev->data;
int ret;
+ dev_info(&intf->dev, "This is qmi_wwan_suspend()\n");
/* Both usbnet_suspend() and subdriver->suspend() MUST return 0
* in system sleep context, otherwise, the resume callback has
@@ -911,6 +912,7 @@ static int qmi_wwan_resume(struct usb_interface *intf)
{
struct usbnet *dev = usb_get_intfdata(intf);
struct qmi_wwan_state *info = (void *)&dev->data;
+ dev_info(&intf->dev, "This is qmi_wwan_resume()\n");
int ret = 0;
bool callsub = (intf == info->control && info->subdriver &&
info->subdriver->resume);
diff --git a/drivers/usb/core/hub.c b/drivers/usb/core/hub.c
index 4c31872321ea..bda1b7ddaeeb 100644
--- a/drivers/usb/core/hub.c
+++ b/drivers/usb/core/hub.c
@@ -3364,6 +3364,7 @@ int usb_port_suspend(struct usb_device *udev, pm_message_t msg)
int port1 = udev->portnum;
int status;
bool really_suspend = true;
+ dev_info(&udev->dev, "This is usb_port_suspend()\n");
usb_lock_port(port_dev);
@@ -3656,6 +3657,7 @@ int usb_port_resume(struct usb_device *udev, pm_message_t msg)
int port1 = udev->portnum;
int status;
u16 portchange, portstatus;
+ dev_info(&udev->dev, "This is usb_port_resume()\n");
if (!test_and_set_bit(port1, hub->child_usage_bits)) {
status = pm_runtime_resume_and_get(&port_dev->dev);
So only those calls for extra logging, nothing else changed. With those changes, journalctl shows log messages each time those suspend and resume functions are called.
To my surprise, when a phonecall is ongoing, suspend and resume calls still happen, during the phonecall.
Example:
Jan 22 16:41:44 pureos ModemManager[804]: <info> [modem0/call0] call state changed: unknown -> ringing-in (incoming-new)
Jan 22 16:41:44 pureos gsd-color[1545]: unable to get EDID for xrandr-DSI-1: unable to get EDID for output
Jan 22 16:41:44 pureos pulseaudio[858]: ALSA woke us up to write new data to the device, but there was actually nothing to write.
Jan 22 16:41:44 pureos pulseaudio[858]: Most likely this is a bug in the ALSA driver 'snd_soc_simple_card'. Please report this issue to the ALSA developers.
Jan 22 16:41:44 pureos pulseaudio[858]: We were woken up with POLLOUT set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Jan 22 16:41:45 pureos phosh[2652]: The XKEYBOARD keymap compiler (xkbcomp) reports:
Jan 22 16:41:45 pureos phosh[2652]: > Warning: Unsupported maximum keycode 569, clipping.
Jan 22 16:41:45 pureos phosh[2652]: > X11 cannot support keycodes above 255.
Jan 22 16:41:45 pureos phosh[2652]: Errors from xkbcomp are not fatal to the X server
Jan 22 16:41:46 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_suspend()
Jan 22 16:41:46 pureos kernel: usb 1-1.2: This is usb_port_suspend()
Jan 22 16:41:46 pureos kernel: usb 1-1: This is usb_port_suspend()
Jan 22 16:41:48 pureos ModemManager[804]: <info> [modem0/call0] user request to accept call
Jan 22 16:41:48 pureos kernel: usb 1-1: This is usb_port_resume()
Jan 22 16:41:48 pureos kernel: usb 1-1.2: This is usb_port_resume()
Jan 22 16:41:48 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_resume()
Jan 22 16:41:48 pureos ModemManager[804]: <info> [modem0/call0] call is accepted
Jan 22 16:41:48 pureos ModemManager[804]: <info> [modem0/call0] call state changed: ringing-in -> active (accepted)
Jan 22 16:41:48 pureos pulseaudio[858]: Configured maximum latency is smaller than latency, using latency instead
Jan 22 16:41:48 pureos pulseaudio[858]: Cannot set requested sink latency of 66.67 ms, adjusting to 32.00 ms
Jan 22 16:41:48 pureos pulseaudio[858]: Cannot set requested source latency of 66.67 ms, adjusting to 32.00 ms
Jan 22 16:41:48 pureos pulseaudio[858]: Configured maximum latency is smaller than latency, using latency instead
Jan 22 16:41:48 pureos pulseaudio[858]: Cannot set requested sink latency of 66.67 ms, adjusting to 32.00 ms
Jan 22 16:41:48 pureos pulseaudio[858]: Cannot set requested source latency of 66.67 ms, adjusting to 32.00 ms
Jan 22 16:41:48 pureos pulseaudio[858]: Cannot set requested source latency of 66.67 ms, adjusting to 32.00 ms
Jan 22 16:41:48 pureos pulseaudio[858]: Cannot set requested sink latency of 66.67 ms, adjusting to 32.00 ms
Jan 22 16:41:48 pureos pulseaudio[858]: Doing resync
Jan 22 16:41:48 pureos pulseaudio[858]: Playback after capture (-14192), drop sink 5528
Jan 22 16:41:48 pureos pulseaudio[858]: ALSA woke us up to read new data from the device, but there was actually nothing to read.
Jan 22 16:41:48 pureos pulseaudio[858]: Most likely this is a bug in the ALSA driver 'snd_soc_simple_card'. Please report this issue to the ALSA developers.
Jan 22 16:41:48 pureos pulseaudio[858]: We were woken up with POLLIN set -- however a subsequent snd_pcm_avail() returned 0 or another value < min_avail.
Jan 22 16:41:48 pureos pulseaudio[858]: Doing resync
Jan 22 16:41:48 pureos pulseaudio[858]: Playback too far ahead (466), drop source 88
Jan 22 16:41:49 pureos pulseaudio[858]: Playback too far ahead (17501), drop source 3360
Jan 22 16:41:50 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_suspend()
Jan 22 16:41:50 pureos kernel: usb 1-1.2: This is usb_port_suspend()
Jan 22 16:41:50 pureos pulseaudio[858]: Playback too far ahead (34308), drop source 6584
Jan 22 16:41:50 pureos kernel: usb 1-1: This is usb_port_suspend()
Jan 22 16:41:51 pureos pulseaudio[858]: Playback too far ahead (10116), drop source 1940
Jan 22 16:41:52 pureos pulseaudio[858]: Playback too far ahead (8912), drop source 1708
Jan 22 16:41:53 pureos pulseaudio[858]: Playback too far ahead (8914), drop source 1708
Jan 22 16:41:54 pureos pulseaudio[858]: Playback too far ahead (8500), drop source 1632
Jan 22 16:41:55 pureos kernel: usb 1-1: This is usb_port_resume()
Jan 22 16:41:55 pureos pulseaudio[858]: Playback too far ahead (9232), drop source 1772
Jan 22 16:41:55 pureos kernel: usb 1-1.2: This is usb_port_resume()
Jan 22 16:41:55 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_resume()
Jan 22 16:41:56 pureos pulseaudio[858]: Playback too far ahead (7723), drop source 1480
Jan 22 16:41:57 pureos pulseaudio[858]: Playback too far ahead (6893), drop source 1320
Jan 22 16:41:57 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_suspend()
Jan 22 16:41:57 pureos kernel: usb 1-1.2: This is usb_port_suspend()
Jan 22 16:41:58 pureos kernel: usb 1-1: This is usb_port_suspend()
Jan 22 16:41:58 pureos pulseaudio[858]: Playback too far ahead (6015), drop source 1152
Jan 22 16:41:59 pureos pulseaudio[858]: Playback too far ahead (8041), drop source 1540
Jan 22 16:42:00 pureos pulseaudio[858]: Playback too far ahead (9883), drop source 1896
Jan 22 16:42:01 pureos kernel: usb 1-1: This is usb_port_resume()
Jan 22 16:42:01 pureos pulseaudio[858]: Playback too far ahead (10297), drop source 1976
Jan 22 16:42:01 pureos kernel: usb 1-1.2: This is usb_port_resume()
Jan 22 16:42:01 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_resume()
Jan 22 16:42:02 pureos pulseaudio[858]: Playback too far ahead (9963), drop source 1912
Jan 22 16:42:03 pureos pulseaudio[858]: Playback too far ahead (9986), drop source 1916
Jan 22 16:42:03 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_suspend()
Jan 22 16:42:03 pureos kernel: usb 1-1.2: This is usb_port_suspend()
Jan 22 16:42:04 pureos kernel: usb 1-1: This is usb_port_suspend()
Jan 22 16:42:04 pureos pulseaudio[858]: Playback too far ahead (10255), drop source 1968
Jan 22 16:42:05 pureos pulseaudio[858]: Playback too far ahead (10031), drop source 1924
Jan 22 16:42:06 pureos pulseaudio[858]: Playback too far ahead (9927), drop source 1904
Jan 22 16:42:07 pureos pulseaudio[858]: Playback too far ahead (10170), drop source 1952
Jan 22 16:42:08 pureos pulseaudio[858]: Playback too far ahead (9819), drop source 1884
Jan 22 16:42:09 pureos pulseaudio[858]: Playback too far ahead (9690), drop source 1860
Jan 22 16:42:10 pureos pulseaudio[858]: Playback too far ahead (9979), drop source 1912
Jan 22 16:42:11 pureos pulseaudio[858]: Playback too far ahead (9768), drop source 1872
Jan 22 16:42:12 pureos pulseaudio[858]: Playback too far ahead (10451), drop source 2004
Jan 22 16:42:13 pureos pulseaudio[858]: Playback too far ahead (9863), drop source 1892
Jan 22 16:42:14 pureos pulseaudio[858]: Playback too far ahead (9876), drop source 1896
Jan 22 16:42:15 pureos pulseaudio[858]: Playback too far ahead (10086), drop source 1936
Jan 22 16:42:16 pureos pulseaudio[858]: Playback too far ahead (10003), drop source 1920
Jan 22 16:42:18 pureos pulseaudio[858]: Playback after capture (-55), drop sink 96
Jan 22 16:42:26 pureos kernel: usb 1-1: This is usb_port_resume()
Jan 22 16:42:27 pureos kernel: usb 1-1.2: This is usb_port_resume()
Jan 22 16:42:27 pureos kernel: qmi_wwan 1-1.2:1.4: This is qmi_wwan_resume()
[...]
[... many more suspend/resume calls ... ]
[...]
Jan 22 16:43:28 pureos ModemManager[804]: <info> [modem0/call0] user request to hangup call
Jan 22 16:43:28 pureos ModemManager[804]: <info> [modem0/call0] call state changed: active -> terminated (terminated)
In the above example, a phonecall started at 16:41:48 and while that call was ongoing there were many suspend/resume calls for the USB port called "usb 1-1.2" which is the modem's port. This does not seem right to me, I was expecting the modem to suspend only when not in use.
It looks like sometimes there are several seconds between usb_port_suspend() and usb_port_resume(), but somehow the phonecall was still active during that time and phonecall audio was heard so I guess the modem must have been active even though the USB port was suspended.
Is it okay for the modem's USB port to be suspended while a phonecall is ongoing?
Is the phonecall audio data not dependent on the USB port, the modem communicates through some other channel for that?
Could phonecall audio quality issues like OS-issues#312 be related to these suspend/resume operations happening during phonecalls?
(I tested also what happens while downloading a large file using wget
using the mobile data connection, then is seemed the runtime suspend functions were never called while that download was ongoing. That seems reasonable, the modem was used during that time and then the kernel did not try to suspend it while it was used.)
According to https://www.kernel.org/doc/html/v4.16/driver-api/usb/power-management.html drivers that support autosuspend (which I guess the L5 modem's driver claims to do) should call some functions usb_autopm_get_...()
and usb_autopm_put_...()
and maybe also usb_mark_last_busy()
to tell the kernel power management core about the device's activity so that the kernel will not try to suspend a device while it is active, could it be that something like that is missing?
Thanks, but the issue went away after a while and I have not been able to reproduce it.
If it happens again, then I will try your fix. Thanks.
Assuming the avatar file is involved, would it make sense for me to remove that file, forcing chatty to fetch it again, could that be a way to reproduce the problem? If so, what is the path to that file? (if all those avatars were still saved on disk, that might explain why I could not reproduce the issue by leaving and rejoining the same matrix room again)