If QMI support was not compiled in, then every net port that wasn't
a QMI port would be force-ignored unless it had the qmi_wwan driver.
Instead, we want to ignore ports with only the qmi_wwan driver.
There are modems out there (e.g. SIM7600E) where we connect a given
CID >1 but once connected, only CID=1 is reported as connected, and
not the one we explicitly attempted to connect. In this situation the
modem is connected successfully, and we're properly ignoring the
disconnection report detected from CGACT? responses, but we're
probably better logging this situation only in debug level, not as
info, because this check is done periodically every 5s...
<debug> [1568649020.333263] (ttyUSB5): --> 'AT+CGDCONT=7,"IP","inet.es"<CR>'
<debug> [1568649020.383517] (ttyUSB5): <-- '<CR><LF>OK<CR><LF>'
<debug> [1568649020.383617] (ttyUSB5) device open count is 3 (open)
<debug> [1568649020.383655] Connection through a plain serial AT port (ttyUSB5)
<debug> [1568649020.383683] (ttyUSB5) device open count is 4 (open)
<debug> [1568649020.383802] (ttyUSB5) device open count is 3 (close)
<debug> [1568649020.383873] (ttyUSB5): --> 'ATD*99***7#<CR>'
<debug> [1568649020.405767] (ttyUSB5): <-- '<CR><LF>CONNECT 115200<CR><LF>'
<debug> [1568649020.405853] [ttyUSB5] Setting flow control: rts-cts
<debug> [1568649020.405878] (ttyUSB5): enabling RTS/CTS flow control
<debug> [1568649020.405897] (ttyUSB5): port attributes not fully set
<debug> [1568649020.405910] (ttyUSB5): flow control settings updated to rts-cts
<debug> [1568649020.405940] (ttyUSB5): port now connected
<debug> [1568649020.405983] Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
<debug> [1568649020.406081] PPP is required for connection, will ignore disconnection reports
<info> [1568649020.406155] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
<info> [1568649020.406361] Simple connect state (8/8): All done
<debug> [1568649020.406461] (ttyUSB5) device open count is 2 (close)
<debug> [1568649020.448483] (net/ppp0): adding device at sysfs path: /sys/devices/virtual/net/ppp0
<debug> [1568649020.448738] (net/ppp0) could not get vendor/product id
<debug> [1568649020.448776] [filter] (net/ppp0) port filtered: virtual device
<debug> [1568649050.395662] (ttyUSB6) device open count is 2 (open)
<debug> [1568649050.395871] (ttyUSB6): --> 'AT+CGACT?<CR>'
<debug> [1568649050.408638] (ttyUSB6): <-- '<CR><LF>+CGACT: 1,1<CR><LF>+CGACT: 2,0<CR><LF>+CGACT: 3,0<CR><LF>+CGACT: 4,0<CR><LF>+CGACT: 5,0<CR><LF>+CGACT: 6,0<CR><LF>+CGACT: 7,0<CR><LF><CR><LF>OK<CR><LF>'
<debug> [1568649050.408803] connection status loaded: disconnected
---> <info> [1568649050.408825] ignoring disconnection report for bearer '/org/freedesktop/ModemManager1/Bearer/0'
<debug> [1568649050.408848] (ttyUSB6) device open count is 1 (close)
<debug> [1568649055.398994] (ttyUSB6) device open count is 2 (open)
<debug> [1568649055.399084] (ttyUSB6): --> 'AT+CGACT?<CR>'
<debug> [1568649055.411489] (ttyUSB6): <-- '<CR><LF>+CGACT: 1,1<CR><LF>+CGACT: 2,0<CR><LF>+CGACT: 3,0<CR><LF>+CGACT: 4,0<CR><LF>+CGACT: 5,0<CR><LF>+CGACT: 6,0<CR><LF>+CGACT: 7,0<CR><LF><CR><LF>OK<CR><LF>'
<debug> [1568649055.411652] connection status loaded: disconnected
---> <info> [1568649055.411674] ignoring disconnection report for bearer '/org/freedesktop/ModemManager1/Bearer/0'
And added support for several new things, including:
* Setting "any" band now attempts to set all supported bands.
* Added new 2G band value '5' (egsm+dcs+pcs+g850).
* Setup support for two different 3G band combinations, a default one
plus an alternate one applicable to the LM940/960 models only. The
alternate combination is selected via udev tags.
During the refactor, the following Telit-specific helpers were also
removed and exchanged with more generic counterparts.
* mm_telit_bands_contains() -> mm_common_bands_garray_lookup()
* mm_telit_get_band_flags_from_string() -> mm_parse_uint_list()
If all CS/PS/EPS report 'denied', we should not report 'unknown' as
consolidated...
<debug> [1568556573.833928] building consolidated registration state: cs 'denied', ps 'denied', eps 'denied' --> 'unknown'
From 5s to 20s, as it seems it could take much more to complete and
get a response, as seen in the logs below.
<debug> [1568553228.546862] (ttyUSB3): --> 'AT+CNSMOD=1<CR>'
<debug> [1568553233.799470] (ttyUSB3): --> 'AT+AUTOCSQ=1,1<CR>'
<debug> [1568553238.798866] (ttyUSB3) setting up 3GPP unsolicited registration messages handlers
<debug> [1568553238.798932] (ttyUSB2) setting up 3GPP unsolicited registration messages handlers
<debug> [1568553238.798990] (ttyUSB3) device open count is 1 (close)
<warn> [1568553238.799029] (tty/ttyUSB3) at port timed out 2 consecutive times
<debug> [1568553238.799094] (ttyUSB3) device open count is 2 (open)
<debug> [1568553238.799148] (ttyUSB3): --> 'AT+CREG=2<CR>'
<warn> [1568553241.798727] (tty/ttyUSB3) at port timed out 3 consecutive times
<debug> [1568553241.798799] (ttyUSB3): --> 'AT+CREG=1<CR>'
<debug> [1568553244.795389] Enabling unsolicited registration events in primary port failed: 'AT sequence failed'
<debug> [1568553244.795462] (ttyUSB2) device open count is 2 (open)
<debug> [1568553244.795507] (ttyUSB3) device open count is 1 (close)
<warn> [1568553244.795545] (tty/ttyUSB3) at port timed out 4 consecutive times
<debug> [1568553244.795588] (ttyUSB2): --> 'AT+CREG=2<CR>'
<debug> [1568553244.800815] (ttyUSB3): <-- '<CR><LF>OK<CR><LF><CR><LF>OK<CR><LF>'
<debug> [1568553244.801624] (ttyUSB3): <-- '<CR><LF>OK<CR><LF><CR><LF>OK<CR><LF>'
<debug> [1568553244.808710] (ttyUSB2): <-- '<CR><LF>OK<CR><LF>'
Very much like the MBIM implementation, we will now retry the lock
check if we get a 'SIM not inserted' error reported, because it may
very well be that the device has just been powered up and the SIM is
not fully detected yet.
If the modem interface reports that this is the last attempt to load
the lock status and the modem is still reporting no sim, then, we'll
report a hard error right away. Otherwise, we'll let the generic logic
retry the operation, instead of doing it ourselves.
The load_unlock_required() step will be automatically retried by the
generic interface logic unless some specific errors happen (e.g. it
won't be retried if a SIM missing error is received).
This patch allows telling the implementation of the method whether
this time being run is the last one before reporting a hard error or
not.
Rework how the broadband bearer runs CGDCONT? and CGDCONT=? and setup
a helper method to perform the CID selection logic.
Also, implement unit tests for the CID selection logic.
When looking for the first unused CID, we should also consider those
contexts defined with a different PDP type, not just the ones with the
same PDP type.
There are two places where we look for unused CIDs:
* First, while processing the list of existing contexts returned by
CGDCONT?, we look for gaps in the used CIDs. E.g. if the first
context has CID=1 and the next one has CID=3, we can definitely use
the unused CID=2.
* Then, while processing the response of CGDCONT=?, we try to see
whether there is any empty CID available after the last existing
one found. E.g. if the last existing context has CID=3 and the
format tells us that the max allowed CID is 16, we can definitely
use the unused CID=4.
In both these cases, we should prefer using such an unused CID found
to overwriting other CIDs that are already defined.
This logic will now overwrite existing CIDs only if there are no
unused CIDs, and the preference to overwrite is as follows:
* If there is any existing context defined without an explicit APN,
overwrite it.
* Otherwise, overwrite the last existing CID found.
* And in the worst case, when no list of contexts was loaded
properly (e.g. some Android phones don't allow querying), fallback
to overwriting CID=1.
When a modem reported back non-sequential CIDs, MM was using the next
larger CID number after the last CID found. In cases where the last CID
found was the highest numbered CID allowed and is not a modifiable CID,
MM would give up and fail to establish a data connection.
The above issue occurs on u-blox TOBY-R200 modems as of firmware 30.33
A02.02. In this firmware version there are two default CIDs programmed
into the modem, one at CID 1 and another at CID 31. The CID at 31 is
the highest CID number that can be used and cannot be modified.
This change makes it so while parsing CIDs for a match, if a jump in CID
numbers is detected, so not sequential, the first open CID will be used
before using the max CID +1 or replacing the max CID. If an exact
match for IP type and APN is found, then that will still be used first.
The Telit LE922 seems to take just a bit more than 3s to reply. Let's
increase it up to 10s to be on the safe side.
<debug> [1568385270.124866] (ttyUSB3): --> 'AT+CPIN?<CR>'
<debug> [1568385273.396659] Couldn't check if unlock required: 'Serial command timed out'
<warn> [1568385273.396847] Modem couldn't be initialized: Couldn't check unlock status: Serial command timed out
<info> [1568385273.397009] Modem: state changed (unknown -> failed)
<debug> [1568385273.397215] (ttyUSB3) device open count is 1 (close)
<debug> [1568385273.397268] Creating ports context for SIM hot swap
<debug> [1568385273.397289] (ttyUSB3) device open count is 2 (open)
<debug> [1568385273.397309] (ttyUSB4) opening serial port...
<debug> [1568385273.397676] (ttyUSB4): setting up baudrate: 57600
<debug> [1568385273.397699] (ttyUSB4): no flow control explicitly requested for device
<debug> [1568385273.397724] (ttyUSB4): port attributes not fully set
<debug> [1568385273.397760] (ttyUSB4) device open count is 1 (open)
<debug> [1568385273.397776] (ttyUSB4): running init sequence...
<debug> [1568385273.397856] Extended signal information reporting disabled
<debug> [1568385273.397927] Couldn't finish initialization in the current state: 'Modem is unusable, cannot fully initialize'
<debug> [1568385273.398432] [device /sys/devices/pci0000:00/0000:00:14.0/usb1/1-11/1-11.4/1-11.4.1] exported modem at path '/org/freedesktop/ModemManager1/Modem/0'
<debug> [1568385273.398464] [device /sys/devices/pci0000:00/0000:00:14.0/usb1/1-11/1-11.4/1-11.4.1] plugin: Telit
<debug> [1568385273.398484] [device /sys/devices/pci0000:00/0000:00:14.0/usb1/1-11/1-11.4/1-11.4.1] vid:pid: 0x1BC7:0x1040
<debug> [1568385273.398509] (ttyUSB3) device open count is 1 (close)
<debug> [1568385273.398546] (ttyUSB4): --> 'ATE0<CR>'
<debug> [1568385273.400412] (ttyUSB3): <-- '<CR><LF>+CPIN: READY<CR><LF><CR><LF>OK<CR><LF>'
<debug> [1568385273.404870] (ttyUSB4): <-- '<CR><LF>OK<CR><LF>'
On u-blox modems it has been observed that attempting to force down the
bearer when the modem had an active data connection, lost the connection
but the bearer is still up, and the modem is searching for the network,
ModemManager would timeout before the CGACT command could return. This
can put the modem in a state where the ModemManager state does not match
the modem's actual state of being connected.
When deactivating the current active bearer, the timeout has been
changed from 10 seconds to 45 seconds. u-blox modems can take up to 40
seconds to respond to deactivation requests through the AT+CGACT
command according to the u-blox AT command reference.
Several plugins define the specific device vid:pid pairs they
support. Let's use this information as a direct indication that
ModemManager can probe the devices.
If the reopening operation fails when attempting to recover the
previous open count, it could mean the port is already gone. We didn't
get a HUP in the TTY because the channel I/O monitoring isn't in place
during this time, so this is the best way to detect that at this
point.
And if we do see an error, we'll flag the port as forced closed so
that we do not attempt to reopen it again.
ModemManager[4219]: <debug> [1568123246.421399] Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[4219]: <info> [1568123246.421465] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
ModemManager[4219]: <debug> [1568123246.421698] Reopening data port (modemu)...
ModemManager[4219]: <debug> [1568123246.421722] (modemu) reopening port (2)
ModemManager[4219]: <debug> [1568123246.421740] (modemu) device open count is 1 (close)
ModemManager[4219]: <debug> [1568123246.421754] (modemu) device open count is 0 (close)
ModemManager[4219]: <debug> [1568123246.421770] (modemu) closing serial port...
ModemManager[4219]: <debug> [1568123246.421786] (modemu): port now disconnected
ModemManager[4219]: <debug> [1568123246.421816] (modemu) serial port closed
ModemManager[4219]: <info> [1568123248.028573] (tty/modemu): released by device '/sys/devices/pci0000:00/0000:00:00.0'
ModemManager[4219]: <debug> [1568123248.028637] Removing empty device '/sys/devices/pci0000:00/0000:00:00.0'
ModemManager[4219]: <debug> [1568123248.028866] Removing from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[4219]: <debug> [1568123248.028914] [device /sys/devices/pci0000:00/0000:00:00.0] unexported modem from path '/org/freedesktop/ModemManager1/Modem/0'
ModemManager[4219]: <debug> [1568123248.028944] Periodic signal checks disabled
ModemManager[4219]: <debug> [1568123256.401738] Connection monitoring is unsupported by the device
ModemManager[4219]: <debug> [1568123256.422939] (modemu) opening serial port...
ModemManager[4219]: <warn> [1568123256.423062] (modemu) could not open serial device (2)
ModemManager[4219]: <debug> [1568123256.423104] Couldn't disconnect bearer '/org/freedesktop/ModemManager1/Bearer/0': Couldn't reopen port (0): Could not open serial device modemu: No such file or directory
ModemManager[4219]: _close_internal: assertion 'self->priv->open_count > 0' failed
Thread 1 "ModemManager" received signal SIGTRAP, Trace/breakpoint trap.
0x00007ffff77894e6 in ?? () from /usr/lib/libglib-2.0.so.0
(gdb)
(gdb) bt
#0 0x00007ffff77894e6 in () at /usr/lib/libglib-2.0.so.0
#1 0x00007ffff7789738 in g_logv () at /usr/lib/libglib-2.0.so.0
#2 0x00007ffff777ff80 in g_log () at /usr/lib/libglib-2.0.so.0
#3 0x0000555555661115 in _close_internal (self=0x555555796380, force=0) at mm-port-serial.c:1378
#4 0x0000555555661865 in mm_port_serial_close (self=0x555555796380) at mm-port-serial.c:1503
#5 0x00005555556078cc in ports_context_unref (ctx=0x5555557c4ca0) at mm-broadband-modem.c:9801
#6 0x000055555560e33a in finalize (object=0x5555557a4250) at mm-broadband-modem.c:11940
#7 0x00007ffff787b351 in g_object_unref () at /usr/lib/libgobject-2.0.so.0
#8 0x00005555555b1c71 in detailed_disconnect_context_free (ctx=0x555555785000) at mm-broadband-bearer.c:1369
#9 0x00007ffff795d62a in () at /usr/lib/libgio-2.0.so.0
#10 0x00007ffff787b351 in g_object_unref () at /usr/lib/libgobject-2.0.so.0
#11 0x00005555555b2532 in data_reopen_3gpp_ready (data=0x555555796380, res=0x55555573a580, task=0x55555573a040) at mm-broadband-bearer.c:1605
#12 0x00007ffff795d584 in () at /usr/lib/libgio-2.0.so.0
#13 0x00007ffff7962a87 in () at /usr/lib/libgio-2.0.so.0
#14 0x0000555555661bc6 in reopen_do (self=0x555555796380) at mm-port-serial.c:1607
#15 0x00007ffff778e3c4 in () at /usr/lib/libglib-2.0.so.0
#16 0x00007ffff778ebb0 in g_main_context_dispatch () at /usr/lib/libglib-2.0.so.0
#17 0x00007ffff7790b11 in () at /usr/lib/libglib-2.0.so.0
#18 0x00007ffff7791a63 in g_main_loop_run () at /usr/lib/libglib-2.0.so.0
#19 0x000055555559afb0 in main (argc=3, argv=0x7fffffffea58) at main.c:181
We cannot complete the flash task cancellation right away because this
may be called from within _close_internal() during a forced port close
after the TTY has gone, which would mean the object is fully disposed
already after the flash cancellation has been requested.
By making the task cancellation complete in idle, we're sure that
there will be at least one reference valid (the one in the task)
during the port close operation.
ModemManager[25156]: <debug> [1568121341.696563] Modem (Generic) '/sys/devices/pci0000:00/0000:00:00.0' completely disposed
**
ERROR:mm-port-serial.c:2067:finalize: assertion failed: (self->priv->iochannel == NULL)
(gdb) bt
#0 0x00007ffff757c755 in raise () at /usr/lib/libc.so.6
#1 0x00007ffff7567851 in abort () at /usr/lib/libc.so.6
#2 0x00007ffff7741062 in () at /usr/lib/libglib-2.0.so.0
#3 0x00007ffff776d99d in g_assertion_message_expr () at /usr/lib/libglib-2.0.so.0
#4 0x0000555555662f0a in finalize (object=0x55555577a380) at mm-port-serial.c:2067
#5 0x0000555555664d81 in finalize (object=0x55555577a380) at mm-port-serial-at.c:632
#6 0x00007ffff787b351 in g_object_unref () at /usr/lib/libgobject-2.0.so.0
#7 0x00007ffff795d5eb in () at /usr/lib/libgio-2.0.so.0
#8 0x00007ffff787b351 in g_object_unref () at /usr/lib/libgobject-2.0.so.0
#9 0x0000555555662126 in mm_port_serial_flash_cancel (self=0x55555577a380) at mm-port-serial.c:1747
#10 0x0000555555661224 in _close_internal (self=0x55555577a380, force=1) at mm-port-serial.c:1397
#11 0x000055555566197b in port_serial_close_force (self=0x55555577a380) at mm-port-serial.c:1526
#12 0x000055555565fbe5 in common_input_available (self=0x55555577a380, condition=(G_IO_IN | G_IO_ERR | G_IO_HUP)) at mm-port-serial.c:971
#13 0x00005555556600c0 in iochannel_input_available (iochannel=0x55555578a0a0, condition=(G_IO_IN | G_IO_ERR | G_IO_HUP), data=0x55555577a380) at mm-port-serial.c:1073
#14 0x00007ffff778ebb0 in g_main_context_dispatch () at /usr/lib/libglib-2.0.so.0
#15 0x00007ffff7790b11 in () at /usr/lib/libglib-2.0.so.0
#16 0x00007ffff7791a63 in g_main_loop_run () at /usr/lib/libglib-2.0.so.0
#17 0x000055555559afb0 in main (argc=3, argv=0x7fffffffea58) at main.c:181
