qmi-proxy crashing?
Sebastian Sjoholm
sebastian.sjoholm at gmail.com
Sun Jan 3 12:02:05 UTC 2021
Hi,
I seem to be experiencing something similar to this. Restarting the
qmi-proxy will clear the issue, also by running without it does not seem to
be any issues.
I am using BG96 and this might be related to a modem crash where the device
is enumerated from crash mode back to normal mode. But this is not frequent
so I am not able to reproduce it on the go. I will try to have qmi-proxy
running with --verbose and see if I can catch it again.
Regards,
Sebastian
# /usr/bin/qmicli -p -d /dev/cdc-wdm0 --wds-get-packet-service-status
error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy
# /usr/bin/qmicli -p -d /dev/cdc-wdm0 --wds-get-packet-service-status
--verbose
[02 Jan 2021, 04:44:39] [Debug] [/dev/cdc-wdm0] Opening device with flags
'proxy, auto'...
[02 Jan 2021, 04:44:39] [Debug] [/dev/cdc-wdm0] automatically selecting QMI
mode
[02 Jan 2021, 04:44:39] [Debug] [/dev/cdc-wdm0] created endpoint
[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 1)...
[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 2)...
[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 3)...
[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 4)...
[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 5)...
[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 6)...
[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 7)...
[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:40] [Debug] spawning new qmi-proxy (try 8)...
[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:40] [Debug] spawning new qmi-proxy (try 9)...
[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
[02 Jan 2021, 04:44:40] [Debug] spawning new qmi-proxy (try 10)...
[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect:
Resource temporarily unavailable
error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy
# /usr/bin/qmicli -d /dev/cdc-wdm0 --wds-get-packet-service-status
error: couldn't create client for the 'wds' service: CID allocation failed
in the CTL client: Transaction timed out
# /usr/bin/qmicli -d /dev/cdc-wdm0 --wds-get-packet-service-status
--verbose
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Opening device with flags
'auto'...
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] automatically selecting QMI
mode
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] created endpoint
[02 Jan 2021, 04:45:07] [Debug] QMI Device at '/dev/cdc-wdm0' ready
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Assuming service 'wds' is
supported...
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Allocating new client ID...
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 16
<<<<<< data = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:01
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent generic request
(translated)...
<<<<<< QMUX:
<<<<<< length = 15
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 1
<<<<<< tlv_length = 4
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Service" (0x01)
<<<<<< length = 1
<<<<<< value = 01
<<<<<< translated = wds
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received message...
<<<<<< RAW:
<<<<<< length = 24
<<<<<< data =
01:17:00:80:00:00:01:01:22:00:0C:00:02:04:00:00:00:00:00:01:02:00:01:02
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received generic response
(translated)...
<<<<<< QMUX:
<<<<<< length = 23
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 12
<<<<<< message = "Allocate CID" (0x0022)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Allocation Info" (0x01)
<<<<<< length = 2
<<<<<< value = 01:02
<<<<<< translated = [ service = 'wds' cid = '2' ]
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Registered 'wds' (version
unknown) client with ID '2'
[02 Jan 2021, 04:45:07] [Debug] Asynchronously getting packet service
status...
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 13
<<<<<< data = 01:0C:00:00:01:02:00:01:00:22:00:00:00
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent generic request
(translated)...
<<<<<< QMUX:
<<<<<< length = 12
<<<<<< flags = 0x00
<<<<<< service = "wds"
<<<<<< client = 2
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 1
<<<<<< tlv_length = 0
<<<<<< message = "Get Packet Service Status" (0x0022)
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received message...
<<<<<< RAW:
<<<<<< length = 24
<<<<<< data =
01:17:00:80:01:02:02:01:00:22:00:0B:00:02:04:00:00:00:00:00:01:01:00:01
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received generic response
(translated)...
<<<<<< QMUX:
<<<<<< length = 23
<<<<<< flags = 0x80
<<<<<< service = "wds"
<<<<<< client = 2
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 1
<<<<<< tlv_length = 11
<<<<<< message = "Get Packet Service Status" (0x0022)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Connection Status" (0x01)
<<<<<< length = 1
<<<<<< value = 01
<<<<<< translated = disconnected
[/dev/cdc-wdm0] Connection status: 'disconnected'
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Releasing 'wds' client with
flags 'release-cid'...
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Unregistered 'wds' client
with ID '2'
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent message...
<<<<<< RAW:
<<<<<< length = 17
<<<<<< data = 01:10:00:00:00:00:00:02:23:00:05:00:01:02:00:01:02
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent generic request
(translated)...
<<<<<< QMUX:
<<<<<< length = 16
<<<<<< flags = 0x00
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "none"
<<<<<< transaction = 2
<<<<<< tlv_length = 5
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 01:02
<<<<<< translated = [ service = 'wds' cid = '2' ]
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received message...
<<<<<< RAW:
<<<<<< length = 24
<<<<<< data =
01:17:00:80:00:00:01:02:23:00:0C:00:02:04:00:00:00:00:00:01:02:00:01:02
[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received generic response
(translated)...
<<<<<< QMUX:
<<<<<< length = 23
<<<<<< flags = 0x80
<<<<<< service = "ctl"
<<<<<< client = 0
<<<<<< QMI:
<<<<<< flags = "response"
<<<<<< transaction = 2
<<<<<< tlv_length = 12
<<<<<< message = "Release CID" (0x0023)
<<<<<< TLV:
<<<<<< type = "Result" (0x02)
<<<<<< length = 4
<<<<<< value = 00:00:00:00
<<<<<< translated = SUCCESS
<<<<<< TLV:
<<<<<< type = "Release Info" (0x01)
<<<<<< length = 2
<<<<<< value = 01:02
<<<<<< translated = [ service = 'wds' cid = '2' ]
[02 Jan 2021, 04:45:07] [Debug] Client released
[02 Jan 2021, 04:45:07] [Debug] Closed
# /usr/bin/qmicli -d /dev/cdc-wdm0 --wds-get-packet-service-status
[/dev/cdc-wdm0] Connection status: 'disconnected'
# pkill -f qmi-proxy
# pgrep -f qmi-proxy
# /usr/bin/qmicli -p -d /dev/cdc-wdm0 --wds-get-packet-service-status
[/dev/cdc-wdm0] Connection status: 'disconnected'
# uname -a
Linux HB2G 4.19.164-LMFSES-DBG #1 SMP Wed Dec 30 18:18:20 CET 2020 armv7l
GNU/Linux
# qmicli --version
qmicli 1.26.6
Copyright (C) 2012-2020 Aleksander Morgado
License GPLv2+: GNU GPL version 2 or later <
http://gnu.org/licenses/gpl-2.0.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
#
On Wed, Feb 26, 2020 at 11:58 AM Paul Gildea <gildeap at tcd.ie> wrote:
> Hey Aleksander,
>
> I never checked had it actually crashed, I thought the message had meant
> it was trying to start it. If/when this happens again I have a good range
> of tests I can run now, thanks!
> If I can figure out a way to make this issue happen at will (or if
> relaunching the proxy does not fix the issue) I can test the verbose proxy
> debug also.
>
> I am resetting the modem with the below commands and they generally work
> perfectly. I am setting up a test to do it hundreds of times.
>
> qmicli -p -d /dev/cdc-wdmX --dms-set-operating-mode=offline
> qmicli -p -d /dev/cdc-wdmX --dms-set-operating-mode=reset
>
>
> For that issue (where a modem gets issued a reset and doesn't actually do
> it) I will run it with the verbose flag next time I see it.
>
> Cheers,
>
> --
> Paul
>
> On Tue, 25 Feb 2020 at 13:11, Aleksander Morgado <aleksander at aleksander.es>
> wrote:
>
>> Hey Paul,
>>
>> > Have seen this issue a few times now, the qmi-proxy appears to be
>> crashing. Every qmi command for every modem on the system then gets this
>> error:
>> >
>> > qmicli --device-open-qmi -p -d /dev/cdc-wdm9 --nas-get-signal-strength
>> > error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy
>> >
>> >
>> > Have you seen this before, or can think of a good way to debug it? Can
>> that daemon be restarted?
>> > So far only rebooting the whole system will bring the modems/qmicli
>> back to operation.
>> >
>>
>> If the qmi-proxy crashes, clients get notified via a HUP in the
>> communication socket, and so e.g. MM would reprobe the modem from
>> scratch. When using qmicli, if the qmi-proxy has crashed, it should be
>> able to relaunch it.
>>
>> The "Couldn't spawn the qmi-proxy" error is really weird; to me it
>> doesn't look like a proxy crash. Did you check whether the proxy
>> process still exists or not after this situation? The fact that the
>> proxy doesn't reply and that further qmicli commands don't reply could
>> actually mean the proxy is "stuck".
>>
>> > Here are the logs of it happening in one instance, below. Modem0
>> reboots, CID allocation fails, I query the modem a few times with
>> ['--wda-get-data-format'] and it times out (which is normal after it has
>> rebooted - takes a while for it to be able to respond to this)
>> > and suddenly all qmi commands start to fail. I notice around this time,
>> just beforehand, modem commands start to time out in general. Previously to
>> this I noticed that, for another modem, I had told it to reset via libqmi
>> and it returns "successful", but the modem actually never resets. No matter
>> how many times I run the command to do so.
>>
>> How are you running the reset command via QMI? Are you putting it
>> first in "offline" before "reset"? Won't work otherwise.
>>
>> > Not the first time that has happened also.
>> >
>> > modem0: qmi_cmd: resp="error: couldn't create client for the 'wda'
>> service: CID allocation failed in the CTL client: Transaction timed out\n"
>> > modem0: qmi_cmd: ['--wda-get-data-format']
>> > modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Transaction
>> timed out\n"
>> > modem0: qmi_cmd: ['--wda-get-data-format']
>> > modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Transaction
>> timed out\n"
>> > modem0: qmi_cmd: ['--wda-get-data-format']
>> > modem3: nas_get_serving_system: get_packet_service_status failed
>> "error: couldn't open the QmiDevice: Transaction timed out\n"
>> > modem2: nas_get_serving_system: get_packet_service_status failed
>> "error: couldn't open the QmiDevice: Transaction timed out\n"
>> > modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Transaction
>> timed out\n"
>> > modem0: qmi_cmd: ['--wda-get-data-format']
>> > modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Couldn't
>> spawn the qmi-proxy\n"
>> >
>>
>> If you can somehow reproduce this issue easily, it may be a good idea
>> to launch the qmi-proxy manually before any qmicli call happens, e..g:
>> $ sudo /usr/libexec/qmi-proxy --verbose
>>
>> Or even under gdb, if that's something you can do.
>>
>> --
>> Aleksander
>> https://aleksander.es
>>
> _______________________________________________
> libqmi-devel mailing list
> libqmi-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/libqmi-devel
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/libqmi-devel/attachments/20210103/4b64e077/attachment-0001.htm>
More information about the libqmi-devel
mailing list