Unable to get IPv4 over LTE

[Aleksander Morgado]

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.

-- 
Aleksander
https://aleksander.es