Re: [MM 07] Huawei plugin: Failed to find primary port
Aleksander Morgado aleksan...@lanedo.com writes: On 09/03/2012 05:13 PM, Aleksander Morgado wrote: On 09/03/2012 03:52 PM, Bjørn Mork wrote: ModemManager[13706]: warn [1346679919.021922] [mm-plugin-manager.c:283] plugin_supports_port_ready(): (Huawei): (tty/ttyUSB4) error when checking support: 'Defer needed' ModemManager[13706]: debug [1346679919.022013] [mm-plugin-manager.c:320] plugin_supports_port_ready(): (tty/ttyUSB4): ignoring port unsupported by physical modem's plugin ModemManager[13706]: debug [1346679919.022067] [mm-plugin-manager.c:140] port_probe_context_finished(): (tty/ttyUSB4): not supported by any plugin Something wrong in the logic to defer port probings; will take a look at that. Are you able to test the attached patch, to see if it solves your issue? Sorry for the delay. Yes, the patch solves this issue. There are a couple of complaints about the DMS version, but I assume those are expected due to unsupported commands? And then there is a !NULL assertion failing, possibly related to SIM initialization? The modem was waiting for the SIM PIN at this point. ModemManager[5165]: KEY: 09:00:01:02:00:00:00:00 ModemManager[5165]: Service: 02 ModemManager[5165]: Client ID: 01 ModemManager[5165]: Transaction ID: 09:00 ModemManager[5165]: debug [1346741345.079565] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: debug [1346741345.079755] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: warn [1346741345.079854] [mm-sim.c:1465] load_sim_identifier_ready(): couldn't load SIM identifier: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.079930] [mm-sim-qmi.c:209] load_imsi(): loading IMSI... ModemManager[5165]: warn [1346741345.080055] [mm-sim.c:1501] load_imsi_ready(): couldn't load IMSI: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.080354] [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band capabilities... ModemManager[5165]: warn [1346741345.080486] [mm-iface-modem.c:3143] load_supported_bands_ready(): couldn't load Supported Bands: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.081158] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB2) device open count is 0 (close) ModemManager[5165]: info [1346741345.081217] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB2) closing serial port... ModemManager[5165]: info [1346741345.082242] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB2) serial port closed ModemManager[5165]: debug [1346741345.082376] [mm-base-modem.c:755] initialize_ready(): Couldn't finish initialization in the current state: 'Modem is currently locked, cannot fully initialize' (ModemManager:5165): GLib-CRITICAL **: g_variant_new_string: assertion `g_utf8_validate (string, -1, NULL)' failed (ModemManager:5165): GLib-CRITICAL **: g_variant_ref_sink: assertion `value != NULL' failed ModemManager[5165]: debug [1346741345.084508] [mm-device.c:395] export_modem(): Exported modem '/sys/devices/pci:00/:00:1d.7/usb2/2-2' at path '/org/freedesktop/ModemManager1/Modem/0' ModemManager[5165]: debug [1346741345.084628] [mm-device.c:403] export_modem(): (/org/freedesktop/ModemManager1/Modem/0): 'Huawei' modem, VID 0x12D1 PID 0x1506 (usb) [Thread 0x7fffed0a3700 (LWP 5169) exited] PIN verification using DMS and connecting using WDS worked fine after this. But I noticed a minor issue when attempting to verify max bearer limits. The only available bearer (BTW, not sure that is true - you can probably do a PPP connection as well) is already connected: bjorn@nemi:/usr/local/src/git/linux$ mmcli -b 0 Bearer '/org/freedesktop/ModemManager1/Bearer/0' - Status | connected: 'yes' | suspended: 'no' | interface: 'wwan0' | IP timeout: '20' - Properties | apn: 'telenor' | roaming: 'allowed' | IP type: 'ipv4' |user: 'none' |password: 'none' | number: 'none' | Rm protocol: 'unknown' - IPv4 configuration | method: 'dhcp' - IPv6 configuration | method: 'unknown' Attemting to create another bearer fails as expected: bjorn@nemi:/usr/local/src/git/linux$ mmcli -m 0 --simple-connect=apn=mms error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.NotFound: No valid data port found to launch connection' But this is unexpected:
Re: [MM 07] Huawei plugin: Failed to find primary port
ModemManager[13706]: warn [1346679919.021922] [mm-plugin-manager.c:283] plugin_supports_port_ready(): (Huawei): (tty/ttyUSB4) error when checking support: 'Defer needed' ModemManager[13706]: debug [1346679919.022013] [mm-plugin-manager.c:320] plugin_supports_port_ready(): (tty/ttyUSB4): ignoring port unsupported by physical modem's plugin ModemManager[13706]: debug [1346679919.022067] [mm-plugin-manager.c:140] port_probe_context_finished(): (tty/ttyUSB4): not supported by any plugin Something wrong in the logic to defer port probings; will take a look at that. Are you able to test the attached patch, to see if it solves your issue? Sorry for the delay. Yes, the patch solves this issue. There are a couple of complaints about the DMS version, but I assume those are expected due to unsupported commands? And then there is a !NULL assertion failing, possibly related to SIM initialization? The modem was waiting for the SIM PIN at this point. Thanks for checking the patch; already pushed. Yes, the complaints about DMS are because the available version is older than the required one for the command, nothing to worry about. ModemManager[5165]: KEY: 09:00:01:02:00:00:00:00 ModemManager[5165]: Service: 02 ModemManager[5165]: Client ID: 01 ModemManager[5165]: Transaction ID: 09:00 ModemManager[5165]: debug [1346741345.079565] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: debug [1346741345.079755] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: warn [1346741345.079854] [mm-sim.c:1465] load_sim_identifier_ready(): couldn't load SIM identifier: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.079930] [mm-sim-qmi.c:209] load_imsi(): loading IMSI... ModemManager[5165]: warn [1346741345.080055] [mm-sim.c:1501] load_imsi_ready(): couldn't load IMSI: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.080354] [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band capabilities... ModemManager[5165]: warn [1346741345.080486] [mm-iface-modem.c:3143] load_supported_bands_ready(): couldn't load Supported Bands: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.081158] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB2) device open count is 0 (close) ModemManager[5165]: info [1346741345.081217] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB2) closing serial port... ModemManager[5165]: info [1346741345.082242] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB2) serial port closed ModemManager[5165]: debug [1346741345.082376] [mm-base-modem.c:755] initialize_ready(): Couldn't finish initialization in the current state: 'Modem is currently locked, cannot fully initialize' (ModemManager:5165): GLib-CRITICAL **: g_variant_new_string: assertion `g_utf8_validate (string, -1, NULL)' failed (ModemManager:5165): GLib-CRITICAL **: g_variant_ref_sink: assertion `value != NULL' failed This is weird; can you run it like this, and get a backtrace of where this happened? sudo G_DEBUG=fatal-criticals gdb --args /usr/sbin/ModemManager --debug That should run gdb and halt when the first critical is issued. ModemManager[5165]: debug [1346741345.084508] [mm-device.c:395] export_modem(): Exported modem '/sys/devices/pci:00/:00:1d.7/usb2/2-2' at path '/org/freedesktop/ModemManager1/Modem/0' ModemManager[5165]: debug [1346741345.084628] [mm-device.c:403] export_modem(): (/org/freedesktop/ModemManager1/Modem/0): 'Huawei' modem, VID 0x12D1 PID 0x1506 (usb) [Thread 0x7fffed0a3700 (LWP 5169) exited] PIN verification using DMS and connecting using WDS worked fine after this. But I noticed a minor issue when attempting to verify max bearer limits. The only available bearer (BTW, not sure that is true - you can probably do a PPP connection as well) is already connected: Yeah, using PPP on AT ports in QMI powered modems should be possible, maybe just creating a generic MMBroadbandBearer instead of a MMBroadbandBearerQmi is enough; but I didn't want to complicate the things yet, better get something stable first. bjorn@nemi:/usr/local/src/git/linux$ mmcli -b 0 Bearer '/org/freedesktop/ModemManager1/Bearer/0' - Status | connected: 'yes' | suspended: 'no' | interface: 'wwan0' | IP timeout: '20' - Properties | apn: 'telenor' | roaming: 'allowed' | IP type: 'ipv4' |user: 'none'
Re: [MM 07] Huawei plugin: Failed to find primary port
bjorn@nemi:/usr/local/src/git/linux$ mmcli -b 0 Bearer '/org/freedesktop/ModemManager1/Bearer/0' - Status | connected: 'yes' | suspended: 'no' | interface: 'wwan0' | IP timeout: '20' - Properties | apn: 'telenor' | roaming: 'allowed' | IP type: 'ipv4' |user: 'none' |password: 'none' | number: 'none' | Rm protocol: 'unknown' - IPv4 configuration | method: 'dhcp' - IPv6 configuration | method: 'unknown' Attemting to create another bearer fails as expected: bjorn@nemi:/usr/local/src/git/linux$ mmcli -m 0 --simple-connect=apn=mms error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.NotFound: No valid data port found to launch connection' But this is unexpected: bjorn@nemi:/usr/local/src/git/linux$ mmcli -b 0 error: couldn't find bearer at '/org/freedesktop/ModemManager1/Bearer/0': 'not found in any modem' bjorn@nemi:/usr/local/src/git/linux$ mmcli -m 0 --list-bearers Found 1 bearers: /org/freedesktop/ModemManager1/Bearer/1 bjorn@nemi:/usr/local/src/git/linux$ mmcli -b 1 Bearer '/org/freedesktop/ModemManager1/Bearer/1' - Status | connected: 'no' | suspended: 'no' | interface: 'unknown' | IP timeout: '20' - Properties | apn: 'mms' | roaming: 'allowed' | IP type: 'ipv4' |user: 'none' |password: 'none' | number: 'none' | Rm protocol: 'unknown' - IPv4 configuration | method: 'unknown' - IPv6 configuration | method: 'unknown' So MM created the bearer and replaced the already connected one with the new and unconnected bearer. That does not seem right? No, it doesn't seem right. --simple-connect should try to do as much as possible to get you connected with the properties you passed. The problem here is that the modem allows only one bearer to be connected as there is only one QMI port; in this case we remove the previously existing bearers in order to allocate space for the new one; but we don't make sure the previous bearer gets disconnected, which is an error. Another approach would be to avoid deleting the previous bearer *if* it is connected. If it wasn't connected, we can always just remove it, create a new one, and connect the new one. Probably both approaches are valid use cases, but looking at it maybe the second one makes more sense as default for a simple method like this. The second approach will issue an error and the user can then disconnect the bearers before retrying the connect. Will prepare a patch for this. Pushed a fix to handle this case now, which seems a good compromise for the Simple.Connect() logic. Cheers! -- Aleksander ___ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list
Re: [MM 07] Huawei plugin: Failed to find primary port
Aleksander Morgado aleksan...@lanedo.com writes: ModemManager[5165]: KEY: 09:00:01:02:00:00:00:00 ModemManager[5165]: Service: 02 ModemManager[5165]: Client ID: 01 ModemManager[5165]: Transaction ID: 09:00 ModemManager[5165]: debug [1346741345.079565] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: debug [1346741345.079755] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: warn [1346741345.079854] [mm-sim.c:1465] load_sim_identifier_ready(): couldn't load SIM identifier: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.079930] [mm-sim-qmi.c:209] load_imsi(): loading IMSI... ModemManager[5165]: warn [1346741345.080055] [mm-sim.c:1501] load_imsi_ready(): couldn't load IMSI: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.080354] [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band capabilities... ModemManager[5165]: warn [1346741345.080486] [mm-iface-modem.c:3143] load_supported_bands_ready(): couldn't load Supported Bands: 'QMI operation failed: Cannot send message: QMI service 'dms' version '1.3' required, got version '1.2'' ModemManager[5165]: debug [1346741345.081158] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB2) device open count is 0 (close) ModemManager[5165]: info [1346741345.081217] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB2) closing serial port... ModemManager[5165]: info [1346741345.082242] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB2) serial port closed ModemManager[5165]: debug [1346741345.082376] [mm-base-modem.c:755] initialize_ready(): Couldn't finish initialization in the current state: 'Modem is currently locked, cannot fully initialize' (ModemManager:5165): GLib-CRITICAL **: g_variant_new_string: assertion `g_utf8_validate (string, -1, NULL)' failed (ModemManager:5165): GLib-CRITICAL **: g_variant_ref_sink: assertion `value != NULL' failed This is weird; can you run it like this, and get a backtrace of where this happened? sudo G_DEBUG=fatal-criticals gdb --args /usr/sbin/ModemManager --debug That should run gdb and halt when the first critical is issued. backtrace follows below. But first, this may be related to a firmware bug in the IMEI code. Looking at: ModemManager[11662]: KEY: 06:00:03:02:00:00:00:00 ModemManager[11662]: Service: 02 ModemManager[11662]: Client ID: 03 ModemManager[11662]: Transaction ID: 06:00 ModemManager[11662]: [/dev/cdc-wdm0] Received message... QMUX: length = 47 flags = 0x80 service = dms client = 3 QMI: flags = response transaction = 6 tlv_length = 35 message = Get IDs (0x0025) TLV: type = Result (0x02) length = 4 value = 00:00:00:00 translated = SUCCESS TLV: type = Imei (0x11) length = 25 value = 33:35:33:36:31:33:30:34:38:38:30:35:31:39:39:02:B0:1C:0E:02:84:E3:A6:01:3D translated = 353613048805199���= ModemManager[11662]: KEY: 06:00:03:02:00:00:00:00 ModemManager[11662]: Service: 02 ModemManager[11662]: Client ID: 03 ModemManager[11662]: Transaction ID: 06:00 ModemManager[11662]: debug [1346755251.079194] [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): loaded equipment identifier: 353613048805199���= ModemManager[11662]: debug [1346755251.079349] [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading device identifier... ModemManager[11662]: debug [1346755251.079495] [mm-modem-helpers.c:129] mm_create_device_identifier(): Device ID source '12d11506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED' ModemManager[11662]: debug [1346755251.079590] [mm-modem-helpers.c:130] mm_create_device_identifier(): Device ID 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf' ModemManager[11662]: debug [1346755251.079703] [mm-broadband-modem-qmi.c:912] modem_load_device_identifier_finish(): loaded device identifier: acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf Which is very odd. Attempting to run qmicli -d /dev/cdc-wdm0 -v --dms-get-ids consistenly result in: [04 Sep 2012, 13:01:55] [Debug] [/dev/cdc-wdm0] Received message... QMUX: length = 38 flags = 0x80 service = dms client = 10 QMI: flags = response transaction = 1 tlv_length = 26 message = Get IDs (0x0025) TLV: type = Result (0x02) length = 4 value = 00:00:00:00 translated = SUCCESS TLV: type = Imei (0x11) length = 16 value = 33:35:33:36:31:33:30:34:38:38:30:35:31:39:39:02 translated = 353613048805199 So you still got a bogus 0x02 byte there, but why did MM see 9 more bytes? Anyway, it is safe to consider any firmware response as
Re: [MM 07] Huawei plugin: Failed to find primary port
ModemManager[11662]: KEY: 06:00:03:02:00:00:00:00 ModemManager[11662]: Service: 02 ModemManager[11662]: Client ID: 03 ModemManager[11662]: Transaction ID: 06:00 ModemManager[11662]: [/dev/cdc-wdm0] Received message... QMUX: length = 47 flags = 0x80 service = dms client = 3 QMI: flags = response transaction = 6 tlv_length = 35 message = Get IDs (0x0025) TLV: type = Result (0x02) length = 4 value = 00:00:00:00 translated = SUCCESS TLV: type = Imei (0x11) length = 25 value = 33:35:33:36:31:33:30:34:38:38:30:35:31:39:39:02:B0:1C:0E:02:84:E3:A6:01:3D translated = 353613048805199���= ModemManager[11662]: KEY: 06:00:03:02:00:00:00:00 ModemManager[11662]: Service: 02 ModemManager[11662]: Client ID: 03 ModemManager[11662]: Transaction ID: 06:00 ModemManager[11662]: debug [1346755251.079194] [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): loaded equipment identifier: 353613048805199���= ModemManager[11662]: debug [1346755251.079349] [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading device identifier... ModemManager[11662]: debug [1346755251.079495] [mm-modem-helpers.c:129] mm_create_device_identifier(): Device ID source '12d11506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED' ModemManager[11662]: debug [1346755251.079590] [mm-modem-helpers.c:130] mm_create_device_identifier(): Device ID 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf' ModemManager[11662]: debug [1346755251.079703] [mm-broadband-modem-qmi.c:912] modem_load_device_identifier_finish(): loaded device identifier: acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf Which is very odd. Attempting to run qmicli -d /dev/cdc-wdm0 -v --dms-get-ids consistenly result in: [04 Sep 2012, 13:01:55] [Debug] [/dev/cdc-wdm0] Received message... QMUX: length = 38 flags = 0x80 service = dms client = 10 QMI: flags = response transaction = 1 tlv_length = 26 message = Get IDs (0x0025) TLV: type = Result (0x02) length = 4 value = 00:00:00:00 translated = SUCCESS TLV: type = Imei (0x11) length = 16 value = 33:35:33:36:31:33:30:34:38:38:30:35:31:39:39:02 translated = 353613048805199 So you still got a bogus 0x02 byte there, but why did MM see 9 more bytes? Anyway, it is safe to consider any firmware response as potentionally buggy, and never trust any of it to fit into any expected pattern... Yes, I know that's easy to say ;-) I believe Dan already had this issue a couple of weeks ago. The main issue here is that the 'length' value of the TLV is clearly wrong. In all cases it should have been '15'. We just get a greater value and we end up reading more transferred data which probably means nothing. We can try to avoid this by making libqmi-glib validate every output 'string' variable as valid UTF-8 (or even ASCII?). Not sure which is the default expected encoding in QMI, but at least this check will make us provide always safe values which we can then use in DBus. Thanks for the check and backtrace, btw. -- Aleksander ___ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list
