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