Quectel UC20: Correct way to get it up and running on embedded?

[Dan Williams]

On Mon, 2017-03-20 at 12:14 +0100, Einar Jón wrote:
> Hello,
> 
> We have an Quectel UC20 modem running with ModemManager. We are using
> the libmm python module (gi.repository.ModemManager) and no
> NetworkManager.
> This will be in hundreds of unattended embedded boxes, and losing the
> connection will require a site visit in many cases.
> 
> I have wwan0 set as dhcp, and dhclient is started automatically on
> "ifup wwan0".
> This kind of fits with what was said here:
> https://lists.freedesktop.org/archives/modemmanager-devel/2015-Decemb
> er/002419.html
> but much of the implementation has been guesswork and trial&error...

Let me preface my response by saying I have no idea what ifup/ifdown do
on your platform, and whether they correctly handle teardown of the
interface and DHCP.

> Our main issues:
> Operstate seems to be always UNKNOWN

You can basically ignore operstate.  You care about interface flags
instead (UP, DOWN, LOWER_UP, etc).

> "ip link set dev wwan0 up" and "ip link set dev wwan0 down" seem to
> do nothing.

Right.  That's normal Linux.  These set/clear the IFF_UP flag which
means "administratively up".  Which means that when the interface is
UP, it can do IP and other stuff.  When it's down, it can't.  That's
all.  It doesn't affect *what* addressing is done on the interface,
it's simply a pre-requisite for doing anything with the interface.

> We need to reset the connection once a day (with mmcli --disable),
> because of external reasons.

I presume the provider terminates the packet data session after 24h or
something like that?  Not uncommon.

> This mostly works, but sometimes we lose connectivity after the
> reconnect.
> In those cases I have 2 IP addresses in the interface, and ip route
> tells me that both of them are gateways.

Since MM doesn't do any IP address setup/teardown on the interface
itself, I wouldn't expect '--disable' alone to clean anything up.  When
disabling, you'll need to either have a process monitor the modem state
and call "ifdown" or do some other kind of cleanup, or do the ifdown
along with the --disable.

> "ifup wwan0 && ifdown wwan0" fixes the connection again without any
> action from the python script (this automatically starts a new
> dhclient and updates ip route).
> This seems to be just a timing issue, or a question of doing things
> in
> the right order.

The order would probably be to disconnect the bearer (mmcli -m X -b Y
--disconnect), "ifdown wwan0", "mmcli -m X --disable".

> My main questions:
> 1) what do I need to do to have a reliable connection?

That depends on quite a few things, many of them not ModemManager
related, so let's try to address them individually as they come up.

> 2) when do I need to do those things?
>   -  in what state should I call ifup ?

After the modem state becomes CONNECTED, or after the bearer
activation/connect returns successfully and you can retrieve the bearer
IP details from MM.  CONNECTED state requires that the bearer
activation be successful, so if you see CONNECTED you should be fine.

>   -  in what state should I call connect_bearer()? Any exceptions?

Bearer-interface specific operations require the modem to be in the
right state (eg, something like REGISTERED).  I would wait to connect a
bearer until the modem has found the network and registered.

If you use the Simple interface instead, you can call Simple.Connect()
at any time other than FAILED state, as the Simple interface will do
everything it can to get connected, including enabling the modem,
waiting for registration, and then starting the bearer.  That could
take a few minutes, but it's meant as a dead-simple interface.

> 3) I switch modem states really fast (from DISABLING to CONNECTING in
> under a second - see syslog below). Do some of these states need to
> wait a bit?

ModemManager won't return from the D-Bus requests for
disabling/enabling/connecting/etc until it's ready; if it does so and
the modem hasn't fully entered that state, I'd consider it a bug.

But I don't think that's your problem, see below.

> 4) Is ModemManager 1.4.10 too old? Are there any major improvements
> I'm missing from staying on Ubuntu 12.04?

Obviously we always recommend the most recent released version
(currently 1.6.x) but I can't think of anything specific that 1.4.x has
that you'd need in terms of bug fixes or features.

> NOTE: To find out the status of the connection, I check if the
> IfState
> is up or down (basically "grep wwan0  /run/network/ifstate"), instead
> of checking operstate (which is UNKNOWN no matter what I do).
> If ifstate is down I call "ifup wwan0" manually.
> When disconnecting (and on the pyhon startup), I call "ifdown wwan0"
> manually.

This could be part of the problem.  The network stack of your distro
(especially ifup/ifdown) has literally no idea what state the modem is
in.  There is no real connection between the modem firmware state and
the Linux-side network interface; it's just a packet tunnel.  Its
Linux-side state doesn't represent anything about the data connection
in the modem firmware itself.

While perhaps unfortunate, there are various reasons why this is the
case and I'm happy to explain further if you'd like.

The point being:

1) when the modem enters the CONNECTED state, call "ifup wwan0"
2) when the mode leaves the CONNECTED state, call "ifdown wwan0" and
wait for that to complete before doing anything else

don't bother checking the existing ifup/ifdown state because it may not
be accurate, because ifup/ifdown don't know anything about the actual
modem state.

One last comment about the double-address thing; it's in the logs below
but I'll say it here instead.

I don't think your process is waiting for "ifdown wwan0" to complete
before attempting to re-enable the modem.  ifdown may take a short
period of time to clean things up, including letting DHCP release the
address.

Mar 19 06:35:52 ifdown
Mar 19 06:35:52 re-enable
Mar 19 06:35:52 registered
Mar 19 06:35:53 dhclient is calling DISCOVER
Mar 19 06:36:53 dhclient gets a lease
Mar 19 06:37:16 ifup
Mar 19 06:37:17 finally CONNECTED state

I think the old dhclient process is sticking around requesting a lease
long before you're at the point where you call 'ifup'.  I'd suggest
waiting until the 'ifdown' completes before re-enabling the modem. 
That is likely where your duplicate addresses are coming from.

Dan

