Arch Linux

Please read this before reporting a bug:
https://wiki.archlinux.org/title/Bug_reporting_guidelines

Do NOT report bugs when a package is just outdated, or it is in the AUR. Use the 'flag out of date' link on the package page, or the Mailing List.

REPEAT: Do NOT report bugs for outdated packages!
Tasklist

FS#42867 - [dhcpcd] outputs several million lines of logging to journald. (received signal PIPE)

Attached to Project: Arch Linux
Opened by Felix Esch (Araeos) - Friday, 21 November 2014, 18:13 GMT
Last edited by Anatol Pomozov (anatolik) - Saturday, 31 October 2015, 05:31 GMT
Task Type Bug Report
Category Packages: Core
Status Closed
Assigned To Ronald van Haren (pressh)
Anatol Pomozov (anatolik)
Architecture x86_64
Severity Medium
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 1
Private No

Details

Description:


dhcpcd (managed by NetworkManager) outputs several million lines per minute of logging to the journal,
all of the form:
...
Nov 21 17:12:55 Caeros dhcpcd[5329]: received signal PIPE
Nov 21 17:12:55 Caeros dhcpcd[5329]: received signal PIPE
Nov 21 17:12:55 Caeros dhcpcd[5329]: received signal PIPE
Nov 21 17:12:55 Caeros dhcpcd[5329]: received signal PIPE
Nov 21 17:12:55 Caeros dhcpcd[5329]: received signal PIPE
Nov 21 17:12:55 Caeros dhcpcd[5329]: received signal PIPE
...


Details:

As you can see in the attached journal log, the spamming starts after systemd-journald spontaneously restarted (it wasn't me ^^).
The processes dhcpcd and systemd-journal each take up almost 100% cpu in top (100% systemd-journal and ~60% dhcpcd).
After the continuous logging starts I can only stop it by killing dhcpcd directly ("systemctl restart NetworkManager" alone did not work).


Additional info:

dhcpcd version 6.6.2-1
networkmanager version 0.9.10.0-4

The dhcpcd process is invoked by NetworkManager with "/usr/bin/dhcpcd -B -K -L -G -c /usr/lib/networkmanager/nm-dhcp-helper enp2s0".
This bug occured on my laptop 2 times during seemingly normal browsing activity in the last week.


Steps to reproduce:

1. Start dhcpcd (maybe only via NetworkManager, untested as standalone).
2. Execute "systemctl restart systemd-journald"
3. wait for a while until dhcpcd starts outputting several million lines of logging. (This may take several minutes).
4. Only way to stop this is by killing "dhcpcd" (with SIGKILL).
   journal-excerpt.log (5.8 KiB)
This task depends upon

Closed by  Anatol Pomozov (anatolik)
Saturday, 31 October 2015, 05:31 GMT
Reason for closing:  Won't fix
Comment by Ben Wolsieffer (lopsided98) - Monday, 08 December 2014, 13:38 GMT
I am having the exact same problem. It only happens to me when I am connected to wifi on my laptop. I am able to stop the journal spamming by turning off my wifi, but when I turn it back on I am no longer able to acquire an ip over dhcp. i am using dhcpcd through NetworkManager.

Here is an excerpt from my journal when I try to connect to wifi after this bug occurs:
...
NetworkManager[245]: <info> (wlp1s0): supplicant interface state: completed -> disconnected
NetworkManager[245]: <info> (wlp1s0): deactivating device (reason 'none') [0]
NetworkManager[245]: <info> (wlp1s0): device state change: failed -> disconnected (reason 'none') [120 30 0]
NetworkManager[245]: <info> Activation (wlp1s0) Stage 4 of 5 (IPv6 Configure Timeout) complete.
NetworkManager[245]: <info> NetworkManager state is now DISCONNECTED
NetworkManager[245]: <info> (wlp1s0): device state change: ip-config -> failed (reason 'ip-config-unavailable') [70 120 5]
NetworkManager[245]: <info> Activation (wlp1s0) Stage 4 of 5 (IPv6 Configure Timeout) started...
NetworkManager[245]: <info> Activation (wlp1s0) Stage 4 of 5 (IPv6 Configure Timeout) scheduled...
NetworkManager[245]: <info> Activation (wlp1s0) Stage 4 of 5 (IPv4 Configure Timeout) complete.
NetworkManager[245]: <info> Activation (wlp1s0) Stage 4 of 5 (IPv4 Configure Timeout) started...
NetworkManager[245]: <info> Activation (wlp1s0) Stage 4 of 5 (IPv4 Configure Timeout) scheduled...
NetworkManager[245]: <info> (wlp1s0): DHCPv4 client pid 3960 exited with status -1
NetworkManager[245]: <info> Activation (wlp1s0) Stage 3 of 5 (IP Configure Start) complete.
NetworkManager[245]: <info> dhcpcd started with pid 3960
NetworkManager[245]: <info> Activation (wlp1s0) Beginning DHCPv4 transaction (timeout in 45 seconds)
NetworkManager[245]: <info> (wlp1s0): device state change: config -> ip-config (reason 'none') [50 70 0]
NetworkManager[245]: <info> Activation (wlp1s0) Stage 3 of 5 (IP Configure Start) started...
NetworkManager[245]: <info> Activation (wlp1s0) Stage 3 of 5 (IP Configure Start) scheduled.
NetworkManager[245]: <info> Activation (wlp1s0/wireless) Stage 2 of 5 (Device Configure) successful. Connected to wireless network 'mersd_guest'.
NetworkManager[245]: <info> (wlp1s0): supplicant interface state: authenticating -> completed
NetworkManager[245]: <info> (wlp1s0): supplicant interface state: inactive -> authenticating
...
Comment by Roy Marples (rsmarples) - Monday, 08 December 2014, 14:26 GMT
Looks to me that NM is stopping and starting dhcpcd very fast based on wpa_supplicant connecting / disconnecting.
Comment by Felix Esch (Araeos) - Monday, 08 December 2014, 19:29 GMT
This happens (as described at the top) to me even with wifi disabled (in NM). And the excerpt with wifi reconnects shows that it fails on the ip-config ('ip-config-unavailable'). This can also be seen in the applet when dhcpcd "cracks" (possibly infinite looping). So it seems with different causes the same bug? Or does your journald restart just before the dhcpcd cracks, too?
Comment by Roy Marples (rsmarples) - Tuesday, 09 December 2014, 20:48 GMT
Are you able to run dhcpcd (with the same arguments, less the -c /usr/lib/networkmanager/nm-dhcp-helper one) outside of NM successfully?
Using the OP, the command line would be /usr/bin/dhcpcd -B -K -L -G enp2s0
Obviously change the interface if needed.

There is an issue when running >1 instance of dhcpcd which is fixed in the newly released dhcpcd-6.6.5 which *may* be related.
Comment by Anatol Pomozov (anatolik) - Tuesday, 30 December 2014, 19:11 GMT
Ben, Felix could you please provide more information about this issue? And test the recent version of dhcpcd.
Comment by Ben Wolsieffer (lopsided98) - Thursday, 01 January 2015, 16:26 GMT
I tried stopping NetworkManager and killing dhcpcd, then starting it (manually) again with those parameters and it worked fine. I still haven't found a way to reproduce it and I haven't noticed any problems in the last week or so. Its possible that it could be fixed as I am using dhcpcd-6.6.7, but I'll let you know if anything more happens.
Comment by Felix Esch (Araeos) - Friday, 02 January 2015, 00:56 GMT
Using my steps above, I also fail to reproduce this bug now.
It seems NetworkManager switched to dhclient because dhcpcd is not started anymore by default.
I also tried the suggested command manually "/usr/bin/dhcpcd -B -K -L -G enp2s0" using dhcpcd version 6.6.7 to no avail.


In conclusion this might sort of fixed itself as long as NetworkManager uses dhclient.

Loading...