Bug 1468293 - Very often, PXE boot will fail getting inspector.ipxe and reseting the node will make it work
Very often, PXE boot will fail getting inspector.ipxe and reseting the node w...
Status: NEW
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-tripleo (Show other bugs)
10.0 (Newton)
Unspecified Unspecified
unspecified Severity unspecified
: ---
: ---
Assigned To: James Slagle
Arik Chernetsky
: ZStream
: 1455490 (view as bug list)
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2017-07-06 11:17 EDT by David Hill
Modified: 2017-08-30 11:15 EDT (History)
6 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed:
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
sosreport (15.10 MB, application/x-xz)
2017-08-05 14:21 EDT, David Hill
no flags Details
tcpdump (73.49 KB, application/octet-stream)
2017-08-05 14:22 EDT, David Hill
no flags Details
console showing failed dhcp (169.41 KB, image/png)
2017-08-05 14:23 EDT, David Hill
no flags Details

  None (edit)
Description David Hill 2017-07-06 11:17:07 EDT
Description of problem:
Very often, PXE boot will fail on introspection and reseting the node will make it work

Version-Release number of selected component (if applicable):


How reproducible:
Often

Steps to Reproduce:
1. Spawn an undercloud in KVM
2. Create 7 nodes (3 ceph, 3 controllers and 1 compute)
3. Start introspection

Actual results:
Introspection times-out because overcloud nodes failed to find the PXE image

Expected results:
Succeeds

Additional info:
This happens on RHOSP 10 more than any other RHOSP releases .  RHOSP 7, 8, 9 and 11 are working almost everytime.  This looks like a race condition.
Comment 1 Bob Fournier 2017-08-04 16:34:33 EDT
David - do you have any logs when tis occurs (sosreports, undercloud /var/logs, ramdisk etc,)?  Thanks.
Comment 2 David Hill 2017-08-04 18:36:46 EDT
I'm reproducing this very easily myself.   I'm not sure if it's because the ramdisk is not yet available through ironic/dnsmasq/http/etc and the overcloud node can't get an IP and image.  Resetting it always works and when it fails, it's usually 3 hosts that fail getting the IP.   I can indeed get logs but since the problem is with the node not getting an IP / image, I doubt it'll show in the logs and the only thing we see on the console is that it failed getting an IP (timed out).
Comment 3 Bob Fournier 2017-08-04 19:55:21 EDT
OK thanks.  If its a problem getting an IP it may be useful to have a tcpdump of DHCP traffic.  

If there are any ramdisk logs they would be in /var/log/ironic/deploy, can you check if anything has gotten logged there?

Also, you don't happen to have another DHCP server in the your network that could be interfering?
Comment 4 David Hill 2017-08-05 09:41:19 EDT
The undercloud is running on KVM and all the overcloud nodes are also running in KVM in the same bridge and there're no other DHCP servers.   I'll do a tcpdump next time I try a deployment that I know is failing often.
Comment 5 David Hill 2017-08-05 12:22:01 EDT
Also, I never have issues deploying the overcloud... only introspection will display this behavior...
Comment 6 Bob Fournier 2017-08-05 13:03:47 EDT
Thanks David.  It would also be useful to check if there are any iptables issues.  The overcloud dhcp server uses a different interface in the qdhcp namespace.
Comment 7 David Hill 2017-08-05 14:20:51 EDT
I can really reproduce this intermittently with almost all OSP releases but with RHOSP 7 and 8, I'm barely able to reproduce it.   I'm attaching sosreports from the undercloud, tcpdump.pcap and a screenshot.  I really doubt the issue is with iptables.
Comment 8 David Hill 2017-08-05 14:21 EDT
Created attachment 1309477 [details]
sosreport
Comment 9 David Hill 2017-08-05 14:22 EDT
Created attachment 1309478 [details]
tcpdump
Comment 10 David Hill 2017-08-05 14:23 EDT
Created attachment 1309479 [details]
console showing failed dhcp
Comment 11 David Hill 2017-08-05 14:37:33 EDT
[ "52:54:00:7C:35:0B" ] this is the mac that didn't introspect this time.
Comment 12 David Hill 2017-08-05 14:45:58 EDT
I took the pcap on the undercloud node and we can see the request is coming by but nothing returns an OFFER.
Comment 13 David Hill 2017-08-05 14:49:48 EDT
In fact, I'm wondering if the problem is not the PXE server that doesn't reply fast enough?    I'm looking at my tcpdumps and it seems like the DHCP server returned 

    192.0.2.1.bootps > 192.0.2.103.bootpc: [udp sum ok] BOOTP/DHCP, Reply, length 325, xid 0x6c8ac168, secs 4, Flags [none] (0x0000)
          Your-IP 192.0.2.103
          Server-IP 192.0.2.1
          Client-Ethernet-Address 52:54:00:7c:35:0b (oui Unknown)
          Vendor-rfc1048 Extensions
            Magic Cookie 0x63825363
            DHCP-Message Option 53, length 1: Offer
            Server-ID Option 54, length 4: 192.0.2.1
            Lease-Time Option 51, length 4: 120
            BF Option 67, length 37: "http://192.0.2.1:8088/inspector.ipxe^@"
            RN Option 58, length 4: 60
            RB Option 59, length 4: 105
            Subnet-Mask Option 1, length 4: 255.255.255.0
            BR Option 28, length 4: 192.0.2.255
            Default-Gateway Option 3, length 4: 192.0.2.1
            END Option 255, length 0
Comment 14 David Hill 2017-08-05 17:21:07 EDT
I have added a 60s delay in my script before the openstack node configure and the introspection and I've had a successful introspection ... I'll try to repeat this.
Comment 15 Bob Fournier 2017-08-05 18:40:34 EDT
Hi David, thanks for the logs and trace.  Looking through the trace I do see a complete DHCP sequence for 52:54:00:7c:35:0b. As you've noted in comment 13, its offered 192.0.2.103 at packet 52 and given boot file http://192.0.2.1:8088/inspector.pxe, I see the client DHCP Request and server Ack after that.  I'm wondering if its an issue pulling down the field via http and not with the DHCP address.

Interesting that the delay has helped, let me know if that is consistent.

The help page for the error code shown on the console is: http://ipxe.org/err/040ee119
Comment 16 Bob Fournier 2017-08-05 20:45:18 EDT
The dnsmasq logs for this mac also look good, its still not clear why the node isn't using this address.  

messages:Aug  5 14:00:27 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPDISCOVER(br-ctlplane) 52:54:00:7c:35:0b
messages:Aug  5 14:00:27 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPOFFER(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:30 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPDISCOVER(br-ctlplane) 52:54:00:7c:35:0b
messages:Aug  5 14:00:30 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPOFFER(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:36 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPDISCOVER(br-ctlplane) 52:54:00:7c:35:0b
messages:Aug  5 14:00:36 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPOFFER(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPREQUEST(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPACK(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPREQUEST(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPACK(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPREQUEST(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPACK(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPREQUEST(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPACK(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPREQUEST(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
messages:Aug  5 14:00:39 undercloud-0-ocata dnsmasq-dhcp[16514]: DHCPACK(br-ctlplane) 192.0.2.103 52:54:00:7c:35:0b
Comment 17 David Hill 2017-08-07 14:47:49 EDT
I just reproduced it once again with RHOSP 10 ...
Comment 18 Bob Fournier 2017-08-07 15:16:58 EDT
David - did the delay in the script help at all?  Also, is it same symptoms - /var/log/messages shows complete DHCP transaction but node console shows error with http://ipxe.org/err/040ee119?

Thanks.
Comment 19 David Hill 2017-08-11 12:53:30 EDT
Nope I don't think it helped because I hit that issue again some builds laters.   I've also looked at the MAC to make sure they were no dupes:

      1 ceph-0-rhosp10.xml:      <mac address='52:54:00:25:8b:ec'/>
      1 ceph-0-rhosp10.xml:      <mac address='52:54:00:ef:7e:d1'/>
      1 ceph-1-rhosp10.xml:      <mac address='52:54:00:87:a0:b3'/>
      1 ceph-1-rhosp10.xml:      <mac address='52:54:00:ed:4f:2b'/>
      1 ceph-2-rhosp10.xml:      <mac address='52:54:00:cf:e4:8d'/>
      1 ceph-2-rhosp10.xml:      <mac address='52:54:00:f9:fd:34'/>
      1 compute-0-rhosp10.xml:      <mac address='52:54:00:0a:d1:af'/>
      1 compute-0-rhosp10.xml:      <mac address='52:54:00:7c:59:65'/>
      1 control-0-rhosp10.xml:      <mac address='52:54:00:b9:40:f9'/>
      1 control-0-rhosp10.xml:      <mac address='52:54:00:ef:a3:6e'/>
      1 control-1-rhosp10.xml:      <mac address='52:54:00:7c:c3:1a'/>
      1 control-1-rhosp10.xml:      <mac address='52:54:00:fd:a5:45'/>
      1 control-2-rhosp10.xml:      <mac address='52:54:00:a3:93:fd'/>
      1 control-2-rhosp10.xml:      <mac address='52:54:00:ee:f9:63'/>
      1 control-3-rhosp10.xml:      <mac address='52:54:00:43:f9:a1'/>
      1 control-3-rhosp10.xml:      <mac address='52:54:00:65:14:23'/>
      1 control-4-rhosp10.xml:      <mac address='52:54:00:1c:05:56'/>
      1 control-4-rhosp10.xml:      <mac address='52:54:00:8e:79:8e'/>
      1 undercloud-0-rhosp10.xml:      <mac address='52:54:00:53:23:d8'/>
      1 undercloud-0-rhosp10.xml:      <mac address='52:54:00:fd:5f:b1'/>
Comment 20 Bob Fournier 2017-08-11 13:03:53 EDT
Thanks David.  As you mentioned on irc, these macs get generated randomly and I don't see the one that failed - 52:54:00:7c:35:0b - in that list.  Can a mac end up being "reused" when you rerun introspection?
Comment 21 David Hill 2017-08-11 13:06:56 EDT
Each time I'm deploying, I'm generating a new set of macs ...   I've increased the introspection range to 50 IPs instead of 20 ... just in case but it should be fine.   Each of my nodes have 2 NICs so I think at some point, it'll do a DHCP request on all the interfaces and this might be something as simple as that.   Since the previous introspection was much slower , I never hit this issue but now that we almost do it in parallel, maybe I'm hitting something weird ...  I'm kind of out of ideas here so I'll try just anything .
Comment 22 Bob Fournier 2017-08-11 14:28:09 EDT
Yeah, it looks like the dhcp addressing is OK as the logs show 192.0.2.103 being used for this mac which is within range. I'm just wondering if you need to increase the randomness of the macs you are generating, perhaps by using the 3rd octet also in the generation, i.e. 52:54:xx:xx:xx:xx.
Comment 23 David Hill 2017-08-11 14:58:22 EDT
If they're not duplicated, it should be fine no?
Comment 24 Bob Fournier 2017-08-11 15:22:30 EDT
> If they're not duplicated, it should be fine no?

Yes, as long as they are not duplicated from a previous run and mapped to a different node.  I see no evidence of that in the sosreport however.  It still looks like a successful dhcp sequence and failure or no attempt in downloading inspector.ipxe
Comment 25 David Hill 2017-08-11 16:50:09 EDT
That's my guts feeling.
Comment 26 Bob Fournier 2017-08-24 14:16:36 EDT
David - one thing worth trying is to set and entry in /etc/hosts for the
undercloud ctrlplane IP, i.e.
192.0.2.1  local_ip

We've seen problems with reverse DNS issues during introspection causing timeouts and as this appears to be an http issue its worth trying. Adding that entry fixes the reverse DNS problem.

Its also a good idea to not use the 192.0.2.1/24 address space as its a non-routable CIDR reserved for documentation per RFC5737.  Instead use 192.168.24.0/24 as we've done elsewhere in Openstack.

See also https://bugzilla.redhat.com/show_bug.cgi?id=1449841
Comment 27 Bob Fournier 2017-08-24 17:49:24 EDT
David, this bug - https://bugzilla.redhat.com/show_bug.cgi?id=1353464 seems to be what you are hitting.  Can you take a look at the workaround proposed?
Comment 28 David Hill 2017-08-24 18:00:06 EDT
I've tried the local_ip thing and it "worked" this time... I'll have to retry it more than one time though as this might be the time it worked ...
Comment 29 David Hill 2017-08-24 18:01:45 EDT
I don't think I'm hitting that bug you just listed but if I hit this again after adding the /etc/hosts entry, I'll try it ... it's free to try right?
Comment 30 David Hill 2017-08-25 13:01:55 EDT
One other thing is that I don't know if this setting change will have an effect on introspection?  I never had issues deploying nodes but always at introspection time.    The hosts trick didn't solve my issue.   I'm now testing the workaround in the BZ you mentionned above but I have the feeling it'll still fail .
Comment 31 David Hill 2017-08-25 14:46:20 EDT
Introspection failed.
Comment 32 Bob Fournier 2017-08-30 10:51:12 EDT
*** Bug 1455490 has been marked as a duplicate of this bug. ***

Note You need to log in before you can comment on or make changes to this bug.