Add timestamp to the output of `dhcpcd -U`

[zacknewman]

In #558 I requested that DHCP RENEWals be logged like they are for DHCPv6. This inconsistency was found to be due to how DHCP code uses logdebugx instead of logmessage like DHCPv6 code does. While I do think the behavior should be made to be consistent, what I actually would like to have is for a way to see information about a DHCP or DHCPv6 lease without enabling "debug" mode.

I try to plan network maintenance around my DHCP and DHCPv6 leases in an effort to keep whatever IPs were assigned. Unfortunately, dhcpcd -U only provides information related to RENEWals and expirations at the time the exchange occurred. Without also knowing when the exchange occurred, this information is not of much use. Since DHCPv6 lease information is logged to syslog(3) (at least on OpenBSD), I am able to get the necessary information since it includes the timestamp. Without the same for DHCP though, I still open myself up to the chance that network maintenance causes my DHCP lease to not be RENEWed (likely) causing a new IP to be assigned.

Would it be possible to include timestamp information in dhcpcd -U? For example instead of something like this:

router$ dhcpcd -U ixl2
reason=CARRIER
interface=ixl2
protocol=link
if_configured=true
ifcarrier=up
ifmetric=0
ifwireless=0
ifflags=34883
ifmtu=1500

reason=RENEW
interface=ixl2
protocol=dhcp
ip_address=76.131.95.65
subnet_cidr=23
network_number=76.131.94.0
subnet_mask=255.255.254.0
routers=76.131.94.1
broadcast_address=255.255.255.255
dhcp_lease_time=7200
dhcp_message_type=5
dhcp_server_identifier=96.113.84.152
dhcp_renewal_time=4159

reason=ROUTERADVERT
interface=ixl2
protocol=ra
nd1_from=fe80::21c:73ff:fe00:99
nd1_acquired=284941
nd1_now=284944
nd1_hoplimit=64
nd1_flags=MO
nd1_lifetime=1800
nd1_source_address=001c73000099
nd1_prefix_information1_length=64
nd1_prefix_information1_flags=L
nd1_prefix_information1_vltime=2592000
nd1_prefix_information1_pltime=604800
nd1_prefix_information1_prefix=fd00:0:101:41::
nd1_prefix_information2_length=64
nd1_prefix_information2_flags=L
nd1_prefix_information2_vltime=2592000
nd1_prefix_information2_pltime=604800
nd1_prefix_information2_prefix=2001:558:1028:3e9f::
nd1_prefix_information3_length=64
nd1_prefix_information3_flags=L
nd1_prefix_information3_vltime=2592000
nd1_prefix_information3_pltime=604800
nd1_prefix_information3_prefix=fd00:0:d:4::

reason=RENEW6
interface=ixl2
protocol=dhcp6
dhcp6_client_id=000445c0fc0ae1b211f09c79f0b2b93691a4
dhcp6_server_id=000100011caae03b40a8f02e8ef4
dhcp6_ia_na1_iaid=00000000
dhcp6_ia_na1_t1=43200
dhcp6_ia_na1_t2=69120
dhcp6_ia_na1_ia_addr1=2001:558:6040:b9:7ce5:5b1a:d32c:1bf0
dhcp6_ia_na1_ia_addr1_pltime=86400
dhcp6_ia_na1_ia_addr1_vltime=86400
dhcp6_ia_pd1_iaid=00000000
dhcp6_ia_pd1_t1=43200
dhcp6_ia_pd1_t2=69120
dhcp6_ia_pd1_prefix1_pltime=86400
dhcp6_ia_pd1_prefix1_vltime=86400
dhcp6_ia_pd1_prefix1_length=60
dhcp6_ia_pd1_prefix1=2601:283:4e00:fdd0::

it'd output something like this:

router$ dhcpcd -U ixl2
reason=CARRIER
interface=ixl2
protocol=link
if_configured=true
ifcarrier=up
ifmetric=0
ifwireless=0
ifflags=34883
ifmtu=1500
timestamp: Aug 25 06:39:01

