FS#66313 - DHCPCD 9.0.1-2 upgrade breaks name resolution

Attached to Project: Arch Linux
Opened by John Barks (Zod) - Sunday, 19 April 2020, 17:28 GMT
Last edited by Antonio Rojas (arojas) - Wednesday, 22 April 2020, 21:36 GMT
Task Type Bug Report
Category Packages: Core
Status Closed
Assigned To Ronald van Haren (pressh)
Architecture All
Severity Low
Priority Normal
Reported Version
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 0
Private No

Details

Description:DHCPCD 9.0.1-2 used with IWD

I had an IP address, no name resolution.
After several reboots I downgraded to 8.1.7-1 which resolved it.

Apr 19 12:04:11 carlos dhcpcd[866]: ps_dostop: Connection
refused


resolv.conf while it's broke..

# Generated by dhcpcd from wlan0.dhcp
# /etc/resolv.conf.head can replace this line

resolv.conf after downgrade..

# Generated by dhcpcd from wlan0.dhcp
# /etc/resolv.conf.head can replace this line
domain Home
nameserver 192.168.1.1
# /etc/resolv.conf.tail can replace this line




Apr 19 12:04:10 carlos systemd[1]: Started zfs-scrub@big_disk.timer.
Apr 19 12:04:10 carlos systemd[1]: Reached target Timers.
Apr 19 12:04:10 carlos systemd[1]: Listening on D-Bus System Message Bus Socket.
Apr 19 12:04:10 carlos systemd[1]: Listening on Libvirt local socket.
Apr 19 12:04:10 carlos systemd[1]: Listening on Libvirt admin socket.
Apr 19 12:04:10 carlos systemd[1]: Listening on Libvirt local read-only socket.
Apr 19 12:04:10 carlos systemd[1]: Listening on Virtual machine lock manager socket.
Apr 19 12:04:10 carlos systemd[1]: Listening on Virtual machine log manager socket.
Apr 19 12:04:10 carlos systemd[1]: Reached target Sockets.
Apr 19 12:04:10 carlos systemd[1]: Reached target Basic System.
Apr 19 12:04:10 carlos systemd[1]: Started D-Bus System Message Bus.
Apr 19 12:04:10 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 ms>
Apr 19 12:04:10 carlos systemd[1]: Starting dhcpcd on all interfaces...
Apr 19 12:04:10 carlos systemd[1]: Starting Wireless service...
Apr 19 12:04:10 carlos systemd[1]: Starting dhcpcd on all interfaces...
Apr 19 12:04:10 carlos systemd[1]: Starting Wireless service...
Apr 19 12:04:10 carlos audit: AUDIT1334 prog-id=7 op=LOAD
Apr 19 12:04:10 carlos audit: AUDIT1334 prog-id=8 op=LOAD
Apr 19 12:04:10 carlos systemd[1]: Starting Login Service...
Apr 19 12:04:10 carlos kernel: audit: type=1334 audit(1587312250.452:18): prog-id=7 op=LOAD
Apr 19 12:04:10 carlos audit: AUDIT1334 prog-id=9 op=LOAD
Apr 19 12:04:10 carlos audit: AUDIT1334 prog-id=10 op=LOAD
Apr 19 12:04:10 carlos systemd[1]: Starting Virtual Machine and Container Registration Service...
Apr 19 12:04:10 carlos dhcpcd[768]: dhcpcd-9.0.1 starting
Apr 19 12:04:10 carlos kernel: NET: Registered protocol family 38
Apr 19 12:04:10 carlos dhcpcd[868]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Apr 19 12:04:10 carlos dhcpcd[868]: ps_start: Address family not supported by protocol
Apr 19 12:04:10 carlos dhcpcd[868]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Apr 19 12:04:10 carlos dhcpcd[868]: ps_start: Address family not supported by protocol
Apr 19 12:04:10 carlos dhcpcd[866]: dev: loaded udev
Apr 19 12:04:10 carlos systemd[1]: Started Virtual Machine and Container Registration Service.
Apr 19 12:04:10 carlos iwd[769]: Wireless daemon version 1.7
Apr 19 12:04:10 carlos iwd[769]: Loaded configuration from /etc/iwd/main.conf
Apr 19 12:04:10 carlos kernel: 8021q: 802.1Q VLAN Support v1.8
Apr 19 12:04:10 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-machined comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 19 12:04:10 carlos systemd[1]: Started Wireless service.
Apr 19 12:04:10 carlos iwd[769]: netconfig: Network configuration is disabled.
Apr 19 12:04:10 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=iwd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 19 12:04:10 carlos iwd[769]: rfkill id 1 can't be matched to a wiphy
Apr 19 12:04:10 carlos iwd[769]: Wiphy: 0, Name: phy0
Apr 19 12:04:10 carlos iwd[769]: Permanent Address: 24:77:03:4f:ff:64
Apr 19 12:04:10 carlos iwd[769]: Bands: 2.4 GHz 5 GHz
Apr 19 12:04:10 carlos iwd[769]: Ciphers: CCMP TKIP
Apr 19 12:04:10 carlos iwd[769]: Supported iftypes: ad-hoc station
Apr 19 12:04:10 carlos systemd[1]: Started dhcpcd on all interfaces.
Apr 19 12:04:10 carlos systemd[1]: Reached target Network.
Apr 19 12:04:10 carlos kernel: kauditd_printk_skb: 3 callbacks suppressed
Apr 19 12:04:10 carlos kernel: audit: type=1130 audit(1587312250.758:22): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-machined comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr>
Apr 19 12:04:10 carlos kernel: audit: type=1130 audit(1587312250.762:23): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=iwd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=?>
Apr 19 12:04:10 carlos kernel: audit: type=1130 audit(1587312250.762:24): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? termina>
Apr 19 12:04:10 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 19 12:04:10 carlos systemd[1]: Starting Network Time Service...
Apr 19 12:04:10 carlos systemd[1]: Starting Permit User Sessions...
Apr 19 12:04:10 carlos systemd-udevd[335]: Using default interface naming scheme 'v245'.
Apr 19 12:04:10 carlos kernel: iwlwifi 0000:25:00.0: Radio type=0x0-0x3-0x1
Apr 19 12:04:10 carlos systemd[1]: Finished Permit User Sessions.
Apr 19 12:04:10 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-user-sessions comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=succ>
Apr 19 12:04:10 carlos kernel: audit: type=1130 audit(1587312250.825:25): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-user-sessions comm="systemd" exe="/usr/lib/systemd/systemd" hostname=?>
Apr 19 12:04:10 carlos systemd[1]: Started LXDE Display Manager.
Apr 19 12:04:10 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lxdm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 19 12:04:10 carlos kernel: audit: type=1130 audit(1587312250.832:26): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=lxdm comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=>
Apr 19 12:04:10 carlos systemd-logind[770]: New seat seat0.
Apr 19 12:04:10 carlos systemd-logind[770]: Watching system buttons on /dev/input/event2 (Power Button)
Apr 19 12:04:11 carlos systemd-logind[770]: Watching system buttons on /dev/input/event1 (Lid Switch)
Apr 19 12:04:11 carlos systemd-logind[770]: Watching system buttons on /dev/input/event0 (Sleep Button)
Apr 19 12:04:11 carlos kernel: iwlwifi 0000:25:00.0: Radio type=0x0-0x3-0x1
Apr 19 12:04:11 carlos ntpd[897]: ntpd 4.2.8p14@1.3728-o Wed Mar 18 13:44:46 UTC 2020 (1): Starting
Apr 19 12:04:11 carlos ntpd[897]: Command line: /usr/bin/ntpd -g -u ntp:ntp
Apr 19 12:04:11 carlos ntpd[897]: ----------------------------------------------------
Apr 19 12:04:11 carlos ntpd[897]: ntp-4 is maintained by Network Time Foundation,
Apr 19 12:04:11 carlos ntpd[897]: Inc. (NTF), a non-profit 501(c)(3) public-benefit
Apr 19 12:04:11 carlos ntpd[897]: corporation. Support and training for ntp-4 are
Apr 19 12:04:11 carlos ntpd[897]: available at https://www.nwtime.org/support
Apr 19 12:04:11 carlos ntpd[897]: ----------------------------------------------------
Apr 19 12:04:11 carlos dhcpcd[866]: enp0s25: waiting for carrier
Apr 19 12:04:11 carlos dhcpcd[866]: wlan0: waiting for carrier
Apr 19 12:04:11 carlos dhcpcd[866]: ps_dostop: Connection refused
Apr 19 12:04:11 carlos dhcpcd[866]: dhcpcd exited
Apr 19 12:04:11 carlos ntpd[918]: proto: precision = 0.088 usec (-23)
Apr 19 12:04:11 carlos ntpd[918]: basedate set to 2020-03-06
Apr 19 12:04:11 carlos ntpd[918]: gps base set to 2020-03-08 (week 2096)
Apr 19 12:04:11 carlos systemd-udevd[335]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Apr 19 12:04:11 carlos dhcpcd[921]: dhcpcd not running
Apr 19 12:04:11 carlos systemd[1]: dhcpcd.service: Control process exited, code=exited, status=1/FAILURE
Apr 19 12:04:11 carlos dhcpcd[921]: dhcpcd not running
Apr 19 12:04:11 carlos systemd[1]: dhcpcd.service: Failed with result 'exit-code'.
Apr 19 12:04:11 carlos audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Apr 19 12:04:11 carlos kernel: audit: type=1131 audit(1587312251.395:27): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? termina>
Apr 19 12:04:11 carlos ntpd[918]: Listen and drop on 0 v4wildcard 0.0.0.0:123
Apr 19 12:04:11 carlos systemd-logind[770]: Watching system buttons on /dev/input/event4 (AT Translated Set 2 keyboard)
Apr 19 12:04:11 carlos ntpd[918]: Listen normally on 1 lo 127.0.0.1:123
Apr 19 12:04:11 carlos systemd-logind[770]: Watching system buttons on /dev/input/event16 (HP WMI hotkeys)
Apr 19 12:04:11 carlos ntpd[918]: Listening on routing socket on fd #18 for interface updates
Apr 19 12:04:11 carlos ntpd[918]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Apr 19 12:04:11 carlos ntpd[918]: kernel reports TIME_ERROR: 0x41: Clock Unsynchronized
Apr 19 12:04:11 carlos systemd[1]: Started Login Service.
Apr 19 12:04:11 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-logind comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 19 12:04:11 carlos kernel: audit: type=1130 audit(1587312251.432:28): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=systemd-logind comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=?>
Apr 19 12:04:11 carlos systemd[1]: Started Virtualization daemon.
Apr 19 12:04:11 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=libvirtd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 19 12:04:11 carlos kernel: audit: type=1130 audit(1587312251.482:29): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=libvirtd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? termi>
Apr 19 12:04:11 carlos systemd[1]: Started Network Time Service.
Apr 19 12:04:11 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=ntpd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 19 12:04:11 carlos kernel: audit: type=1130 audit(1587312251.502:30): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=ntpd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=>
Apr 19 12:04:11 carlos systemd[1]: Reached target Multi-User System.
Apr 19 12:04:11 carlos systemd[1]: Reached target Graphical Interface.
Apr 19 12:04:11 carlos systemd[1]: Startup finished in 6.289s (kernel) + 12.844s (userspace) = 19.134s.
Apr 19 12:04:11 carlos kernel: wlan0: authenticate with 48:77:46:41:5d:ad
Apr 19 12:04:11 carlos kernel: wlan0: send auth to 48:77:46:41:5d:ad (try 1/3)
Apr 19 12:04:11 carlos kernel: wlan0: authenticated
Apr 19 12:04:11 carlos kernel: wlan0: associate with 48:77:46:41:5d:ad (try 1/3)
Apr 19 12:04:11 carlos kernel: wlan0: RX AssocResp from 48:77:46:41:5d:ad (capab=0x511 status=0 aid=6)
Apr 19 12:04:11 carlos kernel: wlan0: associated
Apr 19 12:04:11 carlos kernel: wlan0: Limiting TX power to 30 (30 - 0) dBm as advertised by 48:77:46:41:5d:ad
Apr 19 12:04:14 carlos systemd-udevd[335]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Apr 19 12:04:14 carlos kernel: bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
Apr 19 12:04:14 carlos kernel: tun: Universal TUN/TAP device driver, 1.6
Apr 19 12:04:14 carlos audit: ANOM_PROMISCUOUS dev=virbr0-nic prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Apr 19 12:04:14 carlos kernel: virbr0: port 1(virbr0-nic) entered blocking state
Apr 19 12:04:14 carlos kernel: virbr0: port 1(virbr0-nic) entered disabled state
Apr 19 12:04:14 carlos kernel: device virbr0-nic entered promiscuous mode
Apr 19 12:04:14 carlos kernel: audit: type=1700 audit(1587312254.625:31): dev=virbr0-nic prom=256 old_prom=0 auid=4294967295 uid=0 gid=0 ses=4294967295
Apr 19 12:04:14 carlos systemd-udevd[332]: Using default interface naming scheme 'v245'.
Apr 19 12:04:14 carlos systemd-udevd[332]: ethtool: autonegotiation is unset or enabled, the speed and duplex are not writable.
Apr 19 12:04:14 carlos audit: NETFILTER_CFG table=filter family=2 entries=0


Additional info:
* package version(s)
* config and/or log files etc.
* link to upstream bug report, if any

Steps to reproduce:
This task depends upon

Closed by  Antonio Rojas (arojas)
Wednesday, 22 April 2020, 21:36 GMT
Reason for closing:  Fixed
Additional comments about closing:  dhcpcd 9.0.1-4
Comment by John Barks (Zod) - Sunday, 19 April 2020, 18:39 GMT
http://ix.io/2iHX
Comment by Antonio Rojas (arojas) - Sunday, 19 April 2020, 20:27 GMT
Please report upstream
Comment by John Barks (Zod) - Sunday, 19 April 2020, 22:55 GMT
@arojas

Done.
Comment by Mal Haak (insanemal) - Monday, 20 April 2020, 05:17 GMT
Just to add to this, it also breaks routing.

@John Barks

Can you please link the upstream ticket
Comment by Mal Haak (insanemal) - Monday, 20 April 2020, 05:23 GMT
Just adding some extra info if using the upgraded DHCPCD with NetworkManager

Apr 20 15:10:50 mals dhcpcd[3358]: dhcpcd-9.0.1 starting
Apr 20 15:10:50 mals dhcpcd[3358]: ps_init: /var/lib/dhcpcd/var/lib/dhcpcd: Operation not permitted
Apr 20 15:10:50 mals NetworkManager[545]: <warn> [1587359450.7293] dhcp-listener: dhcp-event: didn't have associated interface.
Apr 20 15:10:50 mals dhcpcd[3365]: if_learnaddrs: if_addrflags6: ::1%lo: No such file or directory
Apr 20 15:10:50 mals dhcpcd[3365]: if_learnaddrs: if_addrflags6: XXXX::XXXX:XXXX:XXXX:XXXX%wlo1: No such file or directory
Apr 20 15:10:50 mals dhcpcd[3365]: if_learnaddrs: if_addrflags6: XXXX:XXXX:XXX:XXXX:XXXX:XXXX:XXXX:XXX%ztukuqetrk: No such file or directory
Apr 20 15:10:50 mals dhcpcd[3365]: if_learnaddrs: if_addrflags6: XXXX::XXXXX:XXXX:XXXX:XXXX%ztukuqetrk: No such file or directory
Apr 20 15:10:50 mals NetworkManager[545]: <warn> [1587359450.7404] dhcp-listener: dhcp-event: (pid 3365) unhandled DHCP event for interface wlo1
Apr 20 15:10:50 mals dhcpcd[3365]: wlo1: connected to Access Point `NONE-5G'
Apr 20 15:10:50 mals dhcpcd[3365]: /var/lib/dhcpcd/duid: Permission denied
Apr 20 15:10:50 mals dhcpcd[3365]: DUID 00:03:00:01:08:71:90:72:62:17
Apr 20 15:10:50 mals dhcpcd[3365]: wlo1: IAID 90:72:62:17
Apr 20 15:10:51 mals kdeconnectd[941]: kdeconnect.core: Broadcasting identity packet
Apr 20 15:10:51 mals dhcpcd[3365]: wlo1: soliciting a DHCP lease
Apr 20 15:10:51 mals dhcpcd[3365]: wlo1: offered 10.0.0.10 from 10.0.0.138
Apr 20 15:10:51 mals dhcpcd[3365]: wlo1: leased 10.0.0.10 for 3600 seconds
Apr 20 15:10:51 mals dhcpcd[3365]: write_lease: /var/lib/dhcpcd/wlo1-NONE-5G.lease: Permission denied

Downgrade fixes it... I'm not sure it's "just" a DHCPCD issue.
Comment by Antonio Rojas (arojas) - Monday, 20 April 2020, 06:13 GMT
Please test 9.0.1-3

@insanemal the NM issue is a different one, and unlikely to be fixed anytime soon: https://gitlab.freedesktop.org/NetworkManager/NetworkManager/-/issues/410
Comment by Mal Haak (insanemal) - Monday, 20 April 2020, 08:06 GMT
Ahhh thanks for that.

Sorry for that.
Comment by John Barks (Zod) - Monday, 20 April 2020, 13:31 GMT
Installed 9.0.1-3 and rebooted
No Ip Address

Downgraded to 9.0.1-2 and rebooted
No IP Address

Downgraded to 8.1.7-1 and rebooted
Got an IP address and name resolution
Comment by John Barks (Zod) - Monday, 20 April 2020, 13:47 GMT
To make clear, I do have IPv6 disabled: GRUB_CMDLINE_LINUX_DEFAULT="loglevel=3 quiet ipv6.disable=1 resume=UUID=ce346460-e737-40c1-b79c-8b2be96034ba"



[jbarks@carlos ~]$ sudo journalctl -b -1 | grep dhcpcd
Apr 20 09:21:55 carlos systemd[1]: Starting dhcpcd on all interfaces...
Apr 20 09:21:55 carlos dhcpcd[800]: dhcpcd-9.0.1 starting
Apr 20 09:21:56 carlos dhcpcd[925]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Apr 20 09:21:56 carlos dhcpcd[925]: ps_start: Address family not supported by protocol
Apr 20 09:21:56 carlos dhcpcd[925]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Apr 20 09:21:56 carlos dhcpcd[925]: ps_start: Address family not supported by protocol
Apr 20 09:21:56 carlos dhcpcd[923]: dev: loaded udev
Apr 20 09:21:56 carlos systemd[1]: Started dhcpcd on all interfaces.
Apr 20 09:21:56 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 20 09:21:56 carlos kernel: audit: type=1130 audit(1587388916.444:31): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 20 09:21:56 carlos dhcpcd[923]: enp0s25: waiting for carrier
Apr 20 09:21:56 carlos dhcpcd[923]: wlan0: waiting for carrier
Apr 20 09:21:56 carlos dhcpcd[923]: ps_dostop: Connection refused
Apr 20 09:21:56 carlos dhcpcd[923]: dhcpcd exited
Apr 20 09:21:56 carlos dhcpcd[950]: dhcpcd not running
Apr 20 09:21:56 carlos systemd[1]: dhcpcd.service: Control process exited, code=exited, status=1/FAILURE
Apr 20 09:21:56 carlos dhcpcd[950]: dhcpcd not running
Apr 20 09:21:56 carlos systemd[1]: dhcpcd.service: Failed with result 'exit-code'.
Apr 20 09:21:56 carlos audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Apr 20 09:23:19 carlos sudo[1257]: jbarks : TTY=pts/0 ; PWD=/home/jbarks ; USER=root ; COMMAND=/usr/bin/dhcpcd
Apr 20 09:23:19 carlos dhcpcd[1258]: dhcpcd-9.0.1 starting
Apr 20 09:23:19 carlos dhcpcd[1268]: dev: loaded udev
Apr 20 09:23:19 carlos dhcpcd[1270]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Apr 20 09:23:19 carlos dhcpcd[1270]: ps_start: Address family not supported by protocol
Apr 20 09:23:19 carlos dhcpcd[1268]: wlan0: connected to Access Point `CXNK00730823'
Apr 20 09:23:19 carlos dhcpcd[1268]: enp0s25: waiting for carrier
Apr 20 09:23:19 carlos dhcpcd[1268]: DUID 00:01:00:01:26:2f:2a:25:24:77:03:4f:ff:64
Apr 20 09:23:19 carlos dhcpcd[1268]: wlan0: IAID 03:4f:ff:64
Apr 20 09:23:19 carlos dhcpcd[1268]: wlan0: adding address fe80::d155:f31c:37b5:9696
Apr 20 09:23:19 carlos dhcpcd[1268]: ipv6_addaddr1: Operation not supported
Apr 20 09:23:19 carlos dhcpcd[1268]: ps_dostop: Connection refused
Apr 20 09:23:19 carlos dhcpcd[1268]: dhcpcd exited
Apr 20 09:25:42 carlos sudo[1283]: jbarks : TTY=pts/0 ; PWD=/var/cache/pacman/pkg ; USER=root ; COMMAND=/usr/bin/pacman -U dhcpcd-8.1.7-1-x86_64.pkg.tar.zst
Apr 20 09:26:01 carlos systemd[1]: Unmounting /var/lib/dhcpcd/dev...
Apr 20 09:26:01 carlos systemd[1]: Unmounting /var/lib/dhcpcd/proc...
Apr 20 09:26:01 carlos systemd[1]: Unmounting /var/lib/dhcpcd/run/systemd/journal...
Apr 20 09:26:01 carlos systemd[1]: Unmounting /var/lib/dhcpcd/run/udev...
Apr 20 09:26:01 carlos systemd[1]: Unmounting /var/lib/dhcpcd/sys...
Apr 20 09:26:01 carlos systemd[1]: var-lib-dhcpcd-dev.mount: Succeeded.
Apr 20 09:26:01 carlos systemd[1]: Unmounted /var/lib/dhcpcd/dev.
Apr 20 09:26:01 carlos systemd[1]: var-lib-dhcpcd-proc.mount: Succeeded.
Apr 20 09:26:01 carlos systemd[1]: Unmounted /var/lib/dhcpcd/proc.
Apr 20 09:26:01 carlos systemd[1]: var-lib-dhcpcd-run-systemd-journal.mount: Succeeded.
Apr 20 09:26:01 carlos systemd[1]: Unmounted /var/lib/dhcpcd/run/systemd/journal.
Apr 20 09:26:01 carlos systemd[1]: var-lib-dhcpcd-run-udev.mount: Succeeded.
Apr 20 09:26:01 carlos systemd[1]: Unmounted /var/lib/dhcpcd/run/udev.
Apr 20 09:26:01 carlos systemd[1]: var-lib-dhcpcd-sys.mount: Succeeded.
Apr 20 09:26:01 carlos systemd[1]: Unmounted /var/lib/dhcpcd/sys.


[jbarks@carlos ~]$ sudo journalctl -b -2 | grep dhcpcd
Apr 20 09:16:42 carlos systemd[1]: Starting dhcpcd on all interfaces...
Apr 20 09:16:42 carlos dhcpcd[798]: dhcpcd-9.0.1 starting
Apr 20 09:16:42 carlos dhcpcd[883]: dev: loaded udev
Apr 20 09:16:42 carlos dhcpcd[885]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Apr 20 09:16:42 carlos dhcpcd[885]: ps_start: Address family not supported by protocol
Apr 20 09:16:42 carlos dhcpcd[885]: ps_inet_startcb: ipv6nd_open: Address family not supported by protocol
Apr 20 09:16:42 carlos dhcpcd[885]: ps_start: Address family not supported by protocol
Apr 20 09:16:42 carlos systemd[1]: Started dhcpcd on all interfaces.
Apr 20 09:16:42 carlos audit[1]: SERVICE_START pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 20 09:16:42 carlos kernel: audit: type=1130 audit(1587388602.766:24): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
Apr 20 09:16:43 carlos dhcpcd[883]: enp0s25: waiting for carrier
#******Shouldn't wlan0 be waiting for carrier here?************ <==(JB Edit)
Apr 20 09:16:43 carlos dhcpcd[883]: ps_dostop: Connection refused
Apr 20 09:16:43 carlos dhcpcd[883]: dhcpcd exited
Apr 20 09:16:43 carlos dhcpcd[944]: dhcpcd not running
Apr 20 09:16:43 carlos dhcpcd[944]: dhcpcd not running
Apr 20 09:16:43 carlos systemd[1]: dhcpcd.service: Control process exited, code=exited, status=1/FAILURE
Apr 20 09:16:43 carlos systemd[1]: dhcpcd.service: Failed with result 'exit-code'.
Apr 20 09:16:43 carlos audit[1]: SERVICE_STOP pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Apr 20 09:16:43 carlos kernel: audit: type=1131 audit(1587388603.356:29): pid=1 uid=0 auid=4294967295 ses=4294967295 msg='unit=dhcpcd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'
Apr 20 09:20:23 carlos sudo[1280]: jbarks : TTY=pts/1 ; PWD=/var/cache/pacman/pkg ; USER=root ; COMMAND=/usr/bin/pacman -U dhcpcd-9.0.1-2-x86_64.pkg.tar.zst
Apr 20 09:21:08 carlos systemd[1]: Unmounting /var/lib/dhcpcd/dev...
Apr 20 09:21:08 carlos systemd[1]: Unmounting /var/lib/dhcpcd/proc...
Apr 20 09:21:08 carlos systemd[1]: Unmounting /var/lib/dhcpcd/run/systemd/journal...
Apr 20 09:21:08 carlos systemd[1]: Unmounting /var/lib/dhcpcd/run/udev...
Apr 20 09:21:08 carlos systemd[1]: Unmounting /var/lib/dhcpcd/sys...
Apr 20 09:21:09 carlos systemd[1]: var-lib-dhcpcd-dev.mount: Succeeded.
Apr 20 09:21:09 carlos systemd[1]: Unmounted /var/lib/dhcpcd/dev.
Apr 20 09:21:09 carlos systemd[1]: var-lib-dhcpcd-proc.mount: Succeeded.
Apr 20 09:21:09 carlos systemd[1]: Unmounted /var/lib/dhcpcd/proc.
Apr 20 09:21:09 carlos systemd[1]: var-lib-dhcpcd-run-systemd-journal.mount: Succeeded.
Apr 20 09:21:09 carlos systemd[1]: Unmounted /var/lib/dhcpcd/run/systemd/journal.
Apr 20 09:21:09 carlos systemd[1]: var-lib-dhcpcd-run-udev.mount: Succeeded.
Apr 20 09:21:09 carlos systemd[1]: Unmounted /var/lib/dhcpcd/run/udev.
Apr 20 09:21:09 carlos systemd[1]: var-lib-dhcpcd-sys.mount: Succeeded.
Apr 20 09:21:09 carlos systemd[1]: Unmounted /var/lib/dhcpcd/sys.
Comment by Antonio Rojas (arojas) - Monday, 20 April 2020, 16:07 GMT
Should be fixed in 9.0.1-4, please confirm
Comment by John Barks (Zod) - Monday, 20 April 2020, 16:23 GMT
That fixes it.

I'm good to go, this ticket can be closed as far as I am concerned.
Comment by Milian Wolff (milianw) - Wednesday, 22 April 2020, 21:30 GMT
I'm still seeing errors with 9.0.2, it looks like the permissions on the folder aren't properly fixed?

Apr 22 20:41:39 agathebauer dhcpcd[21236]: dhcpcd-9.0.2 starting
Apr 22 20:41:39 agathebauer dhcpcd[21236]: ps_init: /var/lib/dhcpcd/var/lib/dhcpcd: Operation not permitted
Apr 22 20:41:39 agathebauer NetworkManager[12184]: <warn> [1587580899.1800] dhcp-listener: dhcp-event: didn't have associated interface.
Apr 22 20:41:39 agathebauer dhcpcd[21243]: if_learnaddrs: if_addrflags6: ::1%lo: No such file or directory
Apr 22 20:41:39 agathebauer dhcpcd[21243]: if_learnaddrs: if_addrflags6: fe80::61e3:40bc:2e99:635a%wlp3s0: No such file or directory
Apr 22 20:41:39 agathebauer NetworkManager[12184]: <warn> [1587580899.1862] dhcp-listener: dhcp-event: (pid 21243) unhandled DHCP event for interface wlp3s0
Apr 22 20:41:39 agathebauer dhcpcd[21243]: wlp3s0: connected to Access Point `LALALAND'
Apr 22 20:41:39 agathebauer dhcpcd[21243]: /var/lib/dhcpcd/duid: Permission denied
Apr 22 20:41:39 agathebauer dhcpcd[21243]: DUID 00:03:00:01:34:02:86:50:7e:b3
Apr 22 20:41:39 agathebauer dhcpcd[21243]: wlp3s0: IAID 86:50:7e:b3
Apr 22 20:41:39 agathebauer dhcpcd[21243]: wlp3s0: soliciting a DHCP lease
Apr 22 20:41:39 agathebauer dhcpcd[21243]: wlp3s0: offered 192.168.178.65 from 192.168.178.1
Apr 22 20:41:39 agathebauer dhcpcd[21243]: wlp3s0: leased 192.168.178.65 for 864000 seconds
Apr 22 20:41:39 agathebauer dhcpcd[21243]: write_lease: /var/lib/dhcpcd/wlp3s0-LALALAND.lease: Permission denied
Apr 22 20:41:39 agathebauer dhcpcd[21243]: wlp3s0: adding route to 192.168.178.0/24
Comment by Antonio Rojas (arojas) - Wednesday, 22 April 2020, 21:35 GMT
As I said above, Networkmanager problems are a different issue altogether, and the dhcpcd plugin has been disabled in the latest release

Loading...