> Relevant python code:
> def handle_modem_state(self, oldState, state):
>     logging.debug('Handle modem state, old: ' +
> self.modem_state_str(oldState) + ' new: ' +
> self.modem_state_str(state))
>     if state == ModemManager.ModemState.DISABLED:
>         self.enable_modem()     # calls modemProxy.Enable(1, ...)
>     elif state == ModemManager.ModemState.ENABLED:
>         self.register_modem()   # calls modemProxy.Register(...)
>     elif state == ModemManager.ModemState.SEARCHING:
>         pass
>     elif state == ModemManager.ModemState.REGISTERED:
>         if oldState != ModemManager.ModemState.CONNECTING and
> oldState
> != ModemManager.ModemState.DISCONNECTING:
>             self.connect_bearer()  # get bearer from DBUS and connect
>     elif state == ModemManager.ModemState.CONNECTED:
>         self.triedPreferredOperator = False
>     elif state == ModemManager.ModemState.CONNECTING:
>         if not self.is_network_interface_up('wwan0'): # check
> operstate/ifstate
>             self.set_network_state('wwan0', 'up')     # calls ifup
> wwan0 in a new process
>     elif state == ModemManager.ModemState.DISABLING:
>         if self.is_network_interface_up('wwan0'):     # check
> operstate/ifstate
>             self.set_network_state('wwan0', 'down')   # calls ifdown
> wwan0 in a new process
> 
> result of: ip -4 a show dev wwan0 | grep -v forever
> 4: wwan0: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu 1500 qdisc pfifo_fast
> state UNKNOWN qlen 1000
>     inet XX.YY.197.125/30 brd XX.YY.197.127 scope global wwan0
>     inet XX.YY.80.188/30 brd XX.YY.80.191 scope global wwan0
> 
> /var/log/syslog with minor obfuscation - python script is
> "modemmonitor[1475]"
> # connection working before modem-reset
> Mar 19 06:35:51 ubuntu12 modem-reset: Performing daily modem reset:
> 'mmcli --disable --modem=0'
> Mar 19 06:35:51 ubuntu12 my_tunnel[3352]: AutoSSH2 stop
> Mar 19 06:35:51 ubuntu12 autossh[14671]: received signal to exit (15)
> Mar 19 06:35:51 ubuntu12 my_tunnel[3352]: AutoSSH2 stop: done
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Modem state: CONNECTED
> -> DISABLING
> Mar 19 06:35:52 ubuntu12 nslcd[1530]: [65b848] <passwd="*"> "*": name
> denied by validnames option
> Mar 19 06:35:52 ubuntu12 nslcd[1530]: [725ebb] <passwd="*"> "*": name
> denied by validnames option
> Mar 19 06:35:52 ubuntu12 my_tunnel[3396]: AutoSSH2 stop
> Mar 19 06:35:52 ubuntu12 my_tunnel[3396]: AutoSSH2 not running
> Mar 19 06:35:52 ubuntu12 my_tunnel[3396]: AutoSSH2 stop: done
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: ifdown wwan0 (for
> dchlient/ssh) returned my_tunnel[3396]: AutoSSH2
> stop#012my_tunnel[3396]: AutoSSH2 not running#012my_tunnel[3396]:
> AutoSSH2 stop: done
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Operator Code:
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Operator Name:
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Registration State:
> UNKNOWN
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Modem state: DISABLING
> -> DISABLED
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Enabling modem...
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Modem state: DISABLED ->
> ENABLING
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Operator Code: 20404
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Operator Name: DATA ONLY
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Registration State: HOME
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Modem state: ENABLING ->
> REGISTERED
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Current operator: 20404
> Mar 19 06:35:52 ubuntu12 modemmonitor[1475]: Modem state: REGISTERED
> -> CONNECTING
> Mar 19 06:35:53 ubuntu12 dhclient: DHCPDISCOVER on wwan0 to
> 255.255.255.255 port 67 interval 60
> Mar 19 06:35:54 ubuntu12 nslcd[1530]: [87a0be] <passwd=-1>
> ldap_start_tls_s() failed: Can't contact LDAP server: Transport
> endpoint is not connected (uri="ldap://ssh.example.com:389")
> Mar 19 06:35:54 ubuntu12 nslcd[1530]: [87a0be] <passwd=-1> failed to
> bind to LDAP server ldap://ssh.example.com:389: Can't contact LDAP
> server: Transport endpoint is not connected
> Mar 19 06:35:54 ubuntu12 nslcd[1530]: [87a0be] <passwd=-1> no
> available LDAP server found: Can't contact LDAP server
> Mar 19 06:35:54 ubuntu12 logger: Unloading CAN driver
> Mar 19 06:35:54 ubuntu12 nslcd[1530]: [8e8cbc] <passwd="*"> "*": name
> denied by validnames option
> Mar 19 06:35:54 ubuntu12 nslcd[1530]: [91daaa] <passwd=-1> no
> available LDAP server found: Server is unavailable
> Mar 19 06:35:54 ubuntu12 logger: Loading CAN driver
> Mar 19 06:35:54 ubuntu12 kernel: [410151.671069] pch_can
> 0000:02:0c.3:
> irq 51 for MSI/MSI-X
> Mar 19 06:35:54 ubuntu12 kernel: [410151.671121] pch_can 0000:02:0c.3
> (unregistered net_device): PCH CAN opened with MSI
> Mar 19 06:35:54 ubuntu12 nslcd[1530]: [66d378] <passwd="*"> "*": name
> denied by validnames option
> Mar 19 06:36:07 ubuntu12 ntpdate[3606]: adjust time server
> 46.243.26.34 offset 0.000085 sec
> Mar 19 06:36:11 ubuntu12 acpid: client 2632[0:0] has disconnected
> Mar 19 06:36:11 ubuntu12 acpid: client connected from 3986[0:0]
> Mar 19 06:36:11 ubuntu12 acpid: 1 client rule loaded
> Mar 19 06:36:53 ubuntu12 dhclient: DHCPDISCOVER on wwan0 to
> 255.255.255.255 port 67 interval 1
> Mar 19 06:36:53 ubuntu12 dhclient: DHCPREQUEST of XX.YY.197.125 on
> wwan0 to 255.255.255.255 port 67
> Mar 19 06:36:53 ubuntu12 dhclient: DHCPOFFER of XX.YY.197.125 from
> XX.YY.197.126
> Mar 19 06:36:53 ubuntu12 dhclient: DHCPACK of XX.YY.197.125 from
> XX.YY.197.126
> Mar 19 06:36:53 ubuntu12 nslcd[1530]: [29fdc1] <passwd="*"> "*": name
> denied by validnames option
> Mar 19 06:36:54 ubuntu12 dhclient: bound to XX.YY.197.125 -- renewal
> in 2886 seconds.
> Mar 19 06:36:54 ubuntu12 my_tunnel[4118]: AutoSSH2 start
> Mar 19 06:37:04 ubuntu12 nslcd[1530]: [802c05] <passwd=-1>
> ldap_start_tls_s() failed: Can't contact LDAP server: Connection
> timed
> out (uri="ldap://ssh.example.com:389")
> Mar 19 06:37:04 ubuntu12 nslcd[1530]: [802c05] <passwd=-1> failed to
> bind to LDAP server ldap://ssh.example.com:389: Can't contact LDAP
> server: Connection timed out
> Mar 19 06:37:04 ubuntu12 nslcd[1530]: [802c05] <passwd=-1> no
> available LDAP server found: Can't contact LDAP server
> Mar 19 06:37:04 ubuntu12 autossh[4150]: port set to 0, monitoring
> disabled
> Mar 19 06:37:04 ubuntu12 autossh[4151]: starting ssh (count 1)
> Mar 19 06:37:04 ubuntu12 autossh[4151]: ssh child pid is 4152
> Mar 19 06:37:04 ubuntu12 my_tunnel[4118]: AutoSSH2 start: done
> Mar 19 06:37:04 ubuntu12 nslcd[1530]: [2a1dc5] <passwd="*"> "*": name
> denied by validnames option
> Mar 19 06:37:16 ubuntu12 ntpdate[4201]: no server suitable for
> synchronization found
> Mar 19 06:37:16 ubuntu12 modemmonitor[1475]: ifup wwan0 (for
> dchlient/ssh) returned my_tunnel[4118]: AutoSSH2
> start#012my_tunnel[4118]: AutoSSH2 start: done#012ssh
> stop/waiting#012ssh start/running, process 4209
> Mar 19 06:37:17 ubuntu12 modemmonitor[1475]: Modem state: CONNECTING
> -> CONNECTED
> Mar 19 06:39:11 ubuntu12 /usr/bin/ssh[4152]: error: ssh: connect to
> host ssh.example.com port 22: Connection timed out
> Mar 19 06:39:11 ubuntu12 autossh[4151]: ssh exited with error status
> 255; restarting ssh
> Mar 19 06:39:11 ubuntu12 autossh[4151]: starting ssh (count 2)
> Mar 19 06:39:11 ubuntu12 autossh[4151]: ssh child pid is 4492
> # connection broken from now on
> 
> ---- Hardware/software
> Ubuntu 12.04 with kernel 3.13.0-57-generic
> CPU : Intel(R) Atom(TM) CPU E680   @ 1.60GHz
> using qmi_wwan, cdc_wdm kernel modules
> ModemManager 1.4.10
> ----
> $ mmcli -m 0
> 
> /org/freedesktop/ModemManager1/Modem/0 (device id '4dd8d723ec[...]')
>   -------------------------
>   Hardware |   manufacturer: 'QUALCOMM INCORPORATED'
>            |          model: '0'
>            |       revision: 'UC20GQBR03A10E1G  1  [2014/05/05
> 9:00:00]'
>            |      supported: 'gsm-umts'
>            |        current: 'gsm-umts'
>            |   equipment id: '861075023803802'
> 
> 
> Best regards
> Einar Jón Gunnarsson
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel