Log IPv4 renewals

[zacknewman]

dhcpcd seems to only log RENEW-like info for IPv6 but not IPv4. Could that be changed? For example my logs always show something similar to:

Nov 21 05:45:55 router dhcpcd[36226]: em0: REPLY6 received from 2001:558:4070:b8::10
Nov 21 05:45:55 router dhcpcd[36226]: em0: renew in 3612, rebind in 5760, expire in 7200 seconds
Nov 21 06:46:07 router dhcpcd[36226]: em0: REPLY6 received from 2001:558:4070:b8::10
Nov 21 06:46:07 router dhcpcd[36226]: em0: renew in 4289, rebind in 5760, expire in 7200 seconds
Nov 21 07:57:36 router dhcpcd[36226]: em0: REPLY6 received from 2001:558:4070:b8::10
Nov 21 07:57:36 router dhcpcd[36226]: em0: renew in 3840, rebind in 5760, expire in 7200 seconds

I'd like if it also logged renewal/rebind info for IPv4.

[ColinMcInnes]

@zacknewman What version of dhcpcd?

[zacknewman]

router$ uname -a
OpenBSD router.philomathiclife.com 7.8 GENERIC.MP#54 amd64
router$ dhcpcd --version
dhcpcd 10.2.4
Copyright (c) 2006-2025 Roy Marples
Compiled in features: INET ARP ARPing IPv4LL INET6 DHCPv6 AUTH PRIVSEP
router$ cat /etc/dhcpcd.conf
noipv6rs
denyinterfaces !(em0)
allowinterfaces em0
script ""
link_rcvbuf 65536
interface em0
	duid
	iaid 0
	ia_na 0
	ia_pd 0/::/60
	ipv6rs
	nooption domain_name,domain_name_servers,domain_search,fqdn,host_name,ntp_servers,time_offset,time_servers
	option rapid_commit
	persistent
	require dhcp_server_identifier
	waitip 64
router$ cat /etc/rc.d/dhcpcd
#!/bin/ksh

daemon="/usr/local/sbin/dhcpcd"
daemon_flags="-Mq"

. /etc/rc.d/rc.subr

pexp="dhcpcd:.*manager.*"

rc_cmd $1

Note when first starting dhcpcd it does log IPv4 info:

Nov 21 09:57:21 router dhcpcd[61225]: dhcpcd-10.2.4 starting
Nov 21 09:57:21 router dhcpcd[1764]: DUID 00:04:7d:eb:51:f7:c1:3f:11:ed:bd:36:7c:c2:55:62:31:fb
Nov 21 09:57:21 router dhcpcd[1764]: no interfaces have a carrier
Nov 21 09:57:21 router dhcpcd[1764]: em0: waiting for carrier
Nov 21 09:57:21 router dhcpcd[1764]: em0: carrier acquired
Nov 21 09:57:21 router dhcpcd[1764]: em0: IAID 00:00:00:00
Nov 21 09:57:21 router dhcpcd[1764]: em0: rebinding prior DHCPv6 lease
Nov 21 09:57:21 router dhcpcd[1764]: em0: carrier lost
Nov 21 09:57:21 router dhcpcd[1764]: em0: carrier acquired
Nov 21 09:57:21 router dhcpcd[1764]: em0: IAID 00:00:00:00
Nov 21 09:57:21 router dhcpcd[1764]: em0: rebinding prior DHCPv6 lease
Nov 21 09:57:21 router dhcpcd[1764]: em0: rebinding lease of 75.70.6.73
Nov 21 09:57:21 router dhcpcd[1764]: em0: soliciting an IPv6 router
Nov 21 09:57:21 router dhcpcd[1764]: em0: Router Advertisement from fe80::21c:73ff:fe00:99
Nov 21 09:57:21 router dhcpcd[1764]: em0: advertised MTU 9192 is greater than link MTU 1500
Nov 21 09:57:21 router dhcpcd[1764]: em0: adding route to fd00:0:101:41::/64
Nov 21 09:57:21 router dhcpcd[1764]: em0: adding route to 2001:558:1028:3e9f::/64
Nov 21 09:57:21 router dhcpcd[1764]: em0: adding route to fd00:0:d:4::/64
Nov 21 09:57:21 router dhcpcd[1764]: em0: adding default route via fe80::21c:73ff:fe00:99
Nov 21 09:57:21 router dhcpcd[1764]: lo0: adding reject route to 2601:283:4e01:8790::/60 via ::1
Nov 21 09:57:21 router dhcpcd[1764]: em0: REPLY6 received from 2001:558:4070:b8::10
Nov 21 09:57:21 router dhcpcd[1764]: em0: adding address 2001:558:6040:b9:9851:c22a:89de:b915/128
Nov 21 09:57:21 router dhcpcd[1764]: em0: renew in 3691, rebind in 5760, expire in 7200 seconds
Nov 21 09:57:21 router dhcpcd[1764]: em0: delegated prefix 2601:283:4e01:8790::/60
Nov 21 09:57:21 router dhcpcd[1764]: em0: probing address 75.70.6.73/23
Nov 21 09:57:21 router dhcpcd[1764]: em0: leased 75.70.6.73 for 3452 seconds
Nov 21 09:57:21 router dhcpcd[1764]: em0: adding default route via 75.70.6.1

It's done this for as long as I remember. The oldest logs I have are from 3/2024, and I was using dhcpcd 10.0.2 then; however I believe it's been doing this since before that as well.

[ColinMcInnes]

Can you check what log level the DHCPv4/v6 messages are printing at?

This should filter out all debug level messages just in case they're being enabled somehow.

journalctl -u dhcpcd* -p info

I'm running 10.1.0 and 10.3.0, and all normal renewals are debug level, so I only see them when I enable debug logs in the conf/cmdline

[zacknewman]

I'm running 10.1.0 and 10.3.0, and all normal renewals are debug level, so I only see them when I enable debug logs in the conf/cmdline

Are you sure about that? I'm not running dhcpcd in "debug" mode; and as my logs show, IPv6 RENEW/REBIND info is still written. Ideally both IPv4 and IPv6 info would be written; but if not, then neither should be written for consistency.

dhcpcd is started with the -q/--quiet argument and no -d/--debug argument, and dhcpcd.conf does not contain the debug option.

[ColinMcInnes]

Running 10.3.0, I replaced --debug with --quiet in my setup, and I'm not seeing anything after the initial lease for IPv4 and IPv6. I'm also running in managed mode.

Can you re-test with 10.3.0?

[zacknewman]

dhcpcd 10.3.0 is broken on OpenBSD per #555. Once a working a version is released, I'll try it; but unless there is a diff since 10.2.4 that suggests the behavior will be different, my money is that this behavior will still exist.

[rsmarples]

https://github.com/NetworkConfiguration/dhcpcd/blob/master/src/dhcp6.c#L3189

So for renew, the loglevel should always be DEBUG, so I'm surprised it's logged at all by itself.

[ColinMcInnes]

@zacknewman Did you try the journalctl command to filter out debug level messages? That will help us track down what is going on here.

journalctl -u dhcpcd* -p info

[zacknewman]

@ColinMcInnes, that command only works when using systemd-journald.service(8); and as I've said a few times, I'm using OpenBSD 7.8 which doesn't use systemd(1) at all.

[ColinMcInnes]

@zacknewman is there a way to filter out the debug messages when checking the log?

What I'm trying to determine here is whether OpenBSD has done some patching to force enabling of some log messages, because renew messages should be debug level, which should be skipped over when "quiet" mode is set.

[zacknewman]

@ColinMcInnes, I was getting these IPv6 renew/rebind logs back in Nov. 2024 when I manually compiled dhcpcd 10.0.10 (i.e., when I didn't run the "package" provided by OpenBSD); so unless you mean something else when you say "whether OpenBSD has done some patching", that's not what is happening. Perhaps it's something baked into the kernel? Weird, unfortunate, and inconsistent that the kernel wouldn't do something similar for IPv4.

Snippet of logs from 11/2024 when manually compiled version of dhcpcd 10.0.10 was used using the same dhcpcd.conf and command arguments (i.e., -Mq):

Nov 16 09:20:08 router dhcpcd[9380]: em0: REPLY6 received from 2001:558:4070:b8::10
Nov 16 09:20:08 router dhcpcd[9380]: em0: renew in 3698, rebind in 5760, expire in 7200 seconds
Nov 16 10:21:46 router dhcpcd[9380]: em0: REPLY6 received from 2001:558:4070:b8::10
Nov 16 10:21:46 router dhcpcd[9380]: em0: renew in 3770, rebind in 5760, expire in 7200 seconds

I know bpf(4) handles DHCP before pf(4) gets a chance to filter anything unlike DHCPv6. I don't have any special logging enabled for pf(4) and have disabled pflogd(8), but perhaps that's somehow related. I'm pretty sure bpf(4) handles DHCP on most other platforms (e.g., Linux-based OSes) though, so that may be a red herring.