Problems with Alcatel IK41 USB modem

Fredrik Yhlen fredrik.yhlen at endian.se
Sun Dec 12 01:26:19 UTC 2021 

Hi,

I have some trouble with Alcatel IK41 USB modem in both MBIM and PPP
mode. Have tested it with following ModemManager versions:
1.14.12-0.2,  1.16.6-2, 1.18.2-1.
The problem is that it disconnects right after it has connected and
then keeps doing that in a loop forever.

Can look like this:
```
c 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/bearer0]
connection through a plain serial AT port: ttyUSB0
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
device open count is 4 (open)
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
device open count is 3 (close)
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
--> 'ATD*99***3#<CR>'
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>CONNECT 150000000<CR><LF>'
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/bearer0]
setting flow control in ttyUSB0: rts-cts
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
enabling RTS/CTS flow control
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
port attributes not fully set
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
flow control settings updated to rts-cts
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
port now connected
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/bearer0] connected
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/bearer0] PPP
is required for connection, will ignore disconnection reports
Dec 05 00:26:54 xxxx ModemManager[769]: <info>  [modem0] state changed
(connecting -> connected)
Dec 05 00:26:54 xxxx ModemManager[769]: <info>  [modem0] simple
connect state (8/8): all done
Dec 05 00:26:54 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
device open count is 2 (close)
Dec 05 00:26:55 xxxx ModemManager[769]: <debug> [modem0/ttyUSB2/at]
<-- '<CR><LF>+CIEV: 7,2<CR><LF>'
Dec 05 00:26:56 xxxx ModemManager[769]: <debug> [base-manager] adding
port ppp0 at sysfs path: /sys/devices/virtual/net/ppp0
Dec 05 00:26:56 xxxx ModemManager[769]: <debug> [ppp0] could not get
vendor/product id
Dec 05 00:26:56 xxxx ModemManager[769]: <debug> [filter] (net/ppp0)
port filtered: virtual device
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0] user request
to disconnect modem (all bearers)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/bearer0]
disconnecting...
Dec 05 00:26:57 xxxx ModemManager[769]: <info>  [modem0] state changed
(connected -> disconnecting)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/bearer0]
sending PDP context deactivation in secondary port...
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB2/at]
device open count is 2 (open)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB2/at]
--> 'AT+CGACT=0,3<CR>'
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0] user request
to disconnect modem (all bearers)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB2/at]
<-- '<CR><LF>OK<CR><LF>'
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/bearer0]
reopening data port ttyUSB0...
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
reopening port (2)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
device open count is 1 (close)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
device open count is 0 (close)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
closing serial port...
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
port now disconnected
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
serial port closed
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0/ttyUSB2/at]
device open count is 1 (close)
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0] user request
to connect modem
Dec 05 00:26:57 xxxx ModemManager[769]: <info>  [modem0] simple
connect started...
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    PIN: unspecified
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    operator
ID: unspecified
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    allowed roaming: yes
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    APN:
services.telenor.se
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    IP family: ipv4v6
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    allowed
authentication: unspecified
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    User: unspecified
Dec 05 00:26:57 xxxx ModemManager[769]: <debug> [modem0]    Password:
unspecified
Dec 05 00:26:57 xxxx ModemManager[769]: <info>  [modem0] simple
connect state (4/8): wait to get fully enabled
Dec 05 00:26:58 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
opening serial port...
Dec 05 00:26:58 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
setting up baudrate: 57600
Dec 05 00:26:58 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at] no
flow control explicitly requested for device
Dec 05 00:26:58 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
port attributes not fully set
Dec 05 00:26:58 xxxx ModemManager[769]: <debug> [modem0/ttyUSB0/at]
device open count is 1 (open)
```

