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]: [1346755251.079194] [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): loaded equipment identifier: 353613048805199���= ModemManager[11662]: [1346755251.079349] [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading device identifier... ModemManager[11662]: [1346755251.079495] [mm-modem-helpers.c:129] mm_create_device_identifier(): Device ID source '12d11506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED' ModemManager[11662]: [1346755251.079590] [mm-modem-helpers.c:130] mm_create_device_identifier(): Device ID 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf' ModemManager[11662]: [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. >> >> Whether the length is wrong can be discussed. It matches the amount of >> data the device sends. The driver won't pad the data in any way, so you >> wouldn't read anything if the length was wrong. So the device sends too >> much data, but formats it as a valid message. Could e.g. be caused by >> some part of the firmware expecting a 0 terminated IMEI string and >> another part sending the IMEI as a char[15] and expecting any user to >> know it is limited to 15 bytes. >> >>> 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. >> >> If the IMEI is the only place where this happens, then it is possible to >> work around it as you know that a valid one always will be exactly 15 >> ASCII digits. > > We could impose that limit in libqmi-glib, by re-using the "max-size" > key, which was meant to be used in input variables only. A "max-size" > given in an output string would just trim the read data to the given > maximum size. > >> >> But in general I don't think we can validate *all* TLVs like this.
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]: [1346755251.079194] >>> [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): >>> loaded equipment identifier: 353613048805199���= >>> ModemManager[11662]: [1346755251.079349] >>> [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading >>> device identifier... >>> ModemManager[11662]: [1346755251.079495] [mm-modem-helpers.c:129] >>> mm_create_device_identifier(): Device ID source >>> '12d11506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED' >>> ModemManager[11662]: [1346755251.079590] [mm-modem-helpers.c:130] >>> mm_create_device_identifier(): Device ID >>> 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf' >>> ModemManager[11662]: [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. > > Whether the length is wrong can be discussed. It matches the amount of > data the device sends. The driver won't pad the data in any way, so you > wouldn't read anything if the length was wrong. So the device sends too > much data, but formats it as a valid message. Could e.g. be caused by > some part of the firmware expecting a 0 terminated IMEI string and > another part sending the IMEI as a char[15] and expecting any user to > know it is limited to 15 bytes. > >> 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. > > If the IMEI is the only place where this happens, then it is possible to > work around it as you know that a valid one always will be exactly 15 > ASCII digits. We could impose that limit in libqmi-glib, by re-using the "max-size" key, which was meant to be used in input variables only. A "max-size" given in an output string would just trim the read data to the given maximum size. > > But in general I don't think we can validate *all* TLVs like this. It > will have to be a case-by-case consideration based on how important the > value is, if related firmware bugs h
Re: [MM 07] Huawei plugin: "Failed to find primary port"
Aleksander Morgado writes: >> 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]: [1346755251.079194] >> [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): >> loaded equipment identifier: 353613048805199���= >> ModemManager[11662]: [1346755251.079349] >> [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading >> device identifier... >> ModemManager[11662]: [1346755251.079495] [mm-modem-helpers.c:129] >> mm_create_device_identifier(): Device ID source >> '12d11506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED' >> ModemManager[11662]: [1346755251.079590] [mm-modem-helpers.c:130] >> mm_create_device_identifier(): Device ID >> 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf' >> ModemManager[11662]: [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. Whether the length is wrong can be discussed. It matches the amount of data the device sends. The driver won't pad the data in any way, so you wouldn't read anything if the length was wrong. So the device sends too much data, but formats it as a valid message. Could e.g. be caused by some part of the firmware expecting a 0 terminated IMEI string and another part sending the IMEI as a char[15] and expecting any user to know it is limited to 15 bytes. > 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. If the IMEI is the only place where this happens, then it is possible to work around it as you know that a valid one always will be exactly 15 ASCII digits. But in general I don't think we can validate *all* TLVs like this. It will have to be a case-by-case consideration based on how important the value is, if related firmware bugs have been observed, and how easy we can validate the value. Bjørn ___ 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"
> 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]: [1346755251.079194] > [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): > loaded equipment identifier: 353613048805199���= > ModemManager[11662]: [1346755251.079349] > [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading device > identifier... > ModemManager[11662]: [1346755251.079495] [mm-modem-helpers.c:129] > mm_create_device_identifier(): Device ID source > '12d11506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED' > ModemManager[11662]: [1346755251.079590] [mm-modem-helpers.c:130] > mm_create_device_identifier(): Device ID > 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf' > ModemManager[11662]: [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
Re: [MM 07] Huawei plugin: "Failed to find primary port"
Aleksander Morgado 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]: [1346741345.079565] [mm-sim-qmi.c:133] >> load_sim_identifier(): loading SIM identifier... >> ModemManager[5165]: [1346741345.079755] [mm-sim-qmi.c:133] >> load_sim_identifier(): loading SIM identifier... >> ModemManager[5165]: [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]: [1346741345.079930] [mm-sim-qmi.c:209] >> load_imsi(): loading IMSI... >> ModemManager[5165]: [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]: [1346741345.080354] >> [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band >> capabilities... >> ModemManager[5165]: [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]: [1346741345.081158] [mm-serial-port.c:969] >> mm_serial_port_close(): (ttyUSB2) device open count is 0 (close) >> ModemManager[5165]: [1346741345.081217] [mm-serial-port.c:984] >> mm_serial_port_close(): (ttyUSB2) closing serial port... >> ModemManager[5165]: [1346741345.082242] [mm-serial-port.c:1005] >> mm_serial_port_close(): (ttyUSB2) serial port closed >> ModemManager[5165]: [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]: [1346755251.079194] [mm-broadband-modem-qmi.c:797] modem_load_equipment_identifier_finish(): loaded equipment identifier: 353613048805199���= ModemManager[11662]: [1346755251.079349] [mm-broadband-modem-qmi.c:924] modem_load_device_identifier(): loading device identifier... ModemManager[11662]: [1346755251.079495] [mm-modem-helpers.c:129] mm_create_device_identifier(): Device ID source '12d11506353613048805199=8200C-FACPACZQ-103801[Oct14201014:00:00]8QUALCOMMINCORPORATED' ModemManager[11662]: [1346755251.079590] [mm-modem-helpers.c:130] mm_create_device_identifier(): Device ID 'acf85b48ca4510376b6ca51f7cc9ba99f07e4bbf' ModemManager[11662]: [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) >> lengt
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"
ModemManager[13706]: [1346679919.021922] [mm-plugin-manager.c:283] plugin_supports_port_ready(): (Huawei): (tty/ttyUSB4) error when checking support: 'Defer needed' ModemManager[13706]: [1346679919.022013] [mm-plugin-manager.c:320] plugin_supports_port_ready(): (tty/ttyUSB4): ignoring port unsupported by physical modem's plugin ModemManager[13706]: [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]: [1346741345.079565] [mm-sim-qmi.c:133] > load_sim_identifier(): loading SIM identifier... > ModemManager[5165]: [1346741345.079755] [mm-sim-qmi.c:133] > load_sim_identifier(): loading SIM identifier... > ModemManager[5165]: [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]: [1346741345.079930] [mm-sim-qmi.c:209] > load_imsi(): loading IMSI... > ModemManager[5165]: [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]: [1346741345.080354] > [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band > capabilities... > ModemManager[5165]: [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]: [1346741345.081158] [mm-serial-port.c:969] > mm_serial_port_close(): (ttyUSB2) device open count is 0 (close) > ModemManager[5165]: [1346741345.081217] [mm-serial-port.c:984] > mm_serial_port_close(): (ttyUSB2) closing serial port... > ModemManager[5165]: [1346741345.082242] [mm-serial-port.c:1005] > mm_serial_port_close(): (ttyUSB2) serial port closed > ModemManager[5165]: [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]: [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]: [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' >
Re: [MM 07] Huawei plugin: "Failed to find primary port"
Aleksander Morgado writes: > On 09/03/2012 05:13 PM, Aleksander Morgado wrote: >> On 09/03/2012 03:52 PM, Bjørn Mork wrote: >>> ModemManager[13706]: [1346679919.021922] [mm-plugin-manager.c:283] >>> plugin_supports_port_ready(): (Huawei): (tty/ttyUSB4) error when checking >>> support: 'Defer needed' >>> ModemManager[13706]: [1346679919.022013] [mm-plugin-manager.c:320] >>> plugin_supports_port_ready(): (tty/ttyUSB4): ignoring port unsupported by >>> physical modem's plugin >>> ModemManager[13706]: [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]: [1346741345.079565] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: [1346741345.079755] [mm-sim-qmi.c:133] load_sim_identifier(): loading SIM identifier... ModemManager[5165]: [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]: [1346741345.079930] [mm-sim-qmi.c:209] load_imsi(): loading IMSI... ModemManager[5165]: [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]: [1346741345.080354] [mm-broadband-modem-qmi.c:1295] modem_load_supported_bands(): loading band capabilities... ModemManager[5165]: [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]: [1346741345.081158] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB2) device open count is 0 (close) ModemManager[5165]: [1346741345.081217] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB2) closing serial port... ModemManager[5165]: [1346741345.082242] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB2) serial port closed ModemManager[5165]: [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]: [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]: [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: bjorn@nemi:/usr/local/src/git/linux$ mmcli -b 0 error: couldn't find bearer at '/
Re: [MM 07] Huawei plugin: "Failed to find primary port"
Hey Bjørn
On 09/03/2012 05:13 PM, Aleksander Morgado wrote:
> On 09/03/2012 03:52 PM, Bjørn Mork wrote:
>> ModemManager[13706]: [1346679919.021922] [mm-plugin-manager.c:283]
>> plugin_supports_port_ready(): (Huawei): (tty/ttyUSB4) error when checking
>> support: 'Defer needed'
>> ModemManager[13706]: [1346679919.022013] [mm-plugin-manager.c:320]
>> plugin_supports_port_ready(): (tty/ttyUSB4): ignoring port unsupported by
>> physical modem's plugin
>> ModemManager[13706]: [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?
--
Aleksander
>From c4ba7f0798058081e51777c2674a64cd6c8eb111 Mon Sep 17 00:00:00 2001
From: Aleksander Morgado
Date: Mon, 3 Sep 2012 17:20:29 +0200
Subject: [PATCH] plugin: defer task if supports check tells us to retry
Huawei modems will probe interface 0 always first; if we try to probe another
interface meanwhile the supports check will give us a MM_CORE_ERROR_RETRY error,
indicating that we need to defer the probing of the port.
---
src/mm-plugin.c | 14 --
1 file changed, 12 insertions(+), 2 deletions(-)
diff --git a/src/mm-plugin.c b/src/mm-plugin.c
index a800997..8db4c04 100644
--- a/src/mm-plugin.c
+++ b/src/mm-plugin.c
@@ -477,8 +477,18 @@ port_probe_run_ready (MMPortProbe *probe,
g_simple_async_result_set_op_res_gpointer (ctx->result,
GUINT_TO_POINTER (MM_PLUGIN_SUPPORTS_PORT_UNSUPPORTED),
NULL);
-} else {
-/* For remaining errors, just propagate them */
+}
+/* Probing failed but the plugin tells us to retry; so we'll defer the
+ * probing a bit */
+else if (g_error_matches (error,
+ MM_CORE_ERROR,
+ MM_CORE_ERROR_RETRY)) {
+g_simple_async_result_set_op_res_gpointer (ctx->result,
+ GUINT_TO_POINTER (MM_PLUGIN_SUPPORTS_PORT_DEFER),
+ NULL);
+}
+/* For remaining errors, just propagate them */
+else {
g_simple_async_result_take_error (ctx->result, error);
}
} else {
--
1.7.11.4
___
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"
On 09/03/2012 03:52 PM, Bjørn Mork wrote: > ModemManager[13706]: [1346679919.021922] [mm-plugin-manager.c:283] > plugin_supports_port_ready(): (Huawei): (tty/ttyUSB4) error when checking > support: 'Defer needed' > ModemManager[13706]: [1346679919.022013] [mm-plugin-manager.c:320] > plugin_supports_port_ready(): (tty/ttyUSB4): ignoring port unsupported by > physical modem's plugin > ModemManager[13706]: [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. -- Aleksander ___ networkmanager-list mailing list networkmanager-list@gnome.org https://mail.gnome.org/mailman/listinfo/networkmanager-list
[MM 07] Huawei plugin: "Failed to find primary port"
Hello, just got a new Huawei device here with 2 AT ports, 1 QCDM port and 1 QMI/wwan port. They seem to be discovered OK, but for some reason the modem creation fails with the message "Failed to find primary port": ModemManager[13706]: [1346679918.952680] [mm-port-probe.c:245] mm_port_probe_set_result_qmi(): (usbmisc/cdc-wdm0) port is QMI-capable ModemManager[13706]: [1346679918.956729] [mm-plugin-manager.c:302] plugin_supports_port_ready(): (Huawei): (usbmisc/cdc-wdm0) found best plugin for port ModemManager[13706]: [1346679918.956846] [mm-plugin-manager.c:171] port_probe_context_finished(): (usbmisc/cdc-wdm0): found best plugin (Huawei) for device (/sys/devices/pci:00/:00:1d.7/usb2/2-2) ModemManager[13706]: [1346679918.956957] [mm-plugin-manager.c:235] suggest_port_probe_result(): (Huawei): (net/wwan0) suggested plugin for port ModemManager[13706]: [1346679918.957053] [mm-plugin-manager.c:246] suggest_port_probe_result(): (Huawei): (net/wwan0) deferred task completed, got suggested plugin ModemManager[13706]: [1346679918.957097] [mm-plugin-manager.c:235] suggest_port_probe_result(): (Huawei): (tty/ttyUSB5) suggested plugin for port ModemManager[13706]: [1346679918.957172] [mm-plugin-manager.c:235] suggest_port_probe_result(): (Huawei): (tty/ttyUSB4) suggested plugin for port ModemManager[13706]: [1346679918.957272] [mm-plugin-manager.c:235] suggest_port_probe_result(): (Huawei): (tty/ttyUSB3) suggested plugin for port ModemManager[13706]: [1346679918.957432] [mm-plugin.c:596] mm_plugin_supports_port(): (Huawei) checking port support (net,wwan0) ModemManager[13706]: [1346679918.957531] [mm-plugin-manager.c:373] plugin_supports_port_ready(): (Huawei): (net/wwan0) task completed, got suggested plugin ModemManager[13706]: [1346679919.018287] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^CURC=0' ModemManager[13706]: [1346679919.020021] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB4) device open count is 0 (close) ModemManager[13706]: [1346679919.020139] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB4) closing serial port... ModemManager[13706]: [1346679919.021297] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB4) serial port closed ModemManager[13706]: [1346679919.021408] [mm-serial-port.c:1074] mm_serial_port_close_force(): (ttyUSB4) forced to close port ModemManager[13706]: [1346679919.021922] [mm-plugin-manager.c:283] plugin_supports_port_ready(): (Huawei): (tty/ttyUSB4) error when checking support: 'Defer needed' ModemManager[13706]: [1346679919.022013] [mm-plugin-manager.c:320] plugin_supports_port_ready(): (tty/ttyUSB4): ignoring port unsupported by physical modem's plugin ModemManager[13706]: [1346679919.022067] [mm-plugin-manager.c:140] port_probe_context_finished(): (tty/ttyUSB4): not supported by any plugin ModemManager[13706]: [1346679919.022122] [mm-device.c:318] mm_device_ignore_port(): Fully ignoring port 'tty/ttyUSB4' from now on ModemManager[13706]: [1346679919.022207] [mm-serial-port.c:969] mm_serial_port_close(): (ttyUSB5) device open count is 0 (close) ModemManager[13706]: [1346679919.022262] [mm-serial-port.c:984] mm_serial_port_close(): (ttyUSB5) closing serial port... ModemManager[13706]: [1346679919.023276] [mm-serial-port.c:1005] mm_serial_port_close(): (ttyUSB5) serial port closed ModemManager[13706]: [1346679919.023404] [mm-serial-port.c:1074] mm_serial_port_close_force(): (ttyUSB5) forced to close port ModemManager[13706]: [1346679919.023535] [mm-plugin-manager.c:283] plugin_supports_port_ready(): (Huawei): (tty/ttyUSB5) error when checking support: 'Defer needed' ModemManager[13706]: [1346679919.023633] [mm-plugin-manager.c:320] plugin_supports_port_ready(): (tty/ttyUSB5): ignoring port unsupported by physical modem's plugin ModemManager[13706]: [1346679919.023671] [mm-plugin-manager.c:140] port_probe_context_finished(): (tty/ttyUSB5): not supported by any plugin ModemManager[13706]: [1346679919.023726] [mm-device.c:318] mm_device_ignore_port(): Fully ignoring port 'tty/ttyUSB5' from now on ModemManager[13706]: [1346679919.918737] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- 'AT^CURC=0' ModemManager[13706]: [1346679919.922834] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '' ModemManager[13706]: [1346679919.923218] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- 'OK' ModemManager[13706]: [1346679919.923362] [huawei/mm-plugin-huawei.c:179] curc_ready(): (Huawei) unsolicited messages in secondary ports turned off ModemManager[13706]: [1346679919.923447] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): --> 'AT^GETPORTMODE' ModemManager[13706]: [1346679921.323856] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- 'AT^GETPORTMODE' ModemManager[13706]: [1346679921.330707] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '' ModemManager[13706]: [1346679921.332966] [mm-at-serial-port.c:392] debug_log(): (ttyUSB3): <-- '^get
