dhcpcd 5.5.4 killed just after forking to background

[benjarobin]

I am running ArchLinux up to date with dhcpcd 5.5.4, linux 3.2.5, and wicd 1.7.1

Wicd for a wired connection starts dhcpcd to obtain an IP. But since dhcpcd 5.5.4 there is a full support of IPv6 and dhcpcd obtain the IPv6 faster than the IPv4 => The consequence it that dhcpcd is forking to background before setting the IPv4.

Unfortunately wicd only check that the IPv4 is set and valid with ifconfig. => Since dhcpcd 5.5.4, the IPv4 is not set and wicd just kill dhcpcd before dhcpcd obtains the chance to set the IPv4 which is done 3 or 4 seconds after dhcpcd is forking to background.

I did open this ticket http://roy.marples.name/projects/dhcpcd/ticket/239 but I think this problem should be fixed in Wicd

For a temporally fix I did that (Wait 5 seconds after dhcpcd is forking to background) : sed -i "s|self.dhcp_object.wait()|self.dhcp_object.wait()\n time.sleep(5)|" /usr/lib/wicd/wnettools.py
cp /usr/lib/wicd/wnettools.py /usr/lib/python2.7/site-packages/wicd/wnettools.py

[Philippe LUC (philfifi-x)]

Hello,
Using same distrib, and same versions of tools.
Wicd log says:

2012/02/26 13:23:53 :: Running DHCP with hostname XXXX
2012/02/26 13:23:53 :: dhcpcd[3439]: version 5.5.4 starting
2012/02/26 13:23:53 ::
2012/02/26 13:23:53 :: dhcpcd[3439]: eth0: sending IPv6 Router Solicitation
2012/02/26 13:23:53 ::
2012/02/26 13:23:53 :: dhcpcd[3439]: eth0: broadcasting for a lease
2012/02/26 13:23:53 ::
2012/02/26 13:23:55 :: dhcpcd[3439]: eth0: Router Advertisement from fe80::201:2eff:fe2b:XXXX
2012/02/26 13:23:55 ::
2012/02/26 13:23:55 :: dhcpcd[3439]: forked to background, child pid 3457
2012/02/26 13:23:55 ::
2012/02/26 13:23:55 ::
2012/02/26 13:23:55 :: DHCP connection successful
2012/02/26 13:23:55 :: Connecting thread exiting.
2012/02/26 13:23:55 :: Sending connection attempt result success

[Philippe LUC (philfifi-x)]

If I switch of my radvd daemon on the router, the IPv4 is correctly assigned, and the log says :

2012/02/26 12:38:42 :: Running DHCP with hostname laptopx-fifi
2012/02/26 12:38:42 :: dhcpcd[6808]: version 5.5.4 starting
2012/02/26 12:38:42 ::
2012/02/26 12:38:42 :: dhcpcd[6808]: eth0: sending IPv6 Router Solicitation
2012/02/26 12:38:42 ::
2012/02/26 12:38:42 :: dhcpcd[6808]: eth0: broadcasting for a lease
2012/02/26 12:38:42 ::
2012/02/26 12:38:45 :: dhcpcd[6808]: eth0: offered 192.168.14.187 from 192.168.14.100
2012/02/26 12:38:45 ::
2012/02/26 12:38:45 :: dhcpcd[6808]: eth0: acknowledged 192.168.14.187 from 192.168.14.100
2012/02/26 12:38:45 ::
2012/02/26 12:38:45 :: dhcpcd[6808]: eth0: checking for 192.168.14.187
2012/02/26 12:38:45 ::
2012/02/26 12:38:46 :: dhcpcd[6808]: eth0: sending IPv6 Router Solicitation
2012/02/26 12:38:46 ::
2012/02/26 12:38:50 :: dhcpcd[6808]: eth0: sending IPv6 Router Solicitation
2012/02/26 12:38:50 ::
2012/02/26 12:38:51 :: dhcpcd[6808]: eth0: leased 192.168.14.187 for 3600 seconds
2012/02/26 12:38:51 ::
2012/02/26 12:38:51 :: dhcpcd[6808]: forked to background, child pid 6835
2012/02/26 12:38:51 ::
2012/02/26 12:38:51 ::
2012/02/26 12:38:51 :: DHCP connection successful
2012/02/26 12:38:51 :: Connecting thread exiting.
2012/02/26 12:38:51 :: Sending connection attempt result success