reason=RENEW
interface=ixl2
protocol=dhcp
ip_address=76.131.95.65
subnet_cidr=23
network_number=76.131.94.0
subnet_mask=255.255.254.0
routers=76.131.94.1
broadcast_address=255.255.255.255
dhcp_lease_time=7200
dhcp_message_type=5
dhcp_server_identifier=96.113.84.152
dhcp_renewal_time=4159
timestamp: Aug 25 06:39:01

reason=ROUTERADVERT
interface=ixl2
protocol=ra
nd1_from=fe80::21c:73ff:fe00:99
nd1_acquired=284941
nd1_now=284944
nd1_hoplimit=64
nd1_flags=MO
nd1_lifetime=1800
nd1_source_address=001c73000099
nd1_prefix_information1_length=64
nd1_prefix_information1_flags=L
nd1_prefix_information1_vltime=2592000
nd1_prefix_information1_pltime=604800
nd1_prefix_information1_prefix=fd00:0:101:41::
nd1_prefix_information2_length=64
nd1_prefix_information2_flags=L
nd1_prefix_information2_vltime=2592000
nd1_prefix_information2_pltime=604800
nd1_prefix_information2_prefix=2001:558:1028:3e9f::
nd1_prefix_information3_length=64
nd1_prefix_information3_flags=L
nd1_prefix_information3_vltime=2592000
nd1_prefix_information3_pltime=604800
nd1_prefix_information3_prefix=fd00:0:d:4::
timestamp: Aug 25 06:39:01

reason=RENEW6
interface=ixl2
protocol=dhcp6
dhcp6_client_id=000445c0fc0ae1b211f09c79f0b2b93691a4
dhcp6_server_id=000100011caae03b40a8f02e8ef4
dhcp6_ia_na1_iaid=00000000
dhcp6_ia_na1_t1=43200
dhcp6_ia_na1_t2=69120
dhcp6_ia_na1_ia_addr1=2001:558:6040:b9:7ce5:5b1a:d32c:1bf0
dhcp6_ia_na1_ia_addr1_pltime=86400
dhcp6_ia_na1_ia_addr1_vltime=86400
dhcp6_ia_pd1_iaid=00000000
dhcp6_ia_pd1_t1=43200
dhcp6_ia_pd1_t2=69120
dhcp6_ia_pd1_prefix1_pltime=86400
dhcp6_ia_pd1_prefix1_vltime=86400
dhcp6_ia_pd1_prefix1_length=60
dhcp6_ia_pd1_prefix1=2601:283:4e00:fdd0::
timestamp: Aug 25 06:39:01

Note in my case I only care about DHCPv6 and DHCP, so not adding timestamp info to link-level messages or router advertisements is fine. For DHCPv6 and DHCP, I would like timestamp information not just for RENEWals but also BOUND, REBIND, etc.

[ColinMcInnes]

Seems like a good idea to me!

[rsmarples]

I'm open to adding this and think it's a good thing, but I am very curious as to the use case for it because I'm willing to bet a it could be solved in a hook script.

[ColinMcInnes]

dhcpcd -U > /tmp/latest-lease-details 2&1 from within an exit-hook results in an empty file. I think it's a privsep limitation?

[ColinMcInnes]

Actually, let me recheck that, it might be just that I wasn't specifying interface.

[ColinMcInnes]

It's actually worse than I thought... it gets stuck

I have it trigger dhcpcd -U on a RENEW

dhcpcd 3427 0.0 0.2 4436 3044 ? Ss 14:16 0:00 dhcpcd: [manager] [ip4] [ip6]
root 3428 0.0 0.2 4728 2112 ? S 14:16 0:00 dhcpcd: [privileged proxy]
dhcpcd 3429 0.0 0.0 4300 400 ? S 14:16 0:00 dhcpcd: [network proxy]
dhcpcd 3430 0.0 0.0 4300 400 ? S 14:16 0:00 dhcpcd: [control proxy]
dhcpcd 4254 0.0 0.1 4448 1444 ? S 14:17 0:00 dhcpcd: [BPF ARP] eth0 192.168.226.119
root 16265 0.0 0.1 2492 1800 ? S 14:22 0:00 /bin/sh /usr/libexec/dhcpcd-run-hooks
root 16297 0.0 0.3 4300 3568 ? S 14:22 0:00 dhcpcd -U

