ethernet disconnects before receiving an answer from dhcp server

[Igel Kuhn]

When trying to set up my wired ethernet with wicd-1.7.2.1 or wicd-1.7.2.4 it fails when trying to acquire an IP address via DHCP (tried all possible dhcp clients in the config menu of wicd). However, I _do_ reliably get an IP if I just let wicd fail and call dhcpcd (with the same command line parameters as shown in the wicd.log) from terminal (as root). Below is a snippet from /var/log/messages when I tried to connect my wired interface (eth0). Note that, at Aug 9 11:11:45, I just started dhcpcd from terminal to prove that it's no network problem.

This is /var/log/messages:

Aug 9 11:11:21 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -k eth0
Aug 9 11:11:21 localhost dhcpcd[4444]: eth0: releasing lease of <ip>
Aug 9 11:11:21 localhost dhcpcd[4779]: sending commands to master dhcpcd process
Aug 9 11:11:21 localhost dhcpcd[4444]: eth0: open_udp_socket: Cannot assign requested address
Aug 9 11:11:21 localhost kernel: [ 1690.861148] r8169 0000:08:00.0: eth0: link down
Aug 9 11:11:21 localhost kernel: [ 1690.862352] r8169 0000:08:00.0: eth0: link down
Aug 9 11:11:21 localhost kernel: [ 1690.862396] ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 9 11:11:21 localhost dhcpcd[4444]: eth0: removing interface
Aug 9 11:11:26 localhost kernel: [ 1696.529034] r8169 0000:08:00.0: eth0: link up
Aug 9 11:11:26 localhost kernel: [ 1696.531185] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Aug 9 11:11:29 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -k wlan0
Aug 9 11:11:29 localhost dhcpcd[4444]: wlan0: removing interface
Aug 9 11:11:29 localhost dhcpcd[4819]: sending commands to master dhcpcd process
Aug 9 11:11:29 localhost kernel: [ 1698.702552] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Aug 9 11:11:29 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -k eth0
Aug 9 11:11:29 localhost dhcpcd[4835]: sending commands to master dhcpcd process
Aug 9 11:11:29 localhost kernel: [ 1698.746904] r8169 0000:08:00.0: eth0: link down
Aug 9 11:11:29 localhost kernel: [ 1698.746911] r8169 0000:08:00.0: eth0: link down
Aug 9 11:11:29 localhost kernel: [ 1698.748148] ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 9 11:11:29 localhost dhcpcd[4843]: sending commands to master dhcpcd process
Aug 9 11:11:29 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -k eth0
Aug 9 11:11:29 localhost kernel: [ 1698.801948] r8169 0000:08:00.0: eth0: link down
Aug 9 11:11:29 localhost kernel: [ 1698.801956] r8169 0000:08:00.0: eth0: link down
Aug 9 11:11:29 localhost kernel: [ 1698.803117] ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 9 11:11:31 localhost dhcpcd[4848]: sending commands to master dhcpcd process
Aug 9 11:11:31 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -h <hostname> --noipv4ll eth0
Aug 9 11:11:31 localhost dhcpcd[4444]: eth0: waiting for carrier
Aug 9 11:11:31 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -k wlan0
Aug 9 11:11:31 localhost dhcpcd[4872]: sending commands to master dhcpcd process
Aug 9 11:11:31 localhost kernel: [ 1701.397081] ADDRCONF(NETDEV_UP): wlan0: link is not ready
Aug 9 11:11:31 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -k eth0
Aug 9 11:11:31 localhost dhcpcd[4444]: eth0: removing interface
Aug 9 11:11:31 localhost dhcpcd[4878]: sending commands to master dhcpcd process
Aug 9 11:11:31 localhost kernel: [ 1701.456433] r8169 0000:08:00.0: eth0: link down
Aug 9 11:11:31 localhost kernel: [ 1701.457610] ADDRCONF(NETDEV_UP): eth0: link is not ready
Aug 9 11:11:35 localhost kernel: [ 1704.581529] r8169 0000:08:00.0: eth0: link up
Aug 9 11:11:35 localhost kernel: [ 1704.583672] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Aug 9 11:11:45 localhost kernel: [ 1715.058054] eth0: no IPv6 routers present
Aug 9 11:11:47 localhost dhcpcd[4904]: sending commands to master dhcpcd process
Aug 9 11:11:47 localhost dhcpcd[4444]: control command: /sbin/dhcpcd -h <hostname> --noipv4ll eth0
Aug 9 11:11:47 localhost dhcpcd[4444]: eth0: broadcasting for a lease
Aug 9 11:11:47 localhost dhcpcd[4444]: eth0: offered <ip> from <DHCP server>
Aug 9 11:11:47 localhost dhcpcd[4444]: eth0: acknowledged <ip> from <DHCP server>
Aug 9 11:11:47 localhost dhcpcd[4444]: eth0: checking for <ip>
Aug 9 11:11:52 localhost dhcpcd[4444]: eth0: leased <ip> for 7200 seconds

This is /var/log/wicd/wicd.log

2012/08/09 11:11:21 :: Forced disconnect on
2012/08/09 11:11:21 :: /sbin/dhcpcd -k eth0
2012/08/09 11:11:21 :: ifconfig eth0 0.0.0.0
2012/08/09 11:11:21 :: /sbin/ip route flush dev eth0
2012/08/09 11:11:21 :: ifconfig eth0 down
2012/08/09 11:11:21 :: ifconfig eth0 up
2012/08/09 11:11:21 :: wpa_cli -i eth0 terminate
2012/08/09 11:11:21 :: ifconfig eth0
2012/08/09 11:11:21 :: ifconfig wlan0
2012/08/09 11:11:21 :: iwconfig wlan0
2012/08/09 11:11:24 :: ifconfig eth0
2012/08/09 11:11:24 :: ifconfig wlan0
2012/08/09 11:11:28 :: ifconfig eth0
2012/08/09 11:11:28 :: ifconfig wlan0
2012/08/09 11:11:29 :: iwconfig wlan0
2012/08/09 11:11:29 :: /sbin/dhcpcd -k wlan0
2012/08/09 11:11:29 :: ifconfig wlan0 0.0.0.0
2012/08/09 11:11:29 :: /sbin/ip route flush dev wlan0
2012/08/09 11:11:29 :: ifconfig wlan0 down
2012/08/09 11:11:29 :: ifconfig wlan0 up
2012/08/09 11:11:29 :: wpa_cli -i wlan0 terminate
2012/08/09 11:11:29 :: /sbin/dhcpcd -k eth0
2012/08/09 11:11:29 :: ifconfig eth0 0.0.0.0
2012/08/09 11:11:29 :: /sbin/ip route flush dev eth0
2012/08/09 11:11:29 :: ifconfig eth0 down
2012/08/09 11:11:29 :: ifconfig eth0 up
2012/08/09 11:11:29 :: wpa_cli -i eth0 terminate
2012/08/09 11:11:29 :: found lastused in configuration True
2012/08/09 11:11:29 :: Putting interface down
2012/08/09 11:11:29 :: ifconfig eth0 down
2012/08/09 11:11:29 :: Releasing DHCP leases...
2012/08/09 11:11:29 :: /sbin/dhcpcd -k eth0
2012/08/09 11:11:29 :: Setting false IP...
2012/08/09 11:11:29 :: ifconfig eth0 0.0.0.0
2012/08/09 11:11:29 :: Stopping wpa_supplicant
2012/08/09 11:11:29 :: wpa_cli -i eth0 terminate
2012/08/09 11:11:29 :: Flushing the routing table...
2012/08/09 11:11:29 :: /sbin/ip route flush dev eth0
2012/08/09 11:11:29 :: Putting interface up...
2012/08/09 11:11:29 :: ifconfig eth0 up
2012/08/09 11:11:31 :: Running DHCP with hostname <hostname>
2012/08/09 11:11:31 :: /sbin/dhcpcd -h <hostname> --noipv4ll eth0
2012/08/09 11:11:31 :: dhcpcd[4848]: sending commands to master dhcpcd process
2012/08/09 11:11:31 ::
2012/08/09 11:11:31 ::
2012/08/09 11:11:31 :: DHCP connection successful
2012/08/09 11:11:31 :: Connecting thread exiting.
2012/08/09 11:11:31 :: ifconfig eth0
2012/08/09 11:11:31 :: IP Address is: None
2012/08/09 11:11:31 :: Sending connection attempt result success
2012/08/09 11:11:31 :: ifconfig wlan0
2012/08/09 11:11:31 :: iwconfig wlan0
2012/08/09 11:11:31 :: Forced disconnect on
2012/08/09 11:11:31 :: /sbin/dhcpcd -k wlan0
2012/08/09 11:11:31 :: ifconfig wlan0 0.0.0.0
2012/08/09 11:11:31 :: /sbin/ip route flush dev wlan0
2012/08/09 11:11:31 :: ifconfig wlan0 down
2012/08/09 11:11:31 :: ifconfig wlan0 up
2012/08/09 11:11:31 :: wpa_cli -i wlan0 terminate
2012/08/09 11:11:31 :: /sbin/dhcpcd -k eth0
2012/08/09 11:11:31 :: ifconfig eth0 0.0.0.0
2012/08/09 11:11:31 :: /sbin/ip route flush dev eth0
2012/08/09 11:11:31 :: ifconfig eth0 down
2012/08/09 11:11:31 :: ifconfig eth0 up
2012/08/09 11:11:31 :: wpa_cli -i eth0 terminate
2012/08/09 11:11:34 :: ifconfig eth0
2012/08/09 11:11:34 :: ifconfig wlan0
2012/08/09 11:11:37 :: ifconfig eth0
2012/08/09 11:11:37 :: ifconfig wlan0
2012/08/09 11:11:40 :: ifconfig eth0
2012/08/09 11:11:40 :: ifconfig wlan0
2012/08/09 11:11:43 :: ifconfig eth0
2012/08/09 11:11:43 :: ifconfig wlan0
2012/08/09 11:11:46 :: ifconfig eth0
2012/08/09 11:11:46 :: ifconfig wlan0
2012/08/09 11:11:49 :: ifconfig eth0
2012/08/09 11:11:49 :: ifconfig wlan0
2012/08/09 11:11:52 :: ifconfig eth0
2012/08/09 11:11:52 :: ifconfig wlan0
2012/08/09 11:11:55 :: ifconfig eth0
2012/08/09 11:11:55 :: iwconfig wlan0
2012/08/09 11:11:58 :: ifconfig eth0

On another note (I should prolly open another bugreport for that) you see how my hostname is given to the dhcp-server, which I _explicitly_ ticked OFF in the wicd interface (wicd-gtk)

[Maris Nartiss (maris-nartiss)]

My guess - it's a duplicate issue of bug #1098978.

To see if it's so, just perform these steps:
while wicd is in state "obtaining IP address", run 'ps fax | grep dhcp' (without quotes) from terminal. You might need to run it few times till you obtain actual dhcp call that might look like this: "7736 ? S 0:00 \_ /sbin/dhcpcd -h darkstar --noipv4ll eth0"
Now try to run the command from terminal (/sbin/dhcpcd -h darkstar --noipv4ll eth0). If it fails, try to remove -h myhostname part and run again. If it succeeds, it's a bug #1098978.