qmi-proxy crashing?

Wed Jan 6 16:43:17 UTC 2021

Hi,

Similar to you, this is very hard for me to reproduce. Until it is fixed,
the solution for me was to code around it - kill the proxy when an error is
detected.
The next command sent then restarts the proxy and all is back to normal.

--
Paul

On Sun, 3 Jan 2021 at 12:02, Sebastian Sjoholm <sebastian.sjoholm at gmail.com>
wrote:

> 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/20210106/bdb9f10b/attachment-0001.htm>