Bug 2109285
| Summary: | fix DHCP (dhclient) accepting lease during EXTENDED event after ACD rework | ||||||
|---|---|---|---|---|---|---|---|
| Product: | Red Hat Enterprise Linux 8 | Reporter: | Thomas Haller <thaller> | ||||
| Component: | NetworkManager | Assignee: | Thomas Haller <thaller> | ||||
| Status: | CLOSED ERRATA | QA Contact: | David Jaša <djasa> | ||||
| Severity: | unspecified | Docs Contact: | |||||
| Priority: | unspecified | ||||||
| Version: | 8.7 | CC: | bgalvani, djasa, lrintel, oshoval, rkhan, sukulkar, till, vbenes | ||||
| Target Milestone: | rc | Keywords: | Triaged | ||||
| Target Release: | --- | Flags: | pm-rhel:
mirror+
|
||||
| Hardware: | Unspecified | ||||||
| OS: | Unspecified | ||||||
| Whiteboard: | |||||||
| Fixed In Version: | NetworkManager-1.39.11-1.el8 | Doc Type: | If docs needed, set a value | ||||
| Doc Text: | Story Points: | --- | |||||
| Clone Of: | Environment: | ||||||
| Last Closed: | 2022-11-08 10:10:38 UTC | Type: | Bug | ||||
| Regression: | --- | Mount Type: | --- | ||||
| Documentation: | --- | CRM: | |||||
| Verified Versions: | Category: | --- | |||||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |||||
| Cloudforms Team: | --- | Target Upstream Version: | |||||
| Embargoed: | |||||||
| Attachments: |
|
||||||
(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). 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. 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 |
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.