after core update 136, dhcpcd stops running on red0

[cfusco]

What's the story with this, is it a universal issue or only limited cases? I've held off upgrading one of my systems after I saw this thread. Should I wait for 137?

I think it's better if you wait. I do not know if it affects any possible configuration. I can only tell you that I am affected and that I have a fiber connection that requires dhcp to get the network parameters from the provider.

[Arne.F]

I have not seen this on my testsystems but im not sure if my testsystem runs long enough. (My mainsystem use PPPoE)

But also my fileservers are IPFire with dhcpcd but they are reconfigured to green only.

You can try an actual nightly build with dhcpcd 8.10

Code: Select all

cd /opt/pakfire/tmp
wget https://nightly.ipfire.org/next/2019-10-13%2006:08:05%20+0000-4863f209/*** ARCH ***/packages/core-upgrade-2.23-137.ipfire
tar xvf core-upgrade-2.23-137.ipfire
./update.sh

[cfusco]

I have not seen this on my testsystems but im not sure if my testsystem runs long enough. (My mainsystem use PPPoE)

But also my fileservers are IPFire with dhcpcd but they are reconfigured to green only.

You can try an actual nightly build with dhcpcd 8.10
[...]

I just did that. I will report in a couple of days if nothing happens, or as soon as I get a SEGV error.

In the mean time, I can report what happened so far with the nightly build.
Two small problems. During the boot I get this error message that was not present before:

Code: Select all

ipset v7.1: Unknown argument: `199.9.14.201'
Try `ipset help' for more information.

The boot process passed the network phase successfully, but it got stuck for a minute or so longer than normal at the "Searching for Sensors...". However, then it completed the boot successfully.

[Arne.F]

The "Serching for sensors" is only run once after a kernel update and can take a while.

The ipset error is known (im not sure if it is already fixed now with the update to 7.3...)

[ITechPro]

I didn't have a problem 'til now on 2 systems, which I've updated on Sunday.
But they only have a few clients on green and blue (max. 10) connected.

[cfusco]

Unfortunately I have to report bad news. It's different thought. This is ifconfig:

Code: Select all

red0      Link encap:Ethernet  HWaddr 00:0D:B9:42:68:92  
          UP BROADCAST RUNNING  MTU:1500  Metric:1
          RX packets:8597522 errors:0 dropped:0 overruns:72 frame:0
          TX packets:1398501 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000 
          RX bytes:10555269823 (10066.2 Mb)  TX bytes:860116014 (820.2 Mb)
          Memory:f7b00000-f7b1ffff 

As you can see, it's still not configured properly. The systemlog on the red interface show this:

Code: Select all

05:00:02 dhcpcd[15384] : sending signal ALRM to pid 16683
05:00:02 dhcpcd[15384] : waiting for pid 16683 to exit
05:00:02 dhcpcd[16683] : received SIGALRM, releasing
05:00:02 dhcpcd[16683] : red0: removing interface
05:00:12 dhcpcd[15384] : pid 16683 failed to exit

When i tried to restart the network, it got stuck at"Stopping dhcpcd on the red0 interface...". After about 10 min I ^c the script. I tried to reboot, obviously it got stuck again at the same step. This is the systemlog, again showing that there was a failure to stop the process. The rest of the log shows a normal boot, after I unplugged and re-plugged the power:

Code: Select all