[benjarobin (benjarobin)]

Well if you fully ready this bug report these log file are normal/OK
There are 2 solutions : revert dhcpcd or apply the "horrible fix" specify in my comment of this bug
Or you could just wait that wicd fix it :-)

[Philippe LUC (philfifi-x)]

The other solution I use is to install dhclient and force wicd to use it.

[namelessone (thisismyfriendsemailaddress)]

Here is a better log explaining what is happening (I am also using ArchLinux, same version of dhcpcd and wicd as listed above)
2012/03/20 08:20:01 :: Autoconnecting...
2012/03/20 08:20:01 :: No wired connection present, attempting to autoconnect to wireless network
2012/03/20 08:20:02 :: trying to automatically connect to...AP
2012/03/20 08:20:05 :: Connecting to wireless network AP
2012/03/20 08:20:06 :: Putting interface down
2012/03/20 08:20:06 :: Releasing DHCP leases...
2012/03/20 08:20:06 :: Setting false IP...
2012/03/20 08:20:06 :: Stopping wpa_supplicant
2012/03/20 08:20:06 :: Flushing the routing table...
2012/03/20 08:20:06 :: Putting interface up...
2012/03/20 08:20:08 :: Running DHCP with hostname arbok
2012/03/20 08:20:08 :: dhcpcd[18081]: version 5.5.4 starting
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: waiting for carrier
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: carrier acquired
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: sending IPv6 Router Solicitation
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: sendmsg: Cannot assign requested address
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: broadcasting for a lease
2012/03/20 08:20:08 ::
2012/03/20 08:20:09 :: dhcpcd[18081]: wlan0: offered x.x.x.x from y.y.y.y `hostname'
2012/03/20 08:20:09 ::
2012/03/20 08:20:09 :: dhcpcd[18081]: wlan0: acknowledged x.x.x.x from y.y.y.y `hostname'
2012/03/20 08:20:09 ::
2012/03/20 08:20:09 :: dhcpcd[18081]: wlan0: checking for x.x.x.x
2012/03/20 08:20:09 ::
2012/03/20 08:20:10 :: dhcpcd[18081]: wlan0: Router Advertisement from <ipv6 addr>
2012/03/20 08:20:10 ::
2012/03/20 08:20:10 :: dhcpcd[18081]: forked to background, child pid 18104
2012/03/20 08:20:10 ::
2012/03/20 08:20:10 ::
2012/03/20 08:20:10 :: DHCP connection successful
2012/03/20 08:20:10 :: not verifying
2012/03/20 08:20:10 :: Connecting thread exiting.
2012/03/20 08:20:12 :: Sending connection attempt result success

As can be seen, the ipv6 address gets obtained while the ipv4 address is still being verified. This causes dhcdcp to fork to the background, and then wicd gets confused because there isn't an ipv4 address yet.

It appears that the dhcpcd devels don't care about this problem--they have this immature idea that as soon as we start using ipv6, ipv4 will magically go away.

sleeping for 5 seconds is a hack, and personally, I don't have to wait for an extra 5 seconds (look at what technology has done to us--we're all impatient now)

It appears that dhcpcd has an option, noipv6rs that can be called from the command line. I suggest that wicd call dhcpcd with this option to alleviate this problem.

[namelessone (thisismyfriendsemailaddress)]

2012/03/20 08:20:01 :: Autoconnecting...
2012/03/20 08:20:01 :: No wired connection present, attempting to autoconnect to wireless network
2012/03/20 08:20:02 :: trying to automatically connect to...IASTATE
2012/03/20 08:20:05 :: Connecting to wireless network IASTATE
2012/03/20 08:20:06 :: Putting interface down
2012/03/20 08:20:06 :: Releasing DHCP leases...
2012/03/20 08:20:06 :: Setting false IP...
2012/03/20 08:20:06 :: Stopping wpa_supplicant
2012/03/20 08:20:06 :: Flushing the routing table...
2012/03/20 08:20:06 :: Putting interface up...
2012/03/20 08:20:08 :: Running DHCP with hostname arbok
2012/03/20 08:20:08 :: dhcpcd[18081]: version 5.5.4 starting
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: waiting for carrier
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: carrier acquired
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: sending IPv6 Router Solicitation
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: sendmsg: Cannot assign requested address
2012/03/20 08:20:08 ::
2012/03/20 08:20:08 :: dhcpcd[18081]: wlan0: broadcasting for a lease
2012/03/20 08:20:08 ::
2012/03/20 08:20:09 :: dhcpcd[18081]: wlan0: offered 10.24.220.189 from 129.186.1.16 `netreg-1.its.iastate.edu'
2012/03/20 08:20:09 ::
2012/03/20 08:20:09 :: dhcpcd[18081]: wlan0: acknowledged 10.24.220.189 from 129.186.1.16 `netreg-1.its.iastate.edu'
2012/03/20 08:20:09 ::
2012/03/20 08:20:09 :: dhcpcd[18081]: wlan0: checking for 10.24.220.189
2012/03/20 08:20:09 ::
2012/03/20 08:20:10 :: dhcpcd[18081]: wlan0: Router Advertisement from fe80::205:dcff:fe1f:3c00
2012/03/20 08:20:10 ::
2012/03/20 08:20:10 :: dhcpcd[18081]: forked to background, child pid 18104
2012/03/20 08:20:10 ::
2012/03/20 08:20:10 ::
2012/03/20 08:20:10 :: DHCP connection successful
2012/03/20 08:20:10 :: not verifying
2012/03/20 08:20:10 :: Connecting thread exiting.
2012/03/20 08:20:12 :: Sending connection attempt result success
--at this point, wicd says connection failed.

As can be seen, the ipv6 address gets obtained while the ipv4 address is still being verified. This causes dhcdcp to fork to the background, and then wicd gets confused because there isn't an ipv4 address yet.

It appears that the dhcpcd devels don't care about this problem--they have this immature idea that as soon as we start using ipv6, ipv4 will magically go away.

sleeping for 5 seconds is a hack, and personally, I don't have to wait for an extra 5 seconds (look at what technology has done to us--we're all impatient now)

It appears that dhcpcd has an option, noipv6rs that can be called from the command line. I suggest that wicd call dhcpcd with this option to alleviate this problem.

[Erik Wesselius (erikwesselius)]

Same problem on fully updated Archlinux system with wicd 1.7.2.4 / dhcpcd-5.5.6 trying to connect to a Fritz!Box 7390 ipv6 modem. After downgrading to dhcpcd-5.2.12 I could connect

wicd log using dhcpcd -5.5.6:
2012/07/29 17:12:15 :: dhcpcd[565]: version 5.5.6 starting
2012/07/29 17:12:15 ::
2012/07/29 17:12:16 :: dhcpcd[565]: wlan0: sending IPv6 Router Solicitation
2012/07/29 17:12:16 ::
2012/07/29 17:12:16 :: dhcpcd[565]: wlan0: sendmsg: Cannot assign requested address
2012/07/29 17:12:16 ::
2012/07/29 17:12:16 :: dhcpcd[565]: wlan0: broadcasting for a lease
2012/07/29 17:12:16 ::
2012/07/29 17:12:16 :: dhcpcd[565]: wlan0: Router Advertisement from xxxx::xxxx:xxxx:xxxx:xxxx
2012/07/29 17:12:16 ::
2012/07/29 17:12:16 :: dhcpcd[565]: forked to background, child pid 592

