Phonecalls sometimes fail due to modem not responding to AT commands, is some other process hijacking the AT port?
This regards Librem 5 with PureOS Byzantium.
Making phonecalls works most of the time, but sometimes I cannot make a call. This is kind of reproducible but not every time, if I reboot e.g. 10 times and each time try to make a call, the problem usually happens at least once in those 10 attempts. When the problem appears, it seems like all following call attempts fail, and then any incoming calls also fail. A reboot is needed to make things work again.
Having added the ModemManager --debug option (ExecStart=/usr/sbin/ModemManager --debug
in the /lib/systemd/system/ModemManager.service
file) and compared logs for cases when making phonecalls work and not, now I think it looks like the problem is that the modem sometimes stops responding to AT commands.
For a successful case, part of the log related to [modem0/ttyUSB1/at] looks like this:
<debug> [1640639307.692391] [modem0/ttyUSB1/at] --> 'AT+CCWA=1<CR>'
<debug> [1640639307.703945] [modem0/ttyUSB1/at] <-- '<CR><LF>OK<CR><LF>'
<debug> [1640639307.704293] [modem0/ttyUSB1/at] device open count is 1 (close)
<debug> [1640639313.155180] [modem0/ttyUSB1/at] device open count is 2 (open)
<debug> [1640639313.155742] [modem0/ttyUSB1/at] --> 'AT+CCLK?<CR>'
<debug> [1640639313.168020] [modem0/ttyUSB1/at] <-- '<CR><LF>+CCLK: "21/12/27,21:08:32+04"<CR><LF><CR><LF>OK<CR><LF>'
<debug> [1640639313.168825] [modem0/ttyUSB1/at] device open count is 1 (close)
<debug> [1640639333.490220] [modem0/ttyUSB1/at] device open count is 2 (open)
<debug> [1640639333.490682] [modem0/ttyUSB1/at] device open count is 3 (open)
<debug> [1640639333.490880] [modem0/ttyUSB1/at] --> 'ATD90510;<CR>'
<debug> [1640639333.534638] [modem0/ttyUSB1/at] <-- '<CR><LF>OK<CR><LF>'
If I understand correctly, each "-->" line indicates an AT command sent to the modem, and each time there is a corresponding "<--" line that shows the response from the modem. That looks fine above, where each "-->" line is followed by a "<--" line.
Below is the corresponding part of the log for a case when I could not make phonecalls:
<debug> [1640636606.219473] [modem0/ttyUSB1/at] --> 'AT+CCWA=1<CR>'
<debug> [1640636606.230312] [modem0/ttyUSB1/at] <-- '<CR><LF>OK<CR><LF>'
<debug> [1640636606.230674] [modem0/ttyUSB1/at] device open count is 1 (close)
<debug> [1640636611.155941] [modem0/ttyUSB1/at] device open count is 2 (open)
<debug> [1640636611.156211] [modem0/ttyUSB1/at] --> 'AT+CCLK?<CR>'
<debug> [1640636614.159204] [modem0/ttyUSB1/at] device open count is 1 (close)
<debug> [1640636660.623905] [modem0/ttyUSB1/at] device open count is 2 (open)
<debug> [1640636660.624328] [modem0/ttyUSB1/at] device open count is 3 (open)
<debug> [1640636660.624529] [modem0/ttyUSB1/at] --> 'ATD90510;<CR>'
<debug> [1640636662.656478] [modem0/ttyUSB1/at] device open count is 4 (open)
In that case the modem responds to the "AT+CCWA" command, but for the "AT+CCLK" and the "ATD" commands there is no response from the modem.
There are also messages about timeouts, like this:
<debug> [1640636614.158768] [modem0] couldn't load network timezone: Serial command timed out
<warn> [1640636750.659447] [modem0/call0] couldn't start call: Serial command timed out
I asked about this on the ModemManager-devel mailing list and got the following reply from Aleksander Morgado there (see https://lists.freedesktop.org/archives/modemmanager-devel/2021-December/009049.html):
There are 2 main explanations for that behavior:
- some other process is trying to talk to the AT port, so "hijacking" the reading part from ModemManager.
- the AT command handler inside the modem firmware, or some AT command processing got stuck in the modem firmware.
When this happens, MM would count up to 10 consecutive AT timeouts, and when that happens it flags the modem as invalid, and it's reprobed. When reprobing, if the QMI port still works, MM will use exclusively that one. If the QMI also doesn't work, the modem will be unusable.
I would try to ask whether case 1) is possible in the Librem5, and if it isn't, then you're facing a modem firmware issue very likely.
So now I would like to find out if it is case 1 above, that is, is some other process "hijacking" the AT port?
The port "ttyUSB1" seems related to a /sys/devices/ path according to the following:
<debug> [1640815008.566228] [base-manager] adding port ttyUSB1 at sysfs path: /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2/1-1.2:1.1/ttyUSB1/tty/ttyUSB1
Is there a way to log all access to that port, that could be used to detect if some other process is using it?
Other ideas about what to do here?