Unable to get IPv4 over LTE

[Dan Williams]

On Tue, 2016-01-19 at 23:59 +0100, Aleksander Morgado wrote:
> Hey Vincent!
> 
> On Tue, Jan 19, 2016 at 10:08 PM, Vincent Bernat <bernat at luffy.cx>
> wrote:
> > I got an odd problem since some time.
> > 
> > Bus 002 Device 045: ID 1199:a001 Sierra Wireless, Inc.
> > ii  modemmanager      1.4.12-1      amd64         D-Bus service for
> > managing modems
> > Linux zoro 4.3.0-1-amd64 #1 SMP Debian 4.3.3-5 (2016-01-04) x86_64
> > GNU/Linux
> > 
> > When I am connected over LTE for the first time since a few days, I
> > cannot get an IPv4. NM just starts a dhclient and the dhclient
> > doesn't
> > get an IP.
> > 
> > NetworkManager[6880]: <info>  (cdc-wdm0): Activation: starting
> > connection 'Sunrise' (fbce8984-7556-44e9-ad99-32d61e7fed7
> > NetworkManager[6880]: <info>  (cdc-wdm0): device state change:
> > disconnected -> prepare (reason 'none') [30 40 0]
> > NetworkManager[6880]: <info>  NetworkManager state is now
> > CONNECTING
> > ModemManager[6866]: <info>  Simple connect started...
> > ModemManager[6866]: <info>  Simple connect state (4/8): Wait to get
> > fully enabled
> > ModemManager[6866]: <info>  Simple connect state (5/8): Register
> > ModemManager[6866]: <info>  Simple connect state (6/8): Bearer
> > ModemManager[6866]: <info>  Simple connect state (7/8): Connect
> > ModemManager[6866]: <info>  Modem
> > /org/freedesktop/ModemManager1/Modem/0: state changed (registered 
> > -> connecting)
> > NetworkManager[6880]: <info>  (cdc-wdm0): modem state changed,
> > 'registered' --> 'connecting' (reason: user-requested)
> > ModemManager[6866]: <info>  Modem
> > /org/freedesktop/ModemManager1/Modem/0: state changed (connecting 
> > -> connected)
> > ModemManager[6866]: <info>  Simple connect state (8/8): All done
> > NetworkManager[6880]: <info>  (cdc-wdm0): modem state changed,
> > 'connecting' --> 'connected' (reason: user-requested)
> > NetworkManager[6880]: <info>  (cdc-wdm0): device state change:
> > prepare -> config (reason 'none') [40 50 0]
> > NetworkManager[6880]: <info>  (cdc-wdm0): device state change:
> > config -> ip-config (reason 'none') [50 70 0]
> > NetworkManager[6880]: <info>  Activation (wwan0) Beginning DHCPv4
> > transaction (timeout in 15 seconds)
> > NetworkManager[6880]: <info>  dhclient started with pid 7248
> > NetworkManager[6880]: <info>  (cdc-wdm0): IPv6 configuration
> > disabled
> > dhclient[7248]: DHCPDISCOVER on wwan0 to 255.255.255.255 port 67
> > interval 5
> > dhclient[7248]: DHCPDISCOVER on wwan0 to 255.255.255.255 port 67
> > interval 10
> > dhclient[7248]: DHCPDISCOVER on wwan0 to 255.255.255.255 port 67
> > interval 15
> > NetworkManager[6880]: <warn>  (wwan0): DHCPv4 request timed out.
> > NetworkManager[6880]: <info>  (wwan0): DHCPv4 state changed unknown
> > -> timeout
> > NetworkManager[6880]: <info>  (wwan0): canceled DHCP transaction,
> > DHCP client pid 7248
> > NetworkManager[6880]: <info>  (wwan0): DHCPv4 state changed timeout
> > -> done
> > 
> > When I am not over LTE, the steps are different:
> > 
> > ModemManager[8662]: <info>  Simple connect state (8/8): All done
> > NetworkManager[8676]: <info>  (cdc-wdm0): modem state changed,
> > 'connecting' --> 'connected' (reason: user-requested)
> > NetworkManager[8676]: <info>  (cdc-wdm0): device state change:
> > prepare -> config (reason 'none') [40 50 0]
> > NetworkManager[8676]: <info>  (cdc-wdm0): device state change:
> > config -> ip-config (reason 'none') [50 70 0]
> > NetworkManager[8676]: <info>  (cdc-wdm0): IPv4 static
> > configuration:
> > NetworkManager[8676]: <info>    address 10.129.4.193/24
> > NetworkManager[8676]: <info>    gateway 10.129.4.1
> > NetworkManager[8676]: <info>    DNS 10.200.102.243
> > NetworkManager[8676]: <info>    DNS 10.200.102.244
> > [...]
> > 
> > After that, it works just fine. If I happen to switch back to LTE
> > during
> > the connection, the connection keeps working. If I disconnect and
> > reconnect over LTE, it connects immediately.
> > 
> > I don't remember exactly when things has changed, but it worked
> > fine in
> > the past over LTE. I have tried with three different carriers with
> > the
> > same symptoms. If I use the modem daily, I have no problem
> > connecting. If I don't connect for a week, I have to find a way to
> > not
> > be over LTE to be able to connect the first time.
> 
> That's weird.
> 
> Would be interesting to see what ModemManager says in each of those
> tries (--debug); and check which are the IP details given by the
> modem
> for each case, before we even try to run the DHCP client. Could you
> gather logs for both situations?
> 
> Dan, maybe we should put the printed IP details as g_message()
> instead
> of g_debug()? They're probably worth having in the logs.

Sure; pushed to master and mm-1-4.

Dan