Bug 1901084
| Summary: | [OSP13] Lookup to ironic server don't handle network errors | ||
|---|---|---|---|
| Product: | Red Hat OpenStack | Reporter: | Bartosz Kupidura <bartosz> |
| Component: | openstack-ironic-python-agent | Assignee: | Steve Baker <sbaker> |
| Status: | CLOSED DUPLICATE | QA Contact: | Alistair Tonner <atonner> |
| Severity: | high | Docs Contact: | |
| Priority: | high | ||
| Version: | 13.0 (Queens) | CC: | jslagle, sbaker |
| Target Milestone: | z13 | Keywords: | Triaged |
| Target Release: | 13.0 (Queens) | ||
| Hardware: | x86_64 | ||
| OS: | Linux | ||
| Whiteboard: | |||
| Fixed In Version: | openstack-ironic-python-agent-3.2.4-2.el7ost | Doc Type: | If docs needed, set a value |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2020-12-09 22:21:02 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: | |||
rhosp-director-images-ipa-x86_64-13.0-20200610.2.el7ost.noarch has a June version, and the downstream backport of this fix[1] landed in August. I'll update with a MODIFIED version when I've found it The fix landed downstream on August 24, and is in openstack-ironic-python-agent-3.2.4-2.el7ost and rhosp-director-images-ipa-13.0-20201112.1.el7ost.noarch.rpm which is already in the z13 release. I'll close this as a duplicate of the original tracking bug #1862105. *** This bug has been marked as a duplicate of bug 1862105 *** |
Description of problem: In some random cases, its possible that `ironic-python-agent` will start sending callbacks to ironic-server when network is not ready. This leads to node in `wait cleanup` state till timeout, then node lands in `cleanup failed` state. ``` /usr/lib/python2.7/site-packages/ironic_python_agent/agent.py: [...] def run(self): [...] self._wait_for_interface() content = self.api_client.lookup_node( hardware_info=hardware.dispatch_to_managers( 'list_hardware_info'), timeout=self.lookup_timeout, starting_interval=self.lookup_interval, node_uuid=uuid) ``` _wait_for_interface is just waiting for mac address available on any interface. Its possible that interface is up, but didnt receive IP address from DHCP. ``` Nov 24 03:09:47 localhost.localdomain ironic-python-agent[1254]: 2020-11-24 03:09:47.990 1254 WARNING requests.sessions [-] TEST send exception HTTPConnectionPool(host='192.168.213.1', port=6385): Max retries exceeded with url: /v1/lookup?addresses=0c%3Ac4%3A7a%3A81%3Aab%3A6f%2C0c%3Ac4%3A7a%3A81%3Aab%3A6e%2C0c%3Ac4%3A7a%3Ab7%3A2d%3Adb%2C0c%3Ac4%3A7a%3Ab7%3A2d%3Ada (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection objec t at 0x7fb70eb45950>: Failed to establish a new connection: [Errno 101] Network is unreachable',)): ConnectionError: HTTPConnectionPool(host='192.168.213.1', port=6385): Max retries exceeded with url: /v1/lookup?addresses=0c%3Ac 4%3A7a%3A81%3Aab%3A6f%2C0c%3Ac4%3A7a%3A81%3Aab%3A6e%2C0c%3Ac4%3A7a%3Ab7%3A2d%3Adb%2C0c%3Ac4%3A7a%3Ab7%3A2d%3Ada (Caused by NewConnectionError('<requests.packages.urllib3.connection.HTTPConnection object at 0x7fb70eb45950>: Failed to establish a new connection: [Errno 101] Network is unreachable',)) ``` Logs from dhcp client: ``` Nov 24 03:09:33 localhost NetworkManager[654]: <info> [1606205373.6306] dhcp-init: Using DHCP client 'dhclient' Nov 24 03:09:35 localhost systemd: Created slice system-dhcp\x2dinterface.slice. Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: eno2...Configured eno2 Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: eno1...Configured eno1 Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: ens7f0...Configured ens7f0 Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: ens7f1...Configured ens7f1 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.4984] dhcp4 (eno1): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5001] dhcp4 (eno1): dhclient started with pid 1207 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5017] dhcp4 (eno2): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5031] dhcp4 (eno2): dhclient started with pid 1211 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5046] dhcp4 (ens7f0): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5062] dhcp4 (ens7f0): dhclient started with pid 1216 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5087] dhcp4 (ens7f1): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5103] dhcp4 (ens7f1): dhclient started with pid 1223 Nov 24 03:09:48 localhost NetworkManager[654]: <info> [1606205388.3010] dhcp4 (eno1): address 192.168.213.144Nov 24 03:09:33 localhost NetworkManager[654]: <info> [1606205373.6306] dhcp-init: Using DHCP client 'dhclient' Nov 24 03:09:35 localhost systemd: Created slice system-dhcp\x2dinterface.slice. Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: eno2...Configured eno2 Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: eno1...Configured eno1 Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: ens7f0...Configured ens7f0 Nov 24 03:09:40 localhost dhcp-all-interfaces.sh: Inspecting interface: ens7f1...Configured ens7f1 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.4984] dhcp4 (eno1): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5001] dhcp4 (eno1): dhclient started with pid 1207 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5017] dhcp4 (eno2): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5031] dhcp4 (eno2): dhclient started with pid 1211 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5046] dhcp4 (ens7f0): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5062] dhcp4 (ens7f0): dhclient started with pid 1216 Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5087] dhcp4 (ens7f1): activation: beginning transaction (timeout in 45 seconds) Nov 24 03:09:40 localhost NetworkManager[654]: <info> [1606205380.5103] dhcp4 (ens7f1): dhclient started with pid 1223 Nov 24 03:09:48 localhost NetworkManager[654]: <info> [1606205388.3010] dhcp4 (eno1): address 192.168.213.144 ``` Eno1 is our interface here. So based on timestamps ironic-python-agent tries to callback server at `2020-11-24 03:09:47.992` and server get IP address from DHCP at `Nov 24 03:09:48`. Simple workaround is to add `ipa-hardware-initialization-delay=10`. TLDR: Ironic node cleanup process hangs randomly. Version-Release number of selected component (if applicable): rhosp-director-images-x86_64-13.0-20200610.2.el7ost.noarch rhosp-director-images-ipa-x86_64-13.0-20200610.2.el7ost.noarch rhosp-director-images-13.0-20200610.2.el7ost.noarch rhosp-director-images-ipa-13.0-20200610.2.el7ost.noarch How reproducible: Block DHCP traffic from node after cleanup starts and observe ironic-python-client logs. Actual results: Node hangs in `cleanup wait` state. Expected results: Node cleanup successfully. Additional info: Its not related to this issue, but it can make debug LONGER. There is bug in python systemd module. Which can hide real problem from you. If you get `TypeError: cannot concatenate 'str' and 'tuple' objects`, it can mean anything. This was fixed 3yrs back https://github.com/systemd/python-systemd/commit/8921c79fb98e5e04c0e2f00813e9d8e015e4206e