RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2109285 - fix DHCP (dhclient) accepting lease during EXTENDED event after ACD rework
Summary: fix DHCP (dhclient) accepting lease during EXTENDED event after ACD rework
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 8
Classification: Red Hat
Component: NetworkManager
Version: 8.7
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: rc
: ---
Assignee: Thomas Haller
QA Contact: David Jaša
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-07-20 21:07 UTC by Thomas Haller
Modified: 2022-11-08 11:26 UTC (History)
8 users (show)

Fixed In Version: NetworkManager-1.39.11-1.el8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2022-11-08 10:10:38 UTC
Type: Bug
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
logfile showing the issue (4.56 MB, text/plain)
2022-07-20 21:07 UTC, Thomas Haller 		no flags Details
View All


Links
System ID Private Priority Status Summary Last Updated
Red Hat Issue Tracker RHELPLAN-128544 0 None None None 2022-07-20 21:10:06 UTC
Red Hat Product Errata RHBA-2022:7680 0 None None None 2022-11-08 10:12:04 UTC
freedesktop.org Gitlab NetworkManager NetworkManager merge_requests 1308 0 None opened [th/dhclient-fix-accept] dhcp: fix EXTENDED DHCP event to accept lease for dhclient plugin 2022-07-20 21:15:14 UTC

Description Thomas Haller 2022-07-20 21:07:16 UTC 
Created attachment 1898345 [details]
logfile showing the issue

since ACD rework, there is a bug in NM's DHCP client.
In particular, it affects `dhcp=dhclient` mode.

See attached log.


This affects current rhel-8.7 and rhel-9.1.
Comment 1 Thomas Haller 2022-07-20 21:10:32 UTC 
(In reply to Thomas Haller from comment #0)
> Created attachment 1898345 [details]
> logfile showing the issue


This is rhel-8.7 package 1:1.39.7-2 with a few patches for easier reproducing the issue.

In particular, the messages from nm-dhcp-helper are visible in syslog.

We see:

Jul 20 14:30:59 node01 nm-dhcp-helper[12866]: nm-dhcp-helper[12866] <info>  [1658327459.0203] nm-dhcp-helper: event called
Jul 20 14:30:59 node01 NetworkManager[12785]: <debug> [1658327459.0217] bus-manager: (dhcp) accepted connection b014765a49204d9d on private socket
Jul 20 14:30:59 node01 NetworkManager[12785]: <debug> [1658327459.0225] dhcp4 (eth0): DHCP event (reason: 'REBOOT')
Jul 20 14:30:59 node01 NetworkManager[12785]: <info>  [1658327459.0227] dhcp4 (eth0):   address 192.168.66.101
Jul 20 14:30:59 node01 NetworkManager[12785]: <info>  [1658327459.0227] dhcp4 (eth0):   plen 24 (255.255.255.0)
Jul 20 14:30:59 node01 NetworkManager[12785]: <info>  [1658327459.0228] dhcp4 (eth0):   gateway 192.168.66.2
Jul 20 14:30:59 node01 NetworkManager[12785]: <info>  [1658327459.0228] dhcp4 (eth0):   lease time 4294967295
Jul 20 14:30:59 node01 NetworkManager[12785]: <info>  [1658327459.0228] dhcp4 (eth0):   hostname 'node01'
Jul 20 14:30:59 node01 NetworkManager[12785]: <info>  [1658327459.0228] dhcp4 (eth0):   nameserver '192.168.66.2'
Jul 20 14:30:59 node01 NetworkManager[12785]: <trace> [1658327459.0228] dhcp4 (eth0): notify: event=extended, l3cd=[f0d879b8b0807e90]
Jul 20 14:30:59 node01 NetworkManager[12785]: <info>  [1658327459.0228] dhcp4 (eth0): state changed new lease, address=192.168.66.101
...
Jul 20 14:31:59 node01 nm-dhcp-helper[12866]: nm-dhcp-helper[12866] <warn>  [1658327519.0825] failure to call notify: Timeout was reached (try signal via Event)
Jul 20 14:31:59 node01 nm-dhcp-helper[12866]: nm-dhcp-helper[12866] <info>  [1658327519.0843] success: NO



the 60 seconds timeout is reached, because NetworkManager forgot to reply the lease notification from nm-dhcp-helper on D-Bus. This is fatal for dhclient (in the attached log, nm-dhcp-client is patched to always `exit 0` and not exhibit the severe parts of the the problem).
Comment 2 David Jaša 2022-08-15 19:08:27 UTC 
Verifying as SanityOnly for NetworkManager-1.39.12-1.el8.x86_64:
a test system that experienced the issue previously (no usable internal logs regretably, but with a characteristic pattern of DHCPDECLINE followed by new DHCPDISCOVER exactly a minute after some lease-extending DHCPREQUEST) didn't experience this issue after hundreds of lease extensions. This however is not conclusive because when the system was affected, the bug manifested for couple of hours and then stopped for no apparent reason.

The new message "lease accepted right away" is visible in the logs:
srp 15 17:22:04 NetworkManager[115261]: <debug> [1660576924.0116] dhcp4 (eth0): accept lease right away

I'm also inclined not to include automated test unless there is reliable trigger for the condition (if we find later it is, we may also change Verified:SanityOnly to Verified:Tested) so for the time being, I'm leaving qe_test_coverage unchanged.
Comment 5 errata-xmlrpc 2022-11-08 10:10:38 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (NetworkManager bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2022:7680
Note You need to log in before you can comment on or make changes to this bug.