wicd log using dhcpcd -5.2.12:
2012/07/29 17:15:44 :: dhcpcd[9945]: version 5.2.12 starting
2012/07/29 17:15:44 ::
2012/07/29 17:15:44 :: dhcpcd[9945]: wlan0: broadcasting for a lease
2012/07/29 17:15:44 ::
2012/07/29 17:15:45 :: dhcpcd[9945]: wlan0: offered 192.168.188.45 from 192.168.188.1
2012/07/29 17:15:45 ::
2012/07/29 17:15:45 :: dhcpcd[9945]: wlan0: acknowledged 192.168.188.45 from 192.168.188.1
2012/07/29 17:15:45 ::
2012/07/29 17:15:45 :: dhcpcd[9945]: wlan0: checking for 192.168.188.45
2012/07/29 17:15:45 ::
2012/07/29 17:15:51 :: dhcpcd[9945]: wlan0: leased 192.168.188.45 for 864000 seconds
2012/07/29 17:15:51 ::
2012/07/29 17:15:51 :: dhcpcd[9945]: forked to background, child pid 9966

[Roy Marples (roy-marples)]

Hi

I'm the dhcpcd author and I'd like to take a moment to discuss how dhcpcd works, and how wicd should interact with it.

dhcpcd is designed to listen to kernel interace events (carrier, interface added, removed, etc) and auto configure that interface as best it can with rules set via dhcpcd.conf(5). As such, it is best run as a single process instead of per interface. wicd could start if it's not running.

Then wicd could listen to dhcpcd generated events via dhcpcd-run-hooks(8) to work out if an interface is configured for DHCP, IPv4LL, RA or any combination of. This is important as dhcpcd is currently dual stack - ipv4 and ipv6. The next major version will add dhcpv6 to the ipv6 stack.

> It appears that the dhcpcd devels don't care about this problem--they have
> this immature idea that as soon as we start using ipv6,
> ipv4 will magically go away.

This is untrue. Once it's configured one protocol, it will attempt to configure the other in the background. We fork once one interface has been configured for one protocol. We don't really care which protocol as modern day applications should support ipv6 anyway.

[Vadim Dyadkin (dyadkin-u)]

I have the same problem with wicd and dhcpcd. It seems that when dhcpcd has backgrounded, wicd checks the configured ipv4 iface. If it is not configured wicd kills dhcpcd. As the solution wicd could check the configured ipv4 OR ipv6.

[Alba Nader (sharepass12)]

Can this bug be related to the issue discussed here?

https://bugs.launchpad.net/wicd/+bug/1269691

Excerpt:

Jan 16 06:29:00 thinkpad dhcpcd[31127]: dhcpcd not running
Jan 16 06:29:00 thinkpad dhcpcd[31147]: dhcpcd not running

[benjarobin (benjarobin)]

To fix this bug properly, just run the following command (ArchLinux package) :

sed -ir "s|--noipv4ll|-w 4 -C wpa --noipv4ll|" /usr/lib/wicd/wnettools.py /usr/lib/python2.7/site-packages/wicd/wnettools.py

[Pieter Leclerc (pieterleclerc-deactivatedaccount)]

My version of dhcpcd (3.2.3) does not have the -w and -C options so I can't just apply this fix, because this would break support for older dhcpcd versions... can you make a patch that is independent of the dhcpcd version, please?

[benjarobin (benjarobin)]

Well, the proposed change did not work properly... I gave up on Wicd and switch to Network-manager (which now works without any problem)
Wicd is definitely broken and nobody maintained it.

[Frank Altpeter (frank42hh)]

Hi,

I had the same problem with wicd and dhcpcd on my gentoo installation (which means it's not ubuntu related). After some searching around, I found a very helpful post on http://zweithirn.friiks.de/archives/175-Wicd-und-dhcpcd.html which recommends to add

waitip 4

to /etc/dhcpcd.conf to prevent dhcpcd forking into background without being configured for IPv4. Since this prevents wicd from killing dhcpcd, I think this is a very good (and working) workaround for the problem until wicd is fixed (which indeed seems to take a lot of time, though).