Bug 1862105
| Summary: | ironic python client connection error - overcloud deployment failed | ||||||||||||||||
|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|---|
| Product: | Red Hat OpenStack | Reporter: | marcelo.guerrero_viveros | ||||||||||||||
| Component: | openstack-ironic-python-agent | Assignee: | Julia Kreger <jkreger> | ||||||||||||||
| Status: | CLOSED ERRATA | QA Contact: | Alistair Tonner <atonner> | ||||||||||||||
| Severity: | high | Docs Contact: | |||||||||||||||
| Priority: | medium | ||||||||||||||||
| Version: | 13.0 (Queens) | CC: | bartosz, bfournie, dbecker, derli, dtantsur, emacchi, igallagh, jkreger, jmelvin, mburns, morazi, rpittau, slinaber | ||||||||||||||
| Target Milestone: | z13 | Keywords: | Triaged, ZStream | ||||||||||||||
| Target Release: | 13.0 (Queens) | ||||||||||||||||
| Hardware: | Unspecified | ||||||||||||||||
| OS: | Unspecified | ||||||||||||||||
| Whiteboard: | |||||||||||||||||
| Fixed In Version: | openstack-ironic-python-agent-3.2.4-2.el7ost | Doc Type: | Bug Fix | ||||||||||||||
| Doc Text: |
Before this update, initial connection errors with the agent were disrupting the retry logic, which sometimes resulted in the agent failing to communicate with the Ironic services, and logging a misleading TypeError to the agent console.
With this update, the exception handling has been fixed to explicitly handle known possible connection and lookup failure cases, and the logging has been updated to provide clarity on what is happening with the agent. Connections are now retried as designed by the agent and logging should no longer report just a TypeError in the event of an unexpected failure.
|
Story Points: | --- | ||||||||||||||
| Clone Of: | Environment: | ||||||||||||||||
| Last Closed: | 2020-10-28 18:29:43 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: |
|
||||||||||||||||
Please provide sosreports and details on your configuration so we can help debugging it. This is the nic configuration of my compute:
resources:
OsNetConfigImpl:
type: OS::Heat::SoftwareConfig
properties:
group: script
config:
str_replace:
template:
get_file: /usr/share/openstack-tripleo-heat-templates/network/scripts/run-os-net-config.sh
params:
$network_config:
network_config:
- type: interface
name: nic3
mtu: 1450
use_dhcp: false
dns_servers:
get_param: DnsServers
addresses:
- ip_netmask:
list_join:
- /
- - get_param: ControlPlaneIp
- get_param: ControlPlaneSubnetCidr
routes:
- ip_netmask: 169.254.169.254/32
next_hop:
get_param: EC2MetadataIp
- default: true
next_hop:
get_param: ControlPlaneDefaultRoute
- type: ovs_bridge
name: br-tenant
use_dhcp: false
members:
- type: interface
name: nic2
- type: ovs_bridge
name: br-ex
use_dhcp: true
members:
- type: interface
name: nic1
As you can see I have dhcp enabled in nic1 and my provisioning interface is nic3. Undercloud director is 192.168.200.1
I gained access to the IPA on the node and can see the following:
Jul 30 13:18:36 localhost kernel: igb 0000:04:00.0: changing MTU from 1500 to 1550
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3323] device (eno1): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3333] device (eno1): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3335] device (eno1): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3343] manager: NetworkManager state is now CONNECTED_SITE
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3344] policy: set 'System eno1' (eno1) as default for IPv4 routing and DNS
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3345] policy: set-hostname: set hostname to 'ane2e-sriov02-sriov01.an.nuagenetworks.net' (from DHCPv4)
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3349] device (eno1): Activation: successful, device activated.
Jul 30 13:18:36 localhost systemd-hostnamed: Changed host name to 'ane2e-sriov02-sriov01.an.nuagenetworks.net'
Jul 30 13:18:36 localhost NetworkManager[408]: <info> [1596129516.3363] manager: NetworkManager state is now CONNECTED_GLOBAL
Jul 30 13:18:36 localhost nm-dispatcher: req:3 'up' [eno1]: new request (4 scripts)
Jul 30 13:18:36 localhost nm-dispatcher: req:3 'up' [eno1]: start running ordered scripts...
Jul 30 13:18:36 localhost nm-dispatcher: req:4 'connectivity-change': new request (4 scripts)
Jul 30 13:18:36 localhost nm-dispatcher: req:5 'hostname': new request (4 scripts)
Jul 30 13:18:36 localhost dhclient[927]: DHCPDISCOVER on eno3 to 255.255.255.255 port 67 interval 3 (xid=0x7de2d2e8)
Jul 30 13:18:36 localhost systemd: Unit iscsi.service cannot be reloaded because it is inactive.
Jul 30 13:18:36 localhost nm-dispatcher: req:4 'connectivity-change': start running ordered scripts...
Jul 30 13:18:36 localhost nm-dispatcher: req:5 'hostname': start running ordered scripts...
Jul 30 13:18:36 localhost systemd: Started Postfix Mail Transport Agent.
Jul 30 13:18:37 localhost systemd: Started Dynamic System Tuning Daemon.
Jul 30 13:18:37 localhost systemd: Reached target Multi-User System.
Jul 30 13:18:37 localhost systemd: Started Stop Read-Ahead Data Collection 10s After Completed Startup.
Jul 30 13:18:37 localhost systemd: Starting Update UTMP about System Runlevel Changes...
Jul 30 13:18:37 localhost systemd: Started Update UTMP about System Runlevel Changes.
Jul 30 13:18:37 localhost systemd: Startup finished in 6.902s (kernel) + 7.563s (userspace) = 14.465s.
Jul 30 13:18:39 localhost dhclient[927]: DHCPDISCOVER on eno3 to 255.255.255.255 port 67 interval 6 (xid=0x7de2d2e8)
Jul 30 13:18:39 localhost dhclient[927]: DHCPREQUEST on eno3 to 255.255.255.255 port 67 (xid=0x7de2d2e8)
Jul 30 13:18:39 localhost dhclient[927]: DHCPOFFER from 192.168.200.5
Jul 30 13:18:39 localhost dhclient[927]: DHCPACK from 192.168.200.5 (xid=0x7de2d2e8)
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4954] dhcp4 (eno3): address 192.168.200.73
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): plen 24 (255.255.255.0)
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): classless static route 169.254.169.254/32 gw 192.168.200.1
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): gateway 192.168.200.1
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): lease time 86400
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): hostname 'host-192-168-200-73'
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): nameserver '10.20.4.163'
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): domain name 'localdomain'
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.4955] dhcp4 (eno3): state changed unknown -> bound
Jul 30 13:18:39 localhost dhclient[927]: bound to 192.168.200.73 -- renewal in 41970 seconds.
Jul 30 13:18:39 localhost kernel: igb 0000:04:00.2: changing MTU from 1500 to 1400
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.5593] device (eno3): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.5603] device (eno3): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.5606] device (eno3): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Jul 30 13:18:39 localhost NetworkManager[408]: <info> [1596129519.5615] device (eno3): Activation: successful, device activated.
Jul 30 13:18:39 localhost nm-dispatcher: req:6 'up' [eno3]: new request (4 scripts)
Jul 30 13:18:39 localhost nm-dispatcher: req:6 'up' [eno3]: start running ordered scripts...
Jul 30 13:18:39 localhost systemd: Unit iscsi.service cannot be reloaded because it is inactive.
Jul 30 13:18:39 localhost dhclient[899]: DHCPDISCOVER on eno2 to 255.255.255.255 port 67 interval 7 (xid=0x15beea6b)
Jul 30 13:18:40 localhost kernel: igb 0000:04:00.0 eno1: igb: eno1 NIC Link is Up 1000 Mbps Full Duplex, Flow Control: RX/TX
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.2926] device (eno1): carrier: link connected
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.2926] device (eno1): DHCPv4 lease renewal requested
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3007] dhcp4 (eno1): canceled DHCP transaction, DHCP client pid 890
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3007] dhcp4 (eno1): state changed bound -> done
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3010] dhcp4 (eno1): activation: beginning transaction (timeout in 45 seconds)
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3021] dhcp4 (eno1): dhclient started with pid 1339
Jul 30 13:18:40 localhost dhclient[1339]: DHCPREQUEST on eno1 to 255.255.255.255 port 67 (xid=0x33f304ac)
Jul 30 13:18:40 localhost dhclient[1339]: DHCPACK from 10.30.128.1 (xid=0x33f304ac)
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3277] dhcp4 (eno1): address 10.30.136.4
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): plen 20 (255.255.240.0)
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): gateway 10.30.128.1
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): lease time 43200
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): hostname 'ane2e-sriov02-sriov01.an.nuagenetworks.net'
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): nameserver '138.203.221.17'
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): nameserver '138.203.68.53'
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): nameserver '135.239.25.53'
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): domain name 'an.nuagenetworks.net'
Jul 30 13:18:40 localhost NetworkManager[408]: <info> [1596129520.3278] dhcp4 (eno1): state changed unknown -> bound
Jul 30 13:18:40 localhost nm-dispatcher: req:7 'dhcp4-change' [eno1]: new request (4 scripts)
Jul 30 13:18:40 localhost nm-dispatcher: req:7 'dhcp4-change' [eno1]: start running ordered scripts...
Jul 30 13:18:40 localhost dhclient[1339]: bound to 10.30.136.4 -- renewal in 18260 seconds.
Jul 30 13:18:40 localhost kernel: mpt3sas_cm0: port enable: SUCCESS
It seems that eno1 is ready before eno3 (my provisioning interface) and ironic python agent tries to reach 192.168.200.1 before eno3 is ready. Hence, the error with no route to host.
I can continue with the deployment if I restart the IPA on the node with:
sudo systemctl restart ironic-python-agent.service
Is there a way to instruct IPA to wait until eno3 (nic3) is ready?
Thanks
Created attachment 1702979 [details]
logs API compute
Attached complete logs of compute after gaining API access
I thought that by setting dhcp equal to false in the network interface template, nic3 was not going to perform dhcp discovery, but it seems that this is for the overcloud configuration. For the initial boot, where I'm having issues, all interfaces send DHCP requests. Correct? Any ideas? Even with the other interfaces and the delay, IPA should still be working since it is local networking which would still be on the route table even if the default gateway was replaced by another interface. The sequence of events and that you can just restart the agent seems... weird. Any chance I can get the ramdisk messages log file as well as the ironic-python-agent log so I can compare both? Also, when you gained access to the ramdisk, what address did you SSH into? Over the provisioning network or another interface? Thanks in advance, -Julia Correct, all interfaces should be attempting to configure network addresses for the ramdisk. Created attachment 1702986 [details]
ramdisk logs video
This is a video with the ramdisk logs. I got it remotely from the IMPI interface. Don't how where to find it in the compute node
It's difficult to see the error in the video because it happens very fast, but it is the same I sent before as a image. Connection Error address 192.168.200.1 port 6385. No route to host Created attachment 1702988 [details]
API logs when it fails
Created attachment 1702989 [details]
API log after restarting API
I got access via the provisioning network. Sorry for the video, don't know where to get the logs from the compute node. In the director I just see ironic/deploy for the controller host, but none for the computes. Maybe because they get stuck. Oh, awesome, thank you for that video, Hopefully I'll be able to go frame by frame but it looks like it the issue your seeing is something we've started to have reported on supermicro hardware intermittently. If you can try running journalctl --full -b from with-in the ramdisk, the IPA logs should be the journal! I attached the API logs, before and after restarting the API. Or does journalctl --full -b provide with more information? `journalctl --full -b` should return since the system boot. I need that before restart! The video did at least give me a general idea that I'm chasing now but the actual logging from that failure should help tremendously. Thanks in advance, -Julia Created attachment 1702995 [details]
API logs journalctl --full -b
thanks
I've attached the logs. Thanks This latest logs were gotten from a new run. The previous API logs I've already attached them. Please look at the attachments (attachment 1702988 [details] and 1702989)
Okay, I think I see exactly what is occurring. At least, one of the issues, there may be more than one thing going on. I'm going to have to patch it and get another logging patch backported, but in the mean time, try adding "ipa-hardware-initialization-delay=30" to your PXE boot command line. That should get you well past the issue your presently encountering. Please let me know! Thanks, -Julia Yes, it worked. Thanks! This means that nic3 was not ready when IPA was trying to establish the connection? What other issues you think there are? Basically the connection times out as one would expect, and then it fails the entire retry logic path instead of actually, retrying! Thank you so much for posting the video, I honestly would have never figured out what exactly was going on without it. *** Bug 1848101 has been marked as a duplicate of this bug. *** 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 (openstack-ironic bug fix advisory), 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-2020:4394 *** Bug 1901084 has been marked as a duplicate of this bug. *** |
Created attachment 1702954 [details] error Description of problem: Overcloud deployment failed on compute nodes Attached captured screen with error. Ironic python client reports connection error due to missing route to host 192.168.200.1 6385 Deployment with multiple nics and no network isolation Version-Release number of selected component (if applicable): How reproducible: Steps to Reproduce: 1. 2. 3. Actual results: Expected results: Additional info: