If we need to disconnect signal handlers for the different port
objects managed in the QMI/MBIM modems, we need to do that during
dispose(), as there is no guarantee at all that the port objects will
exist in the MMBaseModem by the time finalize() is run.
ModemManager[4183]: <debug> [1579097652.255333] Modem (Sierra) '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-8/1-8.4' completely disposed
ModemManager[4183]: [/dev/cdc-wdm1] unexpected port hangup!
ModemManager[4183]: [/dev/cdc-wdm1] channel destroyed
ModemManager[4183]: <info> [1579097652.258186] Connection to mbim-proxy for /dev/cdc-wdm1 lost, reprobing
(ModemManager:4183): GLib-GObject-WARNING **: 15:14:12.258: invalid unclassed pointer in cast to 'MMBaseModem'
ModemManager[4183]: mm_base_modem_set_reprobe: assertion 'MM_IS_BASE_MODEM (self)' failed
(ModemManager:4183): GLib-GObject-WARNING **: 15:14:12.258: invalid unclassed pointer in cast to 'MMBaseModem'
ModemManager[4183]: mm_base_modem_set_valid: assertion 'MM_IS_BASE_MODEM (self)' failed
ModemManager[4183]: [/dev/cdc-wdm1] unexpected port hangup!
ModemManager[4183]: [/dev/cdc-wdm1] channel destroyed
ModemManager[4183]: [/dev/cdc-wdm1] MBIM error: Cannot write message: Broken pipe
ModemManager[4183]: [/dev/cdc-wdm1] MBIM error: Cannot write message: Broken pipe
ModemManager[4183]: [/dev/cdc-wdm1] MBIM error: Cannot write message: Broken pipe
ModemManager[4183]: [/dev/cdc-wdm1] MBIM error: Cannot write message: Broken pipe
The GVariants that we obtain during the processing of the "previous"
dictionary with g_variant_iter_next() are full references, while the
GVariants that we obtain processing the input MMLocationXX objects are
floating references.
The code was working well with the floating references only, as it was
assumed that g_variant_builder_add() would take ownership of them as
full references; but when the GVariant came from the
g_variant_iter_next() processing, g_variant_builder_add() would take a
full new extra reference, triggering the memory leak.
Fix this, by making sure that we always work with full GVariant
references in all cases, converting the floating ones with
g_variant_ref_sink() and making sure we explicitly unref them after
g_variant_builder_add().
==3146== 112 (48 direct, 64 indirect) bytes in 1 blocks are definitely lost in loss record 4,532 of 4,887
==3146== at 0x483877F: malloc (vg_replace_malloc.c:309)
==3146== by 0x50D53DA: g_malloc (gmem.c:99)
==3146== by 0x50F19ED: g_slice_alloc (gslice.c:1024)
==3146== by 0x511D639: g_variant_alloc (gvariant-core.c:486)
==3146== by 0x511D6F9: g_variant_new_from_bytes (gvariant-core.c:529)
==3146== by 0x51146C3: g_variant_new_from_trusted (gvariant.c:326)
==3146== by 0x5115D28: g_variant_new_string (gvariant.c:1264)
==3146== by 0x48EC642: mm_location_3gpp_get_string_variant (mm-location-3gpp.c:294)
==3146== by 0x196350: build_location_dictionary (mm-iface-modem-location.c:162)
==3146== by 0x197E0C: handle_setup_auth_ready (mm-iface-modem-location.c:891)
==3146== by 0x4EC9160: g_task_return_now (gtask.c:1212)
==3146== by 0x4EC92AA: g_task_return (gtask.c:1281)
==3146== 41,658 (35,520 direct, 6,138 indirect) bytes in 740 blocks are definitely lost in loss record 4,887 of 4,887
==3146== at 0x483877F: malloc (vg_replace_malloc.c:309)
==3146== by 0x50D53DA: g_malloc (gmem.c:99)
==3146== by 0x50F19ED: g_slice_alloc (gslice.c:1024)
==3146== by 0x511E02B: g_variant_get_child_value (gvariant-core.c:1093)
==3146== by 0x5114FA7: g_variant_get_variant (gvariant.c:748)
==3146== by 0x511B196: g_variant_valist_get_nnp (gvariant.c:4934)
==3146== by 0x511B87B: g_variant_valist_get_leaf (gvariant.c:5051)
==3146== by 0x511BFBF: g_variant_valist_get (gvariant.c:5232)
==3146== by 0x511C145: g_variant_valist_get (gvariant.c:5267)
==3146== by 0x511C953: g_variant_iter_next (gvariant.c:5667)
==3146== by 0x1962F5: build_location_dictionary (mm-iface-modem-location.c:128)
==3146== by 0x19659A: notify_gps_location_update (mm-iface-modem-location.c:231)
Also, explicitly close the QMI port if we had it open for the
connected bearer.
==991919== 6,533 (48 direct, 6,485 indirect) bytes in 1 blocks are definitely lost in loss record 5,171 of 5,177
==991919== at 0x5048291: g_type_create_instance (gtype.c:1844)
==991919== by 0x502DFC4: g_object_new_internal (gobject.c:1827)
==991919== by 0x502EFA9: g_object_new_valist (gobject.c:2152)
==991919== by 0x502DB9E: g_object_new (gobject.c:1670)
==991919== by 0x2215CA: mm_port_qmi_new (mm-port-qmi.c:615)
==991919== by 0x16C892: mm_base_modem_grab_port (mm-base-modem.c:295)
==991919== by 0x1CEEE5: mm_plugin_create_modem (mm-plugin.c:1048)
==991919== by 0x157E1E: mm_device_create_modem (mm-device.c:413)
==991919== by 0x1535A0: device_support_check_ready (mm-base-manager.c:195)
==991919== by 0x4EC9160: g_task_return_now (gtask.c:1212)
==991919== by 0x4EC92AA: g_task_return (gtask.c:1281)
==991919== by 0x4EC9E34: g_task_return_pointer (gtask.c:1689)
==990910== 28 bytes in 1 blocks are definitely lost in loss record 1,943 of 5,051
==990910== at 0x483877F: malloc (vg_replace_malloc.c:309)
==990910== by 0x50D53DA: g_malloc (gmem.c:99)
==990910== by 0x50F19ED: g_slice_alloc (gslice.c:1024)
==990910== by 0x50F1A2D: g_slice_alloc0 (gslice.c:1050)
==990910== by 0x4A3FD4A: __qmi_message_dms_uim_get_pin_status_response_parse (qmi-dms.c:8212)
==990910== by 0x4A6AFEA: uim_get_pin_status_ready (qmi-dms.c:31662)
==990910== by 0x4EADC8B: g_simple_async_result_complete (gsimpleasyncresult.c:802)
==990910== by 0x4EADCBF: complete_in_idle_cb.lto_priv.0 (gsimpleasyncresult.c:814)
==990910== by 0x50CF4AE: g_idle_dispatch (gmain.c:5617)
==990910== by 0x50CC6F0: g_main_dispatch (gmain.c:3179)
==990910== by 0x50CD616: g_main_context_dispatch (gmain.c:3844)
==990910== by 0x50CD81B: g_main_context_iterate (gmain.c:3917)
When a QMI/MBIM device is unplugged, we first get the notification
from the proxy that the communication is broken, and then we get the
kernel event reporting that the cdc-wdm port is gone.
If we reprobe the device as soon as the proxy notifies us that the
communication is broken, we would end up trying to reprobe the cdc-wdm
port when it's already gone, and we end up trying to create a modem
object when we shouldn't:
<debug> [1577963152.429386] (ttyUSB0) unexpected port hangup!
<debug> [1577963152.429506] (ttyUSB0) forced to close port
<debug> [1577963152.429546] (ttyUSB0) device open count is 0 (close)
<debug> [1577963152.429582] (ttyUSB0) closing serial port...
<debug> [1577963152.429653] (ttyUSB0) serial port closed
<debug> [1577963152.430340] (ttyUSB2) unexpected port hangup!
<debug> [1577963152.430391] (ttyUSB2) forced to close port
<debug> [1577963152.430418] (ttyUSB2) device open count is 0 (close)
<debug> [1577963152.430451] (ttyUSB2) closing serial port...
<debug> [1577963152.430517] (ttyUSB2) serial port closed
<info> [1577963152.436932] (tty/ttyUSB0): released by device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3'
<info> [1577963152.439176] (tty/ttyUSB1): released by device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3'
<info> [1577963152.440409] (tty/ttyUSB2): released by device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3'
<info> [1577963152.447977] (net/wwan1): released by device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3'
Cannot read from istream: connection broken
<info> [1577963152.458878] Connection to qmi-proxy for /dev/cdc-wdm1 lost, reprobing
<debug> [1577963152.459144] [device /sys/devices/pci0000:00/0000:00:14.0/usb2/2-3] unexported modem from path '/org/freedesktop/ModemManager1/Modem/1'
<debug> [1577963152.460151] (ttyUSB1) forced to close port
<info> [1577963152.460182] [device /sys/devices/pci0000:00/0000:00:14.0/usb2/2-3] creating modem with plugin 'Sierra' and '1' ports
<debug> [1577963152.460199] QMI-powered Sierra modem found...
<debug> [1577963152.460382] (cdc-wdm1) type 'qmi' claimed by /sys/devices/pci0000:00/0000:00:14.0/usb2/2-3
<debug> [1577963152.460417] Modem (Sierra) '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3' completely disposed
<warn> [1577963152.460431] Could not recreate modem for device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3': Failed to find a net port in the QMI modem
<debug> [1577963152.460526] Modem (Sierra) '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3' completely disposed
<info> [1577963152.460627] (usbmisc/cdc-wdm1): released by device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3'
<debug> [1577963152.460666] Removing empty device '/sys/devices/pci0000:00/0000:00:14.0/usb2/2-3'
Fix this by delaying the reprobing attempt some time, and make sure we
cancel the reprobing if the device detects that all ports are gone.
Instead of having the reference to the object manager server only
while the modem is exported, just keep a reference for as long as the
device object exists. This will make it easier to handle reprobing
logic.
The request for forced registration is an implementation detail of
mm_iface_modem_3gpp_register_in_network(), not part of any state to
keep in the private info.
We should not assume that a manual registration request to a given
operator is successful if the modem is already registered in that
operator, because if the registration was due to an automatic process,
we cannot make sure the modem won't roam to a different network.
We should only assume that a manual registration is not needed to be
relaunched if the modem is already registered in the requested network
AND if the registration process was manual (i.e. we asked the modem to
lock into a given network).
If the modem (e.g. u-blox LARA) returns a "Not supported" error when
attempting to run +COPS=1,2,<mccmnc> with the MCCMNC encoded in ASCII
(and current charset is different, e.g. UCS2), then attempt to re-run
the same command with the MCCMNC encoded in the explicit current
charset.
<debug> (ttyACM0): --> 'AT+COPS=1,2,"21404"<CR>'
<debug> (ttyACM0): <-- '<CR><LF>+CME ERROR: 4<CR><LF>'
<debug> Got failure code 4: Operation not supported
<debug> (ttyACM0): --> 'AT+COPS=1,2,"00320031003400300034"<CR>'
<debug> (ttyACM0): <-- '<CR><LF>+CME ERROR: 111<CR><LF>
If the charset selected via CSCS is UCS2, the modem may decide to
return all the strings in the +COPS=? response in UCS2:
<debug> (ttyACM0): --> 'AT+COPS=?<CR>'
<debug> (ttyACM0): <-- '<CR><LF>+COPS: (2,"004D006F007600690073007400610072","004D006F007600690073007400610072","00320031003400300037",7)
<debug> Found network '00320031003400300037' ('004D006F007600690073007400610072','004D006F007600690073007400610072'); availability: current, access tech: lte
If the Simple.Connect() operation fails before the bearer connection
process starts (e.g. during the previous SIM-PIN checks or explicit
registration attempt), the ongoing connect cancellable is not being
properly cleared, and this would prevent additional new connection
attempts unless an explicit Simple.Disconnect() is called.
$ sudo mmcli -m 1 --simple-connect="operator-id=21403,apn=internet"
error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.MobileEquipment.NetworkTimeout: Network timeout'
$ sudo mmcli -m 1 --simple-connect="operator-id=21403,apn=internet"
error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.InProgress: Connection request forbidden: operation already in progress'
$ sudo mmcli -m 1 --simple-connect="operator-id=21403,apn=internet"
error: couldn't connect the modem: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.InProgress: Connection request forbidden: operation already in progress'
Fix this, by making sure the ongoing connect cancellable is always
cleared when completing the DBus method invocation that created it.
Fixes https://gitlab.freedesktop.org/mobile-broadband/ModemManager/issues/169
Defining the new error codes in the headers is not enough, we also
need to add support in the error helpers in order to create proper
GErrors with the expected error codes.
We don't want the connection status checks to interfere with the
disconnection logic, e.g. if they're both using the same TTY for both
things.
E.g. the CGACT? from the conncheck gets in the way of the
disconnection logic:
<debug> [1576037519.710684] Flashing data port (ttyUSB1)...
<debug> [1576037519.710740] (ttyUSB1): port attributes not fully set
<debug> [1576037520.287636] (ttyUSB1) device open count is 3 (open)
<debug> [1576037520.287804] (ttyUSB1): --> 'AT+CGACT?<CR>'
<debug> [1576037520.711067] (ttyUSB1) device open count is 2 (close)
<debug> [1576037520.711127] (ttyUSB1): running init sequence...
<debug> [1576037520.711231] PDP disconnection already sent
<debug> [1576037520.711263] Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0'
Instead, fully skip all conncheck and stat updates as long as the
modem is not connected. The actual conncheck and stat update timeouts
will be removed once completely disconnected, as it was before.
If the modem is connected using the primary port, we can just rely on
the secondary port.
# mmcli --call 0 --start
error: couldn't start the call: 'GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Connected: Cannot run sequence: port is connected'
When we try to disconnect a bearer and the bearer is already
disconnected (e.g. after a cancelled connection attempt), avoid reporting
that as an error:
<warn> [1575287560.433398] Error disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0': 'Couldn't disconnect QMI bearer: this bearer is not connected'. Will assume disconnected anyway.
If a WDS indication is received telling us that the modem is no longer
connected, abort the ongoing connection attempt right away with an
error and cleanup all allocated clients (implicitly disconnecting them
if required)..
Fixes https://gitlab.freedesktop.org/mobile-broadband/ModemManager/issues/155
If the bearer is using a QMI port that is not the primary one, we need
to explicitly open it during the connection attempt. Keep track of
that, and make sure we close it during normal disconnection or if the
connection attempt fails.
If we blindly try to use QMI over MBIM on devices that don't support
it, the logic works ok but it's very slow, given that the QMI device
open operation has several internal retries, and all those end up
timing out.
Avoid that lost time by checking the list of services supported by the
MBIM modem, and if the QMI over MBIM service is not listed, we'll
avoid trying to open the QMI device right away.
Until now we had only a 2500ms timeout initialized since the first
port was exposed until we decided we were ready to consider all ports
notified by the kernel.
With this new logic, we add an additional condition: even if the
2500ms initial timeout has elapsed already, we leave an additional
1500ms since the last port addition for new ports to appear.
This new logic is useful when relying on the ReportKernelEvent() DBus
method, as it is the user the one responsible for reporting the kernel
events instead of udev. Now, the user is not forced to make sure all
ports are exposed in 2500ms; instead, we also allow ports to be
reported in more than 2500ms as long as the time between port
additions reported is less than 1500ms.
Note that this does not mean that the whole probing time will now
always be 4000ms. On well behaved systems (like when based on udev)
this new 'extra' probing timeout may expire long before the 'min'
probing timeout we already had as well.
E.g. in this setup, the reporting of the NET port was done 1100ms
later than the last ttyUSB3, and that was already too late as the
original 2500ms threshold had already expired.
[1573536994.593874] (tty/ttyUSB0): first port in device /sys/devices/platform/ehci-platform/usb1/1-1
[1573536994.596659] [plugin manager] task 1: port grabbed: ttyUSB0
[1573536995.093579] (tty/ttyUSB1): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
[1573536995.094172] [plugin manager] task 1: port grabbed: ttyUSB1
[1573536995.603206] (tty/ttyUSB2): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
[1573536995.603822] [plugin manager] task 1: port grabbed: ttyUSB2
[1573536996.111564] (tty/ttyUSB3): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
[1573536996.112257] [plugin manager] task 1: port grabbed: ttyUSB3
[1573536996.814816] [device /sys/devices/platform/ehci-platform/usb1/1-1] creating modem with plugin 'Quectel' and '4' ports
[1573536997.265820] (net/wwan0): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
[1573536997.296935] (usbmisc/cdc-wdm0): additional port in device /sys/devices/platform/ehci-platform/usb1/1-1
If we know that the LTE attach status/configuration CIDs in the Basic
Connect Extensions service are unsupported, don't even try to use
them, so that we avoid timeouts in the requests.
[11642]: <debug> [1573665255.321490] Couldn't reload current power state: QMI operation failed: Transaction timed out
[11642]: <debug> [1573665255.321697] No need to change power state: already in 'on' power state
[11642]: <debug> [1573665255.330864] Modem (Quectel) '/sys/devices/platform/ehci-platform/usb1/1-1' completely disposed
**
ERROR:mm-iface-modem-simple.c:44:private_free: assertion failed: (!priv->ongoing_connect)
If the modem goes away in the middle of a connection attempt, there's
no explicit connection cancellation performed, we just cleanup the
modem object. In this case, the ongoing attempt cancellable will still
exist, so just clean it up as well.
Aleksander Morgado
Amol Lad