I will see if I can scope the privsep to see what specifically it doesn't like.

[zacknewman]

I'm open to adding this and think it's a good thing, but I am very curious as to the use case for it because I'm willing to bet a it could be solved in a hook script.

I have been using the same ISP for about a decade, and I have had my IPs change maybe a handful of times. Every time it was due to missing the RENEWal window which could be due to maintenance on their side, a long power outage on my side, or an issue that crept up when performing an upgrade or something to my networking equipment.

No question hooks are the appropriate solution for most people, and it's what I would use if this were to change (e.g., I change ISPs to an entity that doesn't like assigning the same IPs). This means I (ab)use dhcpcd to essentially only do the necessary exchanges and nothing more and is why my dhcpcd.conf is instructed to remove a lot of options. I disable hooks completely in fact.. Everything else is static including carving out the /64 subnets from the /60 prefix that is delegated to me. My recursive DNS server has static IPs. My NTP server has static IPs. Essentially everything.

I do have an emergency ksh(1) script¹ that I maintain that I run in the very rare event that my IPs have changed. Again, if I needed to use this that often, I'd change my setup.

Footnotes

1. Nothing too elaborate. Basically it invokes dhcpcd -U to obtain the necessary information before using sed(1) to replace the IPs in the files that need to be changed before restarting the affected network interfaces, pf(4), and any affected daemons. ↩

[rsmarples]

Typically a RENEW (assuming carrier stays up) fails with an ISP because their DHCP server isn't reachable by IP and only via DHCP RELAY.
This is find because DHCP will then attempt to REBIND and you generally keep the same IP.
Also an IP address can change during the RENEW phase as well - you could commonly get a NAK or the server could just respond with a different IP address. dhcpcd handles both just fine (or should).

Not that I encourage you to change what works for you, but I would work your approach differently because I know that due to the nature of DHCP, an address can change - it is not guaranteed at the client to be otherwise.
As such applications and thus configuration should expect it and I'm always irked when I have to configure an ip address anywhere in my configs. If I have to then I get my hooks to write the ip address to the config and doing it that way.

My flow is write new config -> diff new config vs old -> if different, backup old install new and restart the service.
This works when I change ISP and I don't have to mess or restrict the stock dhcpcd.conf file too much either.

What the appliction expects to bind to an interface: listen: 1.2.3.4
How I expect the application to bind to an interface: listen %eth0 - listen to any address on eth0 - suffix with :0 for the first address, etc, something like that.
It's 2026 and the former config is not good when network renumbering can and does happen :)
Anyway rant over.

I'll look at implementing this sometime next week as I'm a bit busy for weekend now.

[zacknewman]

I already know almost all of that, but I have 10 years of inertia behind this and it hasn't really failed me. I'm also aware of the "risk" I'm taking; thus a change in this behavior is on my radar. Should be noted I also have a VPN endpoint which requires my WireGuard clients to be configured to use the correct IPv6 and IPv4 endpoints. This means any change to my IPs would require manual intervention anyway on such client devices. I have a VPS as well that I can use as a VPN since it has truly static IPs, but I prefer to connect to my home network when possible. While I appreciate your thoughts and I'm sure as a DHCP/DHCPv6 "expert" it also annoys you when one like myself (ab)uses DHCP/DHCPv6, I promise I know what I'm doing and am willing to face the consequences if/when this no longer holds. I think adding a timestamp to dhcpcd -U is inline with its purpose even if you understandably disagree with my choice to use it in this manner.

[rsmarples]

It's actually worse than I thought... it gets stuck

I have it trigger dhcpcd -U on a RENEW

dhcpcd 3427 0.0 0.2 4436 3044 ? Ss 14:16 0:00 dhcpcd: [manager] [ip4] [ip6] root 3428 0.0 0.2 4728 2112 ? S 14:16 0:00 dhcpcd: [privileged proxy] dhcpcd 3429 0.0 0.0 4300 400 ? S 14:16 0:00 dhcpcd: [network proxy] dhcpcd 3430 0.0 0.0 4300 400 ? S 14:16 0:00 dhcpcd: [control proxy] dhcpcd 4254 0.0 0.1 4448 1444 ? S 14:17 0:00 dhcpcd: [BPF ARP] eth0 192.168.226.119 root 16265 0.0 0.1 2492 1800 ? S 14:22 0:00 /bin/sh /usr/libexec/dhcpcd-run-hooks root 16297 0.0 0.3 4300 3568 ? S 14:22 0:00 dhcpcd -U

I will see if I can scope the privsep to see what specifically it doesn't like.

It's not a privsep issue, dhcpcd -U gets stuck in a hook without it just as easily.
The problem is dhcpcd blocks for the script to finish and dhcpcd -U needs dhcpcd to be running.
That is not easily fixable.

Also you have all the information you need in environment variables when the hooks run so I'm not massively motivated in fixing that.

[ColinMcInnes]

Also you have all the information you need in environment variables when the hooks run so I'm not massively motivated in fixing that.

I agree, that's how I solved it, including tacking on a timestamp, just noting that the "obvious" solution to dumping the current leases status won't work in an exit hook.

Also it just dumps the env from the current interaction, so an eth0 IPv4 hook won't report on an eth2 IPv6 for example, you'd have to track them all separately and combine them.

In the end, the solution to @zacknewman's issue is something like "use an exit hook to monitor for IP changes, and if those occur, notify the appropriate daemons to reconfigure"

case "$reason" in
    RENEW)
        if [ -n "$old_ip_address" ] && [ "$new_ip_address" != "$old_ip_address" ]; then 
             logger -t "$0" -p user.debug "IP changed, configuring $new_ip_address"
             # Notify services to switch to new IP
        fi
        ;;
esac

[zacknewman]

In the end, the solution to @zacknewman's issue is something like "use an exit hook to monitor for IP changes, and if those occur, notify the appropriate daemons to reconfigure"

No, that's not the solution for me. It's the solution that one should suggest to the average person or even yourself, but it's not appropriate for me. I don't want to spend time justifying what I'm doing and why it's the correct decision for me, and it's why I hesitated even answering Roy's question about the use case because I anticipated this interaction.

It's important to accept that existential arguments are inherently meaningless because liar's paradox withstanding everything is possible. This means any argument of the form "I would/wouldn't do that because x is possible" is meaningless. It's possible I don't exist. It's possible 2 + 2 = 4 is not true. It's possible the water I'm currently drinking was laced with cyanide, and I will be dead shortly due to poisoning. In reality what people mean is that the expected value of an event is/isn't worth it based on some probabilistic distribution coupled with some units they are using to measure the "value".

In my case the units are "quality of life plus added security". The probabilistic distribution is one that would predict a change in IP twice every decade. Now fortunately, Bayesian statistics mandate that I constantly re-evaluate my probabilities based on new information and events. This means that in the same way that just because I flipped this coin 100 times and 52 of the times landed on heads, I must account for the possibility the coin is in fact unfair and that if after the next 100 flips I find the total count of heads to be 140, then I'm obligated to adjust the probabilities. In fact basic stats shows that after an infinite number of flips of a truly fair coin, there will not only be a subsequence of an infinite number of consecutive heads but there will be an infinite number of said subsequences (i.e., not only is "everything possible" but any event will happen and will happen an infinite number of times given an infinite number of opportunities because any event has actual probability exclusively between 0 and 1).

Now am I saying the probability that my ISP after a decade of very rarely changing my IPs will suddenly change my IPs has the same odds of my glass of water being laced with cyanide or the same odds that 2 + 2 ≠ 4? Of course not. But the odds are clearly substantially lower than one would understandably expect for a random ISP in some random geographic location. Additionally, the "quality of life" hit that happens is the following *drum roll please*: ./fix-ips.sh. This is run manually with me physically connected to the serial console on my router after it's successfully booted and daemons (including dhcpcd) had an opportunity to begin. If there is an issue (e.g., unbound(8) can't start because the IPs assigned to outgoing-interface are invalid), then I consult syslog(3) to see what dhcpcd did. If I see the IPs are different, then I manually run that script. Sure if the consequences were instead something like death, I would not be doing this because while the probability is low the consequences are so dire that the probability is not low enough (e.g., as low of a probability that my water was laced with cyanide or even something much higher like dying in a car wreck and yet I still drive).

