Re: [MM 07] Huawei plugin: "Failed to find primary port"

[Aleksander Morgado <aleksander lanedo com>]

>>>> 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/pci0000:00/0000: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'
>                      |    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.


-- 
Aleksander