Re: dhcpcd timeout

[Victor Gaydov <victor gaydov gmail com>]

On Fri, 04 Jun 2010 19:23:55 -0700
Dan Williams <dcbw redhat com> wrote:

> On Thu, 2010-06-03 at 10:34 +0400, Victor Gaydov wrote:  
> > Hello,
> > 
> > After upgrade from 0.7 to 0.8 NetworkManager compiled with dhcpcd
> > can't start connection because of dhcpcd timeout. Is it a way to
> > change this timeout?
> > 
> > Notes:
> >  - NetworkManager compiled with dhclient works fine
> >  - dhcpcd executed manually work fine
> >  - it seems that lease-time from /etc/dhcp/dhcpd.conf doesn't matter
> >    when dhcpcd is executed by NM
> > 
> > Log attached.  
> 
> Is there any chance you could run wireshark on the interface and see
> if any DHCP packets get out?  This is quite odd and it would point to
> either a misconfiguraton of dhcpcd on NM's part (maybe sendign the
> wrong command-line arguments) or it could point to a problem in
> dhcpcd.  It might also be useful to strace dhcpcd to see what it's
> doing.
> 
> The logs show the problem, but don't really provide any insight into
> what might be going on.  The other alternative may be to recompile NM
> and send any debugging or verbose command-line arguments that dhcpcd
> might use to get more output from it about the issue.
> 
> Dan
> 
>   

Hello! Sorry for delay.

The problem was related to timeouts: 45s is not enough. I changed
DHCP_TIMEOUT in sources and added '-t' option to dhcpcd and everything
works fine. Is it a way to change dhcp timeout in config file?

PS. Debug log is attached. I can also send wireshark log if necessary -
yes, DHCP packets are getting out.

-- 
Victor Gaydov.

What sin has not been committed in the name of efficiency?

NetworkManager: <info>  (eth0): carrier now ON (device state 2)
NetworkManager: <info>  (eth0): device state change: 2 -> 3 (reason 40)
NetworkManager: <info>  Activation (eth0) starting connection 'Auto eth0'
NetworkManager: <info>  (eth0): device state change: 3 -> 4 (reason 0)
NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) started...
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
NetworkManager: <info>  Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) starting...
NetworkManager: <info>  (eth0): device state change: 4 -> 5 (reason 0)
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) successful.
NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager: <info>  Activation (eth0) Stage 2 of 5 (Device Configure) complete.
NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager: <info>  (eth0): device state change: 5 -> 7 (reason 0)
NetworkManager: <info>  Activation (eth0) Beginning DHCP transaction (timeout in 45 seconds)
NetworkManager: <info>  dhcpcd started with pid 4717
NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP6 Configure Get) scheduled...
NetworkManager: <info>  Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP6 Configure Get) started...
NetworkManager: <info>  Activation (eth0) Stage 4 of 5 (IP6 Configure Get) complete.
[EXEC] dhcpcd -d -B -K -L -c /usr/libexec/nm-dhcp-client.action eth0
eth0: dhcpcd 4.0.15 starting
eth0: hardware address = 00:80:48:44:74:f5
eth0: executing `/usr/libexec/nm-dhcp-client.action', reason PREINIT
eth0: broadcasting for a lease
eth0: sending DHCP_DISCOVER with xid 0x5661b03a, next in 4.59 seconds
NetworkManager: <info>  DHCP: device eth0 state changed normal exit -> preinit
eth0: sending DHCP_DISCOVER with xid 0x5661b03a, next in 7.95 seconds
eth0: sending DHCP_DISCOVER with xid 0x5661b03a, next in 16.37 seconds
NetworkManager: <info>  (eth0): carrier now OFF (device state 7, deferring action for 4 seconds)
NetworkManager: <info>  (eth0): carrier now ON (device state 7)
eth0: sending DHCP_DISCOVER with xid 0x5661b03a, next in 31.86 seconds
eth0: timed out
eth0: executing `/usr/libexec/nm-dhcp-client.action', reason FAIL
eth0: broadcasting for a lease
eth0: sending DHCP_DISCOVER with xid 0x4bf9ac2a, next in 3.69 seconds
NetworkManager: <info>  DHCP: device eth0 state changed preinit -> fail
NetworkManager: <info>  (eth0): device state change: 7 -> 9 (reason 17)
NetworkManager: <info>  Marking connection 'Auto eth0' invalid.
NetworkManager: <info>  Activation (eth0) failed.
NetworkManager: <info>  (eth0): device state change: 9 -> 3 (reason 0)
NetworkManager: <info>  (eth0): deactivating device (reason: 0).
eth0: received SIGTERM, stopping
NetworkManager: <info>  (eth0): canceled DHCP transaction, dhcp client pid 4717