Skip to content

feat(dhcp): enable --debug option for dhcpcd#6693

Merged
holmanb merged 1 commit intocanonical:mainfrom
cjp256:dhcpcd
Jan 29, 2026
Merged

feat(dhcp): enable --debug option for dhcpcd#6693
holmanb merged 1 commit intocanonical:mainfrom
cjp256:dhcpcd

Conversation

@cjp256
Copy link
Contributor

@cjp256 cjp256 commented Jan 28, 2026

The primary motivation for this extra detail is to capture the flow when multiple DISCOVER requests are required, similar to what we see in dhclient today so we can better understand how time is spent in dhcpcd.

Without debug:

2026-01-28 18:19:59,156 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: soliciting a DHCP lease
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1

With debug:

2026-01-28 19:52:56,822 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.128 seconds
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
spawned manager process on PID 527
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
DUID 00:01:00:01:31:0d:25:98:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.0 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: soliciting a DHCP lease
eth0: spawned BPF BOOTP on PID 535
eth0: sending DISCOVER (xid 0x3793814b), next in 4.6 seconds
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: process BPF BOOTP already started on pid 535
eth0: sending REQUEST (xid 0x3793814b), next in 4.4 seconds
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true BOUND
forked to background

One interesting detail I noticed is that a persistent lease file may be used for reboots and DISCOVER is skipped:

2026-01-28 19:49:57,987 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.386 seconds
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned manager process on PID 527
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.4 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: rebinding lease of 10.0.0.4
eth0: spawned BPF ARP 10.0.0.4 on PID 545
eth0: sending REQUEST (xid 0x3740297a), next in 4.5 seconds
eth0: spawned BPF BOOTP on PID 546
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true REBOOT
forked to background

The --debug option has been around forever for dhcpcd so it should be safe. We can see it the oldest tagged version in git and Ubuntu 14.04's manpage:
https://manpages.ubuntu.com/manpages//trusty/man8/dhcpcd-bin.8.html

Test Steps

Create test image & provision. Reboot. Verify expected outputs.

