DHCP renewal

DHCP renewal

[Michael Johnson]

[-- Attachment #1: Type: text/plain, Size: 1128 bytes --]

Hi all,

I'm having a problem with the DHCP component of iwd whereby I have it
sending the initial request and getting the IP fine but when it comes time
for renewal (in my case after 1 hour) then there is an error and the DHCP
lease is left to expire. Turning on the IWD_DHCP_DEBUG flag I get this
output:

Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:626
Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:628
Entering state: DHCP_STATE_RENEWING
Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_send_request:394
Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:633
Sending request failed: Socket operation on non-socket
Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_send_release:487
Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] l_dhcp_client_stop:1199
Entering state: DHCP_STATE_INIT

Does anyone know what might be causing this? I'm still learning the code
base but I don't see anything obvious wrong (and I can't be sure this isn't
a problem with my system).
This is with the latest master build of both iwd and ell.


Michael

[-- Attachment #2: attachment.htm --]
[-- Type: text/html, Size: 1291 bytes --]

Re: DHCP renewal

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 1480 bytes --]

Hi Michael,

On 6/28/21 12:08 PM, Michael Johnson wrote:
> Hi all,
> 
> I'm having a problem with the DHCP component of iwd whereby I have it sending 
> the initial request and getting the IP fine but when it comes time for renewal 
> (in my case after 1 hour) then there is an error and the DHCP lease is left to 
> expire. Turning on the IWD_DHCP_DEBUG flag I get this output:
> 
> Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:626
> Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:628 Entering 
> state: DHCP_STATE_RENEWING
> Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_send_request:394
> Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:633 Sending 
> request failed: Socket operation on non-socket

This implies that the socket used for the unicast wasn't opened properly.

Try stracing / logging what happens in _dhcp_default_transport_bind().  Maybe 
one of the sockopts we try to set on the socket is not available?

> Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_send_release:487
> Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] l_dhcp_client_stop:1199 Entering 
> state: DHCP_STATE_INIT
> 
> Does anyone know what might be causing this? I'm still learning the code base 
> but I don't see anything obvious wrong (and I can't be sure this isn't a problem 
> with my system).
> This is with the latest master build of both iwd and ell.
> 
> 

Regards,
-Denis

Re: DHCP renewal

[Michael Johnson]

[-- Attachment #1: Type: text/plain, Size: 2194 bytes --]

Thanks Denis,

I tracked it down to a problem with capabilities in the systemd service. I
have sent a patch.

Along with the fix, I'm thinking it would be good to have extra logging in
ell/dhcp.c to make these kinds of errors easier to find.
Would you be open to a patch which adds `l_error()` output if the bind
operation fails? I know that `ell/dhcp.c` doesn't currently
have any error output but instead bubbles the errors up. Also I don't know
how fatal this kind of error should really be so maybe
logging isn't enough?

Regards,
Michael

On Mon, 28 Jun 2021 at 18:32, Denis Kenzior <denkenz@gmail.com> wrote:

> Hi Michael,
>
> On 6/28/21 12:08 PM, Michael Johnson wrote:
> > Hi all,
> >
> > I'm having a problem with the DHCP component of iwd whereby I have it
> sending
> > the initial request and getting the IP fine but when it comes time for
> renewal
> > (in my case after 1 hour) then there is an error and the DHCP lease is
> left to
> > expire. Turning on the IWD_DHCP_DEBUG flag I get this output:
> >
> > Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:626
> > Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:628
> Entering
> > state: DHCP_STATE_RENEWING
> > Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_send_request:394
> > Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_t1_expired:633
> Sending
> > request failed: Socket operation on non-socket
>
> This implies that the socket used for the unicast wasn't opened properly.
>
> Try stracing / logging what happens in _dhcp_default_transport_bind().
> Maybe
> one of the sockopts we try to set on the socket is not available?
>
> > Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] dhcp_client_send_release:487
> > Jun 28 14:46:25 p3-1337 iwd[7281]: [DHCPv4] l_dhcp_client_stop:1199
> Entering
> > state: DHCP_STATE_INIT
> >
> > Does anyone know what might be causing this? I'm still learning the code
> base
> > but I don't see anything obvious wrong (and I can't be sure this isn't a
> problem
> > with my system).
> > This is with the latest master build of both iwd and ell.
> >
> >
>
> Regards,
> -Denis
>

[-- Attachment #2: attachment.htm --]
[-- Type: text/html, Size: 2697 bytes --]

Re: DHCP renewal

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 1104 bytes --]

Hi Michael,

On 6/29/21 11:23 AM, Michael Johnson wrote:
> Thanks Denis,
> 
> I tracked it down to a problem with capabilities in the systemd service. I have 
> sent a patch.
> 

Yep, nice catch.  I don't run systemd, otherwise I would have caught this sooner.

> Along with the fix, I'm thinking it would be good to have extra logging in 
> ell/dhcp.c to make these kinds of errors easier to find.

Right.  I think we were a bit sloppy here.

> Would you be open to a patch which adds `l_error()` output if the bind operation 
> fails? I know that `ell/dhcp.c` doesn't currently

Yes, definitely.  We should at least log this failure via CLIENT_DEBUG.

> have any error output but instead bubbles the errors up. Also I don't know how 
> fatal this kind of error should really be so maybe
> logging isn't enough?

We could.  I think we issue l_dhcp_client_stop in a few failure cases already. 
Perhaps we can also add an extra event to signal that a fatal error occurred. 
Would make it easier to know something went wrong even if IWD_DHCP_DEBUG isn't set.

Regards,
-Denis