The security benefits I get from not allowing dhcpcd access to just manipulate files is worth it to me. I don't use UPnP because I don't like the idea that an online game is able to just punch holes in my firewall as it needs. I don't want to give dhcpcd access to my firewall rules to change the IPs that are based on the IPs assigned to me. Note, I only accept a specific link-local address because in 5+ years it's been the same link-local address my ISP's server has used. I don't want dhcpcd to assign values to my unbound.conf(5)'s outgoing-interface. I want to control that. Now Bayesian stats mandates I re-evaluate this. If suddenly my IPs aren't nearly as stable, then you better believe the quality of life of not having to run ./fix-ips.sh every month (or some maximum frequency threshold I'm content with) is worth the hit in security. I'll start to allow dhcpcd access to files I ideally wouldn't want it to have. I will remove the WireGuard endpoint which requires stable IPs. I will remove hardcoded IPs in my firewall rules. Until then though and for me based on my probabilistic distributions and my "value units" and security, I'll continue to do it this way.

Fortunately the inclusion of a timestamp to the output of dhcpcd -U is orthogonal to all this nonsense. We all agree that that information is currently not accessible without putting dhcpcd in "debug" mode. The question then becomes it would seem "is a timestamp at least as useful as every item currently in dhcpcd -U?" The answer is unquestionably yes. Proof. "Useful" implies "informative" (note the converse does not hold (i.e., just because something is informative doesn't mean it's useful)). Why? Well if something weren't informative, then how could it be of use? If I'm able to ascertain the same information from something else, then it's useless. Maybe such a thing is convenient, but that's doesn't make it useful. We already agree that a timestamp is informative because we can't recreate it based on anything in dhcpcd -U or syslog(3) when not in "debug" mode. This means it's at least possible for it to be "useful". Meanwhile this is what dhcpcd -U ixl2 currently outputs:

reason=CARRIER
interface=ixl2
ifxname=ixl2
protocol=link
if_configured=true
ifcarrier=up
ifmetric=0
ifwireless=0
ifflags=34883
ifmtu=1500

reason=RENEW
interface=ixl2
ifxname=ixl2
protocol=dhcp
ip_address=76.131.95.65
subnet_cidr=23
network_number=76.131.94.0
subnet_mask=255.255.254.0
routers=76.131.94.1
broadcast_address=255.255.255.255
dhcp_lease_time=7200
dhcp_message_type=5
dhcp_server_identifier=96.113.84.152
dhcp_renewal_time=3843

reason=ROUTERADVERT
interface=ixl2
ifxname=ixl2
protocol=ra
nd1_from=fe80::21c:73ff:fe00:99
nd1_acquired=69220
nd1_now=69221
nd1_hoplimit=64
nd1_flags=MO
nd1_lifetime=1800
nd1_source_address=001c73000099
nd1_prefix_information1_length=64
nd1_prefix_information1_flags=L
nd1_prefix_information1_vltime=2592000
nd1_prefix_information1_pltime=604800
nd1_prefix_information1_prefix=fd00:0:101:41::
nd1_prefix_information2_length=64
nd1_prefix_information2_flags=L
nd1_prefix_information2_vltime=2592000
nd1_prefix_information2_pltime=604800
nd1_prefix_information2_prefix=fd00:0:d:4::
nd1_prefix_information3_length=64
nd1_prefix_information3_flags=L
nd1_prefix_information3_vltime=2592000
nd1_prefix_information3_pltime=604800
nd1_prefix_information3_prefix=2001:558:1028:3e9f::

reason=RENEW6
interface=ixl2
ifxname=ixl2
protocol=dhcp6
dhcp6_client_id=000445c0fc0ae1b211f09c79f0b2b93691a4
dhcp6_server_id=000100011caae03b40a8f02e8ef4
dhcp6_ia_na1_iaid=00000000
dhcp6_ia_na1_t1=4239
dhcp6_ia_na1_t2=5760
dhcp6_ia_na1_ia_addr1=2001:558:6040:b9:7ce5:5b1a:d32c:1bf0
dhcp6_ia_na1_ia_addr1_pltime=7200
dhcp6_ia_na1_ia_addr1_vltime=7200
dhcp6_ia_pd1_iaid=00000000
dhcp6_ia_pd1_t1=4239
dhcp6_ia_pd1_t2=5760
dhcp6_ia_pd1_prefix1_pltime=7200
dhcp6_ia_pd1_prefix1_vltime=7200
dhcp6_ia_pd1_prefix1_length=60
dhcp6_ia_pd1_prefix1=2601:283:4e00:fdd0::
dhcp6_reconfigure_accept=
dhcp6_auth_protocol=3
dhcp6_auth_algorithm=1
dhcp6_auth_rdm=0
dhcp6_auth_replay=31f479f3035f480f
dhcp6_auth_information=015f3a16ca13dd89fe5e48d158efd50759

Can you really not find a single thing that's not as useful as a timestamp there? For starters what about this line: subnet_cidr=23? I claim this is not only useless but more strongly 100% uninformative. Why? Because of this line: subnet_mask=255.255.254.0? With 100% accuracy 100% of the time, I can already re-create subnet_cidr based on this information—note the converse is not true specifically when the subnet mask is something "unusual" (e.g., 89.123.56.98). QED.

Now we are logically obligated to either remove that line since it's truly useless and more strongly uninformative or add something that has more use/information like a timestamp. Even without that, what about dhcp6_auth_replay=31f479f3035f480f is "useful"? Note you can't justify it on grounds of "debugging" since it's returned regardless if dhcpcd is in "debug" mode; additionally, timestamps are extremely useful when debugging so that's also an argument for a timestamp.

In summary, please add a timestamp. Yes, my probabilistic distribution is not the same as yours nor are my "value units"; but that doesn't make a timestamp useless.

[ColinMcInnes]

It's generated from a command line utility that can just as easily also run "date".

If you're going to go on a tirade, maybe put that energy into a patch file.

[zacknewman]

I'm tired of "defending" my approach; hence the "tirade"/"soapbox". In my situation the only time IPs change are due to missing a RENEWal window. As long as I don't miss such a window, my IPs will not change. Without having timestamp info in dhcpcd -U, there's no way to know the next time a RENEWal will occur unless I put dhcpcd in "debug" mode and read syslog(3) or restart dhcpcd and invoke dhcpcd -U since I know the reference time such a lease applies to (i.e., the time I restarted dhcpcd).

You are right it would be better to add such content in the form of a PR than rant. Unfortunately my fluency in C is limited, and I don't like the idea of letting an LLM do it for me. Sorry if I offended you. I'll hide my response in an effort to avoid the toxicity it may cause. Sometimes frustration gets the best of me.

[ColinMcInnes]

I'm tired of "defending" my approach; hence the "tirade"/"soapbox". In my situation the only time IPs change are due to missing a RENEWal window. As long as I don't miss such a window, my IPs will not change. Without having timestamp info in dhcpcd -U, there's no way to know the next time a RENEWal will occur unless I put dhcpcd in "debug" mode and read syslog(3) or reboot the machine and invoke dhcpcd -U since I know the reference time such a lease applies to (i.e., the time I booted the machine).

Exit hooks run every renewal and can generate that timestamp for you, and even notify you if the IP changes. If you don't want it to take automatic action, fine, but it can still write to a file to let you know a RENEW occurred, at what time, and the length of the renewal period.

EDIT: Forget the bit about REBIND, that's sent when the RENEW failed but the REBIND succeeded. I'm thinking of my own setup, where I've patched in some extra exit-hooks to let me know the RENEW failed and it's now doing a rebind, which gives me a window to fire off notifications to a monitor.

If that sounds useful I could submit a patch. It adds a LOT of exit hooks though, as I wanted to know every time dhcpcd did anything in case I wanted to react to it.