Merge type

  • Squash merge using "Proposed Commit Message"
  • Rebase and merge unique commits. Requires commit messages per-commit each referencing the pull request number (#<PR_NUM>)

The primary motivation for this extra detail is to capture the
flow when multiple DISCOVER requests are required, similar to
what we see in dhclient today so we can better understand how
time is spent in dhcpcd.

Without debug:

```
2026-01-28 18:19:59,156 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: soliciting a DHCP lease
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
```

With debug:

```
2026-01-28 19:52:56,822 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.128 seconds
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
spawned manager process on PID 527
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
DUID 00:01:00:01:31:0d:25:98:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.0 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: soliciting a DHCP lease
eth0: spawned BPF BOOTP on PID 535
eth0: sending DISCOVER (xid 0x3793814b), next in 4.6 seconds
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: process BPF BOOTP already started on pid 535
eth0: sending REQUEST (xid 0x3793814b), next in 4.4 seconds
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true BOUND
forked to background
```

One interesting detail I noticed is that a persistent lease file
may be used for reboots and DISCOVER is skipped:

```
2026-01-28 19:49:57,987 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.386 seconds
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned manager process on PID 527
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.4 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: rebinding lease of 10.0.0.4
eth0: spawned BPF ARP 10.0.0.4 on PID 545
eth0: sending REQUEST (xid 0x3740297a), next in 4.5 seconds
eth0: spawned BPF BOOTP on PID 546
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true REBOOT
forked to background
```

The --debug option has been around forever for dhcpcd so it should
be safe.  We can see it the oldest tagged version in git and
Ubuntu 14.04's manpage:
https://manpages.ubuntu.com/manpages//trusty/man8/dhcpcd-bin.8.html

Signed-off-by: Chris Patterson <cpatterson@microsoft.com>
@peytonr18
Copy link
Contributor

LGTM!

@holmanb
Copy link
Member

holmanb commented Jan 29, 2026

This looks good to me. Thanks @cjp256!

@holmanb holmanb merged commit 9c2faf8 into canonical:main Jan 29, 2026
22 of 23 checks passed
drzee99 pushed a commit to drzee99/cloud-init that referenced this pull request Feb 2, 2026
The primary motivation for this extra detail is to capture the
flow when multiple DISCOVER requests are required, similar to
what we see in dhclient today so we can better understand how
time is spent in dhcpcd.

Without debug:

```
2026-01-28 18:19:59,156 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: soliciting a DHCP lease
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
```

With debug:

```
2026-01-28 19:52:56,822 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.128 seconds
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
spawned manager process on PID 527
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
DUID 00:01:00:01:31:0d:25:98:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.0 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: soliciting a DHCP lease
eth0: spawned BPF BOOTP on PID 535
eth0: sending DISCOVER (xid 0x3793814b), next in 4.6 seconds
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: process BPF BOOTP already started on pid 535
eth0: sending REQUEST (xid 0x3793814b), next in 4.4 seconds
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true BOUND
forked to background
```

One interesting detail I noticed is that a persistent lease file
may be used for reboots and DISCOVER is skipped:

```
2026-01-28 19:49:57,987 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.386 seconds
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned manager process on PID 527
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.4 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: rebinding lease of 10.0.0.4
eth0: spawned BPF ARP 10.0.0.4 on PID 545
eth0: sending REQUEST (xid 0x3740297a), next in 4.5 seconds
eth0: spawned BPF BOOTP on PID 546
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true REBOOT
forked to background
```

The --debug option has been around forever for dhcpcd so it should
be safe.  We can see it the oldest tagged version in git and
Ubuntu 14.04's manpage:
https://manpages.ubuntu.com/manpages//trusty/man8/dhcpcd-bin.8.html

Signed-off-by: Chris Patterson <cpatterson@microsoft.com>
holmanb pushed a commit that referenced this pull request Feb 5, 2026
The primary motivation for this extra detail is to capture the
flow when multiple DISCOVER requests are required, similar to
what we see in dhclient today so we can better understand how
time is spent in dhcpcd.

Without debug:

```
2026-01-28 18:19:59,156 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: soliciting a DHCP lease
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
```

With debug:

```
2026-01-28 19:52:56,822 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.128 seconds
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:52:56,822 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
spawned manager process on PID 527
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
DUID 00:01:00:01:31:0d:25:98:60:45:bd:86:6f:e1
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.0 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: soliciting a DHCP lease
eth0: spawned BPF BOOTP on PID 535
eth0: sending DISCOVER (xid 0x3793814b), next in 4.6 seconds
eth0: offered 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: process BPF BOOTP already started on pid 535
eth0: sending REQUEST (xid 0x3793814b), next in 4.4 seconds
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true BOUND
forked to background
```

One interesting detail I noticed is that a persistent lease file
may be used for reboots and DISCOVER is skipped:

```
2026-01-28 19:49:57,987 - performance.py[DEBUG]: Running ['dhcpcd', '--ipv4only', '--waitip', '--persistent', '--noarp', '--debug', '--script=/bin/true', 'eth0'] took 0.386 seconds
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stdout for interface=eth0:
2026-01-28 19:49:57,987 - azure.py[DEBUG]: dhcp client stderr for interface=eth0: dhcpcd-10.0.6 starting
chrooting as dhcpcd to /usr/lib/dhcpcd
sandbox: seccomp
spawned manager process on PID 527
spawned privileged proxy on PID 528
spawned controller proxy on PID 529
DUID 00:01:00:01:31:0d:0f:cd:60:45:bd:86:6f:e1
eth0: executing: /bin/true PREINIT
eth0: executing: /bin/true CARRIER
eth0: IAID bd:86:6f:e1
eth0: delaying IPv4 for 0.4 seconds
eth0: reading lease: /var/lib/dhcpcd/eth0.lease
eth0: rebinding lease of 10.0.0.4
eth0: spawned BPF ARP 10.0.0.4 on PID 545
eth0: sending REQUEST (xid 0x3740297a), next in 4.5 seconds
eth0: spawned BPF BOOTP on PID 546
eth0: acknowledged 10.0.0.4 from 168.63.129.16 LVL101082702015SOC
eth0: leased 10.0.0.4 for infinity
eth0: writing lease: /var/lib/dhcpcd/eth0.lease
eth0: adding IP address 10.0.0.4/16 broadcast 10.0.255.255
eth0: using Classless Static Routes
eth0: adding route to 10.0.0.0/16
eth0: adding default route via 10.0.0.1
eth0: adding host route to 168.63.129.16 via 10.0.0.1
eth0: adding host route to 169.254.169.254 via 10.0.0.1
eth0: executing: /bin/true REBOOT
forked to background
```

The --debug option has been around forever for dhcpcd so it should
be safe.  We can see it the oldest tagged version in git and
Ubuntu 14.04's manpage:
https://manpages.ubuntu.com/manpages//trusty/man8/dhcpcd-bin.8.html

Signed-off-by: Chris Patterson <cpatterson@microsoft.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants