<div dir="ltr">Hi, <div><br></div><div>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.</div><div>The next command sent then restarts the proxy and all is back to normal.</div><div><br></div><div>--</div><div>Paul</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Sun, 3 Jan 2021 at 12:02, Sebastian Sjoholm <<a href="mailto:sebastian.sjoholm@gmail.com">sebastian.sjoholm@gmail.com</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>Hi,</div><div><br></div><div>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.</div><div><br></div><div>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.</div><div><br></div><div>Regards,</div><div>Sebastian<br></div><div><br></div><div>#  /usr/bin/qmicli -p -d /dev/cdc-wdm0 --wds-get-packet-service-status<br>error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy<br>#  /usr/bin/qmicli -p -d /dev/cdc-wdm0 --wds-get-packet-service-status --verbose<br>[02 Jan 2021, 04:44:39] [Debug] [/dev/cdc-wdm0] Opening device with flags 'proxy, auto'...<br>[02 Jan 2021, 04:44:39] [Debug] [/dev/cdc-wdm0] automatically selecting QMI mode<br>[02 Jan 2021, 04:44:39] [Debug] [/dev/cdc-wdm0] created endpoint<br>[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 1)...<br>[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 2)...<br>[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 3)...<br>[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 4)...<br>[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 5)...<br>[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 6)...<br>[02 Jan 2021, 04:44:39] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:39] [Debug] spawning new qmi-proxy (try 7)...<br>[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:40] [Debug] spawning new qmi-proxy (try 8)...<br>[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:40] [Debug] spawning new qmi-proxy (try 9)...<br>[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>[02 Jan 2021, 04:44:40] [Debug] spawning new qmi-proxy (try 10)...<br>[02 Jan 2021, 04:44:40] [Debug] cannot connect to proxy: Could not connect: Resource temporarily unavailable<br>error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy<br>#  /usr/bin/qmicli -d /dev/cdc-wdm0 --wds-get-packet-service-status<br>error: couldn't create client for the 'wds' service: CID allocation failed in the CTL client: Transaction timed out<br>#  /usr/bin/qmicli -d /dev/cdc-wdm0 --wds-get-packet-service-status --verbose<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Opening device with flags 'auto'...<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] automatically selecting QMI mode<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] created endpoint<br>[02 Jan 2021, 04:45:07] [Debug] QMI Device at '/dev/cdc-wdm0' ready<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Assuming service 'wds' is supported...<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Allocating new client ID...<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent message...<br><<<<<< RAW:<br><<<<<<   length = 16<br><<<<<<   data   = 01:0F:00:00:00:00:00:01:22:00:04:00:01:01:00:01<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent generic request (translated)...<br><<<<<< QMUX:<br><<<<<<   length  = 15<br><<<<<<   flags   = 0x00<br><<<<<<   service = "ctl"<br><<<<<<   client  = 0<br><<<<<< QMI:<br><<<<<<   flags       = "none"<br><<<<<<   transaction = 1<br><<<<<<   tlv_length  = 4<br><<<<<<   message     = "Allocate CID" (0x0022)<br><<<<<< TLV:<br><<<<<<   type       = "Service" (0x01)<br><<<<<<   length     = 1<br><<<<<<   value      = 01<br><<<<<<   translated = wds<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received message...<br><<<<<< RAW:<br><<<<<<   length = 24<br><<<<<<   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<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received generic response (translated)...<br><<<<<< QMUX:<br><<<<<<   length  = 23<br><<<<<<   flags   = 0x80<br><<<<<<   service = "ctl"<br><<<<<<   client  = 0<br><<<<<< QMI:<br><<<<<<   flags       = "response"<br><<<<<<   transaction = 1<br><<<<<<   tlv_length  = 12<br><<<<<<   message     = "Allocate CID" (0x0022)<br><<<<<< TLV:<br><<<<<<   type       = "Result" (0x02)<br><<<<<<   length     = 4<br><<<<<<   value      = 00:00:00:00<br><<<<<<   translated = SUCCESS<br><<<<<< TLV:<br><<<<<<   type       = "Allocation Info" (0x01)<br><<<<<<   length     = 2<br><<<<<<   value      = 01:02<br><<<<<<   translated = [ service = 'wds' cid = '2' ]<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Registered 'wds' (version unknown) client with ID '2'<br>[02 Jan 2021, 04:45:07] [Debug] Asynchronously getting packet service status...<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent message...<br><<<<<< RAW:<br><<<<<<   length = 13<br><<<<<<   data   = 01:0C:00:00:01:02:00:01:00:22:00:00:00<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent generic request (translated)...<br><<<<<< QMUX:<br><<<<<<   length  = 12<br><<<<<<   flags   = 0x00<br><<<<<<   service = "wds"<br><<<<<<   client  = 2<br><<<<<< QMI:<br><<<<<<   flags       = "none"<br><<<<<<   transaction = 1<br><<<<<<   tlv_length  = 0<br><<<<<<   message     = "Get Packet Service Status" (0x0022)<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received message...<br><<<<<< RAW:<br><<<<<<   length = 24<br><<<<<<   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<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received generic response (translated)...<br><<<<<< QMUX:<br><<<<<<   length  = 23<br><<<<<<   flags   = 0x80<br><<<<<<   service = "wds"<br><<<<<<   client  = 2<br><<<<<< QMI:<br><<<<<<   flags       = "response"<br><<<<<<   transaction = 1<br><<<<<<   tlv_length  = 11<br><<<<<<   message     = "Get Packet Service Status" (0x0022)<br><<<<<< TLV:<br><<<<<<   type       = "Result" (0x02)<br><<<<<<   length     = 4<br><<<<<<   value      = 00:00:00:00<br><<<<<<   translated = SUCCESS<br><<<<<< TLV:<br><<<<<<   type       = "Connection Status" (0x01)<br><<<<<<   length     = 1<br><<<<<<   value      = 01<br><<<<<<   translated = disconnected<br><br>[/dev/cdc-wdm0] Connection status: 'disconnected'<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] Unregistered 'wds' client with ID '2'<br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent message...<br><<<<<< RAW:<br><<<<<<   length = 17<br><<<<<<   data   = 01:10:00:00:00:00:00:02:23:00:05:00:01:02:00:01:02<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] sent generic request (translated)...<br><<<<<< QMUX:<br><<<<<<   length  = 16<br><<<<<<   flags   = 0x00<br><<<<<<   service = "ctl"<br><<<<<<   client  = 0<br><<<<<< QMI:<br><<<<<<   flags       = "none"<br><<<<<<   transaction = 2<br><<<<<<   tlv_length  = 5<br><<<<<<   message     = "Release CID" (0x0023)<br><<<<<< TLV:<br><<<<<<   type       = "Release Info" (0x01)<br><<<<<<   length     = 2<br><<<<<<   value      = 01:02<br><<<<<<   translated = [ service = 'wds' cid = '2' ]<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received message...<br><<<<<< RAW:<br><<<<<<   length = 24<br><<<<<<   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<br><br>[02 Jan 2021, 04:45:07] [Debug] [/dev/cdc-wdm0] received generic response (translated)...<br><<<<<< QMUX:<br><<<<<<   length  = 23<br><<<<<<   flags   = 0x80<br><<<<<<   service = "ctl"<br><<<<<<   client  = 0<br><<<<<< QMI:<br><<<<<<   flags       = "response"<br><<<<<<   transaction = 2<br><<<<<<   tlv_length  = 12<br><<<<<<   message     = "Release CID" (0x0023)<br><<<<<< TLV:<br><<<<<<   type       = "Result" (0x02)<br><<<<<<   length     = 4<br><<<<<<   value      = 00:00:00:00<br><<<<<<   translated = SUCCESS<br><<<<<< TLV:<br><<<<<<   type       = "Release Info" (0x01)<br><<<<<<   length     = 2<br><<<<<<   value      = 01:02<br><<<<<<   translated = [ service = 'wds' cid = '2' ]<br><br>[02 Jan 2021, 04:45:07] [Debug] Client released<br>[02 Jan 2021, 04:45:07] [Debug] Closed<br>#  /usr/bin/qmicli -d /dev/cdc-wdm0 --wds-get-packet-service-status<br>[/dev/cdc-wdm0] Connection status: 'disconnected'<br># pkill -f qmi-proxy<br># pgrep -f qmi-proxy<br>#  /usr/bin/qmicli -p -d /dev/cdc-wdm0 --wds-get-packet-service-status<br>[/dev/cdc-wdm0] Connection status: 'disconnected'<br># uname -a<br>Linux HB2G 4.19.164-LMFSES-DBG #1 SMP Wed Dec 30 18:18:20 CET 2020 armv7l GNU/Linux<br># qmicli --version<br>qmicli 1.26.6<br>Copyright (C) 2012-2020 Aleksander Morgado<br>License GPLv2+: GNU GPL version 2 or later <<a href="http://gnu.org/licenses/gpl-2.0.html" target="_blank">http://gnu.org/licenses/gpl-2.0.html</a>><br>This is free software: you are free to change and redistribute it.<br>There is NO WARRANTY, to the extent permitted by law.<br><br># <br></div><div><br></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, Feb 26, 2020 at 11:58 AM Paul Gildea <<a href="mailto:gildeap@tcd.ie" target="_blank">gildeap@tcd.ie</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr">Hey Aleksander,<div><br></div><div>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!</div><div>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.</div><div><br></div><div>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.</div><div><br></div><div><p style="margin:10px 0px 0px;padding:0px;color:rgb(23,43,77);font-family:-apple-system,BlinkMacSystemFont,"Segoe UI",Roboto,Oxygen,Ubuntu,"Fira Sans","Droid Sans","Helvetica Neue",sans-serif;font-size:14px;background-color:rgb(244,245,247)">qmicli -p -d /dev/cdc-wdmX --dms-set-operating-mode=offline<br>qmicli -p -d /dev/cdc-wdmX --dms-set-operating-mode=reset</p></div><div><br></div><div><br></div><div>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.</div><div><br></div><div>Cheers,</div><div><br></div><div>--</div><div>Paul</div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, 25 Feb 2020 at 13:11, Aleksander Morgado <<a href="mailto:aleksander@aleksander.es" target="_blank">aleksander@aleksander.es</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hey Paul,<br>
<br>
> 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:<br>
><br>
> qmicli --device-open-qmi -p -d /dev/cdc-wdm9 --nas-get-signal-strength<br>
> error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy<br>
><br>
><br>
> Have you seen this before, or can think of a good way to debug it? Can that daemon be restarted?<br>
> So far only rebooting the whole system will bring the modems/qmicli back to operation.<br>
><br>
<br>
If the qmi-proxy crashes, clients get notified via a HUP in the<br>
communication socket, and so e.g. MM would reprobe the modem from<br>
scratch. When using qmicli, if the qmi-proxy has crashed, it should be<br>
able to relaunch it.<br>
<br>
The "Couldn't spawn the qmi-proxy" error is really weird; to me it<br>
doesn't look like a proxy crash. Did you check whether the proxy<br>
process still exists or not after this situation? The fact that the<br>
proxy doesn't reply and that further qmicli commands don't reply could<br>
actually mean the proxy is "stuck".<br>
<br>
> 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)<br>
> 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.<br>
<br>
How are you running the reset command via QMI? Are you putting it<br>
first in "offline" before "reset"? Won't work otherwise.<br>
<br>
> Not the first time that has happened also.<br>
><br>
> modem0: qmi_cmd: resp="error: couldn't create client for the 'wda' service: CID allocation failed in the CTL client: Transaction timed out\n"<br>
> modem0: qmi_cmd: ['--wda-get-data-format']<br>
> modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Transaction timed out\n"<br>
> modem0: qmi_cmd: ['--wda-get-data-format']<br>
> modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Transaction timed out\n"<br>
> modem0: qmi_cmd: ['--wda-get-data-format']<br>
> modem3: nas_get_serving_system: get_packet_service_status failed "error: couldn't open the QmiDevice: Transaction timed out\n"<br>
> modem2: nas_get_serving_system: get_packet_service_status failed "error: couldn't open the QmiDevice: Transaction timed out\n"<br>
> modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Transaction timed out\n"<br>
> modem0: qmi_cmd: ['--wda-get-data-format']<br>
> modem0: qmi_cmd: resp="error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy\n"<br>
><br>
<br>
If you can somehow reproduce this issue easily, it may be a good idea<br>
to launch the qmi-proxy manually before any qmicli call happens, e..g:<br>
$ sudo /usr/libexec/qmi-proxy --verbose<br>
<br>
Or even under gdb, if that's something you can do.<br>
<br>
-- <br>
Aleksander<br>
<a href="https://aleksander.es" rel="noreferrer" target="_blank">https://aleksander.es</a><br>
</blockquote></div>
_______________________________________________<br>
libqmi-devel mailing list<br>
<a href="mailto:libqmi-devel@lists.freedesktop.org" target="_blank">libqmi-devel@lists.freedesktop.org</a><br>
<a href="https://lists.freedesktop.org/mailman/listinfo/libqmi-devel" rel="noreferrer" target="_blank">https://lists.freedesktop.org/mailman/listinfo/libqmi-devel</a><br>
</blockquote></div>
</blockquote></div>