or
```
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0] user request
to disconnect modem (all bearers)
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB2/at]
<-- '<CR><LF>OK<CR><LF>'
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/bearer0]
reopening data port ttyUSB0...
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
reopening port (2)
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 1 (close)
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 0 (close)
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
closing serial port...
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
port now disconnected
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
serial port closed
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0/ttyUSB2/at]
device open count is 1 (close)
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0] user request
to connect modem
Dec 02 17:21:30 xxxx ModemManager[778]: <info>  [modem0] simple
connect started...
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    PIN: unspecified
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    operator
ID: unspecified
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    allowed roaming: yes
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    APN:
services.telenor.se
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    IP family: ipv4v6
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    allowed
authentication: unspecified
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    User: unspecified
Dec 02 17:21:30 xxxx ModemManager[778]: <debug> [modem0]    Password:
unspecified
Dec 02 17:21:30 xxxx ModemManager[778]: <info>  [modem0] simple
connect state (4/8): wait to get fully enabled
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
opening serial port...
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
setting up baudrate: 57600
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at] no
flow control explicitly requested for device
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
port attributes not fully set
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 1 (open)
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 2 (open)
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/bearer0]
flashing data port ttyUSB0...
Dec 02 17:21:31 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
port attributes not fully set
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 1 (close)
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
running init sequence...
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/bearer0] PDP
disconnection already sent
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/bearer0] disconnected
Dec 02 17:21:32 xxxx ModemManager[778]: <info>  [modem0] state changed
(disconnecting -> registered)
Dec 02 17:21:32 xxxx ModemManager[778]: <info>  [modem0] simple
connect state (5/8): register
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0] already
registered automatically in network '24008', automatic registration
not launched...
Dec 02 17:21:32 xxxx ModemManager[778]: <info>  [modem0/bearer0]
connection #3 finished: duration 3s, tx: 0 bytes, rx :0 bytes
Dec 02 17:21:32 xxxx ModemManager[778]: <info>  [modem0] simple
connect state (6/8): bearer
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0] Using already
existing bearer at '/org/freedesktop/ModemManager1/Bearer/0'...
Dec 02 17:21:32 xxxx ModemManager[778]: <info>  [modem0] simple
connect state (7/8): connect
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/bearer0] connecting...
Dec 02 17:21:32 xxxx ModemManager[778]: <info>  [modem0] state changed
(registered -> connecting)
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/bearer0]
launching 3GPP connection attempt with APN 'services.telenor.se'
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/bearer0]
checking context definition format...
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 2 (open)
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
--> 'ATE0<CR>'
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>OK<CR><LF>'
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
--> 'ATV1<CR>'
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>OK<CR><LF>'
Dec 02 17:21:32 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
--> 'AT+CMEE=1<CR>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>OK<CR><LF>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
--> 'ATX4<CR>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>OK<CR><LF>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
--> 'AT&C1<CR>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>OK<CR><LF>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]
unhandled PDP type in CGDCONT=? reply: 'PPP'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]
checking currently defined contexts...
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 3 (open)
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 2 (close)
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
--> 'AT+CGDCONT?<CR>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>+CGDCONT:
1,"IPV4V6","","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0<CR><LF>+CGDCONT:
2,"IPV4V6","","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0<CR><LF>+CGDCONT:
3,"IPV4V6","services.telenor.se","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0<CR><LF>+CGDCONT:
4,"IP","services.telenor.se","0.0.0.0",0,0,0,0<CR><LF><CR><LF>OK<CR><LF>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0] found
4 PDP contexts
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]   PDP
context [cid=1] [type='ipv4v6'] [apn='']
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]   PDP
context [cid=2] [type='ipv4v6'] [apn='']
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]   PDP
context [cid=3] [type='ipv4v6'] [apn='services.telenor.se']
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]   PDP
context [cid=4] [type='ipv4'] [apn='services.telenor.se']
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]
looking for best CID matching APN 'services.telenor.se' and PDP type
'ipv4v6'...
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0] found
exact context at CID 3
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 3 (open)
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]
connection through a plain serial AT port: ttyUSB0
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 4 (open)
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
device open count is 3 (close)
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
--> 'ATD*99***3#<CR>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
<-- '<CR><LF>CONNECT 150000000<CR><LF>'
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0]
setting flow control in ttyUSB0: rts-cts
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
enabling RTS/CTS flow control
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
port attributes not fully set
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
flow control settings updated to rts-cts
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/ttyUSB0/at]
port now connected
Dec 02 17:21:33 xxxx ModemManager[778]: <debug> [modem0/bearer0] connected
```

I don't know what causes the problem but I know that for some reason it matters
if the correct PDP is at index 1 or not. If it is, the modem will connect
fine and also works after successive reboots, at least with PPP, but if not then
it will simply never connect.
This issue can occur when the modem gets powered on with an empty PDP list and
nothing handles the modem for a while, for example during a system bootup when
it takes some time before modemmanager is up and running. Then the modem
adds its own garbage PDP at index 1 and tries connect with it. And I'm not
sure why this matters because modemmanager identifies the correct index and
PDP to use. Maybe it doesn't deactivate the PDP that the modem itself has
already activated, because it always seems to work when the correct PDP is
at index 1.

Example when it doesn't work:
```
+CGDCONT: 1,"IPV4V6","","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0
+CGDCONT: 2,"IPV4V6","","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0
+CGDCONT: 3,"IPV4V6","services.telenor.se","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0

OK
```

Example when it does work:
```
AT+CGACT?

+CGACT: 1,1
+CGACT: 2,0

OK
AT+CGDCONT?

+CGDCONT: 1,"IPV4V6","services.telenor.se","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0
+CGDCONT: 2,"IPV4V6","","0.0.0.0.0.0.0.0.0.0.0.0.0.0.0.0",0,0,0,0

OK
AT+CGATT?

+CGATT: 1

OK
``
So the current workaround solution is:
1. Clear all PDPs manually + detach with CGATT=0
2. restart modemmanager so it adds correct PDP at index 1

After that nothing more needs to be done - it will continue to work after
rebooting the system several times or hotplugging the modem.
It also doesn't matter if garbage PDP gets added to the next
available index, which in this case is 2 or 3.

Another workaround is to just detach from packet domain service with
CGATT=0, but then this needs to be done every time.

Any of you have any idea whats really going on here and do you have a
better solution for this?

Thanks!

Best regards,
Fredrik

More information about the ModemManager-devel mailing list