07:45:59 dhcpcd[32456] : sending signal ALRM to pid 16683
07:45:59 dhcpcd[32456] : waiting for pid 16683 to exit
07:46:09 dhcpcd[32456] : pid 16683 failed to exit
07:51:02 dhcpcd[1067] : sending signal ALRM to pid 16683
07:51:02 dhcpcd[1067] : waiting for pid 16683 to exit
07:51:12 dhcpcd[1067] : pid 16683 failed to exit
07:53:26 dhcpcd[14510] : red0: waiting for carrier
07:53:26 dhcpcd[14510] : red0: carrier acquired
07:53:26 dhcpcd[14510] : DUID 00:01:00:01:24:00:67:9a:00:0d:b9:42:68:90
07:53:26 dhcpcd[14510] : red0: IAID b9:42:68:92
07:53:26 dhcpcd[14510] : red0: adding address fe80::20d:b9ff:fe42:6892
07:53:26 dhcpcd[14510] : ipv6_addaddr1: Permission denied
07:53:27 dhcpcd[14510] : red0: soliciting a DHCP lease
07:53:27 dhcpcd[14510] : red0: soliciting an IPv6 router
07:53:28 dhcpcd[14510] : red0: offered 80.253.88.254 from 213.144.129.5 `carnica.init7.net'
07:53:28 dhcpcd[14510] : red0: probing address 80.253.88.254/24
07:53:33 dhcpcd[14510] : red0: leased 80.253.88.254 for 1800 seconds
07:53:33 dhcpcd[14510] : red0: adding route to 80.253.88.0/24
07:53:33 dhcpcd[14510] : red0: adding default route via 80.253.88.1
07:53:53 dhcpcd[14510] : forked to background, child pid 15632

In a way it's worse than before. Now it needs an hard reboot, while before it was enough to rebound dhcpd to the interface.

It will be nice to downgrade to dhcpd 7, so I can install the nightly with the previous version of the package and test if this time there are no issues. Logically, it's the only way to be sure it is a bug in the version of dhcpd > 8 and not something else specific to my machine/installation.

Edit: I noticed from my log that the incident happened at 5 o'clock. Then I remembered that I have set the connection scheduler of IPFIre to reconnect every day at 5 o'clock. So, this is probably what caused the problem. There is a new bug in dhcpd that prevents the proper termination of the process and any script trying to rebind the interface gets stuck there. To test the hypothesis I tried "/etc/init.d/network restart" while the red interface was still properly configured, and indeed, it got stuck again. This is something easier to test. Arne, maybe you can try to replicate this on your machine?

[Arne.F]

I still cannot reproduce the bug with 8.1 also if i try to reconnect manually.

The downgrade is in git but the nightly builder is not finished yet.

[FischerM]

Hi,

'dhcpcd 8.1.1' is out:

dhcpcd-8.1.1 has been released with the following changes:

* IPv6: Fix a potential crash when udevs marks an interface ready.
* Linux: compat shim added for setproctitle(3).
* arc4random: fixed UB in compat shim.
* DHCP: Fix fallout from dhcpcd-8.1.0 for checksum calculation.

The last fix involved a lot a people, quite a few different fixes and played havoc with gcc-9.2 but should now be resolved.

I'm working on it.

Best,
Matthias

[Arne.F]

Please test if the downgrade works:

https://nightly.ipfire.org/master/2019- ... -a2c2c4c7/+++ ARCH +++/packages/core-upgrade-2.23-137.ipfire

[cfusco]

Please test if the downgrade works:

https://nightly.ipfire.org/master/2019- ... -a2c2c4c7/+++ ARCH +++/packages/core-upgrade-2.23-137.ipfire

Thanks Arne, I will tonight. So far I had no more problems. The connection has been stable since I installed the dhcpd 8.1, however the bug that I described before is perfectly reproducible, so I removed the rule in the connections manager of IPFire to reconnect every morning a 5 o'clock. I will test the new build and report here.

[cfusco]

Please test if the downgrade works:

https://nightly.ipfire.org/master/2019- ... -a2c2c4c7/+++ ARCH +++/packages/core-upgrade-2.23-137.ipfire

It works flawlessly. The red interface is stable and there are no problems to stop dhcpd. Look at the log of the installation of the nightly, the first log is coming from stopping dhcpd 8 which I had to hard reset because it got stuck removing the interface, the second is after I installed the new nightly and rebooted.

Code: Select all

IPFire diagnostics
Section: red
Date: October 18, 2019

16:55:54 dhcpcd[25178] : sending signal ALRM to pid 15780
16:55:54 dhcpcd[25178] : waiting for pid 15780 to exit
16:55:54 dhcpcd[15780] : received SIGALRM, releasing
16:55:54 dhcpcd[15780] : red0: removing interface <--------
16:56:04 dhcpcd[25178] : pid 15780 failed to exit <---------
16:57:46 dhcpcd[14204] : red0: waiting for carrier
16:57:46 dhcpcd[14204] : red0: carrier acquired
16:57:46 dhcpcd[14204] : DUID 00:01:00:01:24:00:67:9a:00:0d:b9:42:68:90
16:57:46 dhcpcd[14204] : red0: IAID b9:42:68:92
16:57:46 dhcpcd[14204] : red0: adding address fe80::20d:b9ff:fe42:6892
16:57:46 dhcpcd[14204] : ipv6_addaddr1: Permission denied
16:57:46 dhcpcd[14204] : red0: rebinding lease of 80.253.88.254
16:57:46 dhcpcd[14204] : red0: probing address 80.253.88.254/24
16:57:47 dhcpcd[14204] : red0: soliciting an IPv6 router
16:57:51 dhcpcd[14204] : red0: leased 80.253.88.254 for 1800 seconds
16:57:51 dhcpcd[14204] : red0: adding route to 80.253.88.0/24
16:57:51 dhcpcd[14204] : red0: adding default route via 80.253.88.1
16:58:08 dhcpcd[14204] : forked to background, child pid 15327
17:04:31 dhcpcd[15899] : sending signal ALRM to pid 15327
17:04:31 dhcpcd[15899] : waiting for pid 15327 to exit
17:04:31 dhcpcd[15327] : received SIGALRM, releasing
17:04:31 dhcpcd[15327] : red0: removing interface <--------
17:04:31 dhcpcd[15327] : red0: releasing lease of 80.253.88.254 <------
17:04:31 dhcpcd[15327] : red0: deleting route to 80.253.88.0/24
17:04:31 dhcpcd[15327] : red0: deleting default route via 80.253.88.1
17:04:33 dhcpcd[15327] : dhcpcd exited
17:04:40 dhcpcd[16357] : red0: waiting for carrier
17:04:40 dhcpcd[16357] : red0: carrier acquired
17:04:40 dhcpcd[16357] : DUID 00:01:00:01:24:00:67:9a:00:0d:b9:42:68:90
17:04:41 dhcpcd[16357] : red0: IAID b9:42:68:92
17:04:41 dhcpcd[16357] : red0: adding address fe80::20d:b9ff:fe42:6892
17:04:41 dhcpcd[16357] : ipv6_addaddr1: Permission denied
17:04:41 dhcpcd[16357] : red0: soliciting a DHCP lease
17:04:41 dhcpcd[16357] : red0: soliciting an IPv6 router
17:04:42 dhcpcd[16357] : red0: offered 80.253.88.254 from 213.144.129.5 `carnica.init7.net'
17:04:42 dhcpcd[16357] : red0: probing address 80.253.88.254/24
17:04:47 dhcpcd[16357] : red0: leased 80.253.88.254 for 1800 seconds
17:04:47 dhcpcd[16357] : red0: adding route to 80.253.88.0/24
17:04:47 dhcpcd[16357] : red0: adding default route via 80.253.88.1
17:05:09 dhcpcd[16357] : forked to background, child pid 17611

So to summarize, it works!

[BeBiMa]

How did you install dhcpcd only from the nightly build for core 137 on core 136?

BTW:
Could we change the topic to "after core update 136, dhcpcd stops running on red0"?

[cfusco]

How did you install dhcpcd only from the nightly build for core 137 on core 136?

I did not do that. I just installed the night build which I am using now. I changed the subject.

[cfusco]

How did you install dhcpcd only from the nightly build for core 137 on core 136?

I did not do that. I just installed the night build which I am using now. I changed the subject.

This morning at 5 o'clock again it happened the same thing, my ipfire tried to reconnect and the dhcpcd again got stuck:

Code: Select all

IPFire diagnostics
Section: red
Date: October 20, 2019

05:00:02 dhcpcd[29284] : sending signal ALRM to pid 17611
05:00:02 dhcpcd[29284] : waiting for pid 17611 to exit
05:00:02 dhcpcd[17611] : received SIGALRM, releasing
05:00:02 dhcpcd[17611] : red0: removing interface
05:00:12 dhcpcd[29284] : pid 17611 failed to exit
08:11:49 dhcpcd[15448] : sending signal ALRM to pid 17611
08:11:49 dhcpcd[15448] : waiting for pid 17611 to exit
08:11:59 dhcpcd[15448] : pid 17611 failed to exit
08:14:50 dhcpcd[14891] : red0: waiting for carrier
08:14:50 dhcpcd[14891] : red0: carrier acquired
08:14:50 dhcpcd[14891] : DUID 00:01:00:01:24:00:67:9a:00:0d:b9:42:68:90
08:14:50 dhcpcd[14891] : red0: IAID b9:42:68:92
08:14:50 dhcpcd[14891] : red0: adding address fe80::20d:b9ff:fe42:6892
08:14:50 dhcpcd[14891] : ipv6_addaddr1: Permission denied
08:14:51 dhcpcd[14891] : red0: soliciting an IPv6 router
08:14:51 dhcpcd[14891] : red0: soliciting a DHCP lease
08:14:52 dhcpcd[14891] : red0: offered 80.253.88.254 from 213.144.129.5 `carnica.init7.net'
08:14:52 dhcpcd[14891] : red0: probing address 80.253.88.254/24
08:14:57 dhcpcd[14891] : red0: leased 80.253.88.254 for 1800 seconds
08:14:57 dhcpcd[14891] : red0: adding route to 80.253.88.0/24
08:14:57 dhcpcd[14891] : red0: adding default route via 80.253.88.1
08:15:17 dhcpcd[14891] : forked to background, child pid 16029

I had to hard reboot, again.
it turns out that I did not downgrade. Now i feel an idiot for not having tested this before:

Code: Select all

[root@ipfire ~]# dhcpcd --version
dhcpcd 8.1.0
Copyright (c) 2006-2019 Roy Marples
Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH

I am still on version 8.1.0. Did I install the wrong night build?

[Arne.F]

https://git.ipfire.org/?p=ipfire-2.x.gi ... 6499ee3f63

your fireinfo profile shows that you have installed the version with the update to 8.1.0

try again the latest... there are much more other fixes...

https://nightly.ipfire.org/next/2019-10 ... -f48920d8/+++ ARCH +++/packages/core-upgrade-2.23-137.ipfire