Hi, I'm seeing a DHCP issue with a particular router. This is with an older ConnMan release (0.72 plus a few local patches, none of which touch DHCP code). Unfortunately I am not able to upgrade this machine to a newer release or even test with another machine on the same network, but I think this issue may exist with newer releases, too.
Here's what we're seeing:
Jun 28 22:21:39 platform connmand[676]: DHCP: start renew timeout
Jun 28 22:21:39 platform connmand[676]: DHCP: switch listening mode (0 ==> 2)
Jun 28 22:21:39 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 04:21:39 platform connmand[676]: DHCP: start renew timeout
Jun 29 04:21:39 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 04:21:39 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 07:21:39 platform connmand[676]: DHCP: start renew timeout
Jun 29 07:21:39 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 07:21:39 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 08:51:39 platform connmand[676]: DHCP: start renew timeout
Jun 29 08:51:39 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 08:51:39 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 09:36:39 platform connmand[676]: DHCP: start renew timeout
Jun 29 09:36:39 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 09:36:39 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 09:59:09 platform connmand[676]: DHCP: start renew timeout
Jun 29 09:59:09 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 09:59:09 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 10:10:24 platform connmand[676]: DHCP: start renew timeout
Jun 29 10:10:24 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 10:10:24 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 10:16:01 platform connmand[676]: DHCP: start renew timeout
Jun 29 10:16:01 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 10:16:01 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 10:18:49 platform connmand[676]: DHCP: start renew timeout
Jun 29 10:18:49 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 10:18:49 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 10:20:13 platform connmand[676]: DHCP: start renew timeout
Jun 29 10:20:13 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 10:20:13 platform connmand[676]: DHCP: sending DHCP renew request
Jun 29 10:20:55 platform connmand[676]: DHCP: start renew timeout
Jun 29 10:20:55 platform connmand[676]: DHCP: switch listening mode (2 ==> 2)
Jun 29 10:20:55 platform connmand[676]: DHCP: start rebound
Jun 29 10:21:16 platform connmand[676]: DHCP: start rebound timeout
Jun 29 10:21:16 platform connmand[676]: DHCP: switch listening mode (2 ==> 1)
Jun 29 10:21:16 platform connmand[676]: DHCP: sending DHCP rebound request
Jun 29 10:21:16 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:16 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:19 platform connmand[676]: DHCP: restart DHCP timeout
Jun 29 10:21:19 platform connmand[676]: DHCP: restart DHCP (retries 1)
Jun 29 10:21:19 platform connmand[676]: DHCP: switch listening mode (1 ==> 1)
Jun 29 10:21:19 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:19 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:19 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:22 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:22 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:22 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:25 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:25 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:25 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:28 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:28 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:28 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:31 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:31 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:31 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:34 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:34 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:34 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:37 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:37 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:37 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:40 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:40 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:40 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:43 platform connmand[676]: DHCP: sending DHCP discover request
Jun 29 10:21:43 platform connmand[676]: DHCP: received DHCP packet (current
state 4)
Jun 29 10:21:43 platform connmand[676]: DHCP: processed DHCP packet (new state
4)
Jun 29 10:21:46 platform connmand[676]: DHCP: switch listening mode (1 ==> 0)
Jun 29 10:21:46 platform connmand[676]: DHCP: sending IPV4LL probe request
Jun 29 10:21:46 platform connmand[676]: DHCP: switch listening mode (0 ==> 3)
Jun 29 10:21:48 platform connmand[676]: DHCP: IPV4LL probe timeout (retries 1)
Jun 29 10:21:48 platform connmand[676]: DHCP: sending IPV4LL probe request
Jun 29 10:21:49 platform connmand[676]: DHCP: IPV4LL probe timeout (retries 2)
Jun 29 10:21:49 platform connmand[676]: DHCP: sending IPV4LL probe request
Jun 29 10:21:51 platform connmand[676]: DHCP: IPV4LL probe timeout (retries 3)
Jun 29 10:21:51 platform connmand[676]: DHCP: sending IPV4LL announce request
Jun 29 10:21:54 platform connmand[676]: DHCP: request timeout (retries 1)
Jun 29 10:21:54 platform connmand[676]: DHCP: sending IPV4LL announce request
Jun 29 10:21:56 platform connmand[676]: DHCP: request timeout (retries 2)
Jun 29 10:21:56 platform connmand[676]: DHCP: switching to monitor mode
So we end up failing to renew the lease. Restarting ConnMan or even just taking
it offline and back online again fixes things.
The server appears to be refusing to renew our lease. Maybe it is buggy. But I
am also unsure of how ConnMan is handling the situation. In particular, ConnMan
restarts the client and sends a series of discover requests. However, reading
the code suggests that DHCP offer packets are only handled when the client state
is INIT_SELECTING, and at this point our client has state REBINDING. So I think
the server is sending DHCP offers and we are just ignoring them.
My knowledge of DHCP is nil, so maybe I am misunderstanding things. But it does
seem like the client state should be getting reset when the client is restarted.
Thoughts?
Also, I think this would be helpful:
diff --git a/gdhcp/client.c b/gdhcp/client.c
index ec1b2a2..c824a56 100644
--- a/gdhcp/client.c
+++ b/gdhcp/client.c
@@ -1910,7 +1910,9 @@ static gboolean listener_event(GIOChannel *channel,
GIOCondition condition,
/* No message type / client id option, ignore package */
return TRUE;
- debug(dhcp_client, "received DHCP packet (current state %d)",
+ debug(dhcp_client,
+ "received DHCP packet with message type %d (current state %d)",
+ *message_type,
dhcp_client->state);
switch (dhcp_client->state) {
Thanks,
Forest
--
Forest Bond
http://www.alittletooquiet.net
http://www.rapidrollout.com
signature.asc
Description: Digital signature
_______________________________________________ connman mailing list [email protected] http://lists.connman.net/listinfo/connman
