Open Stack

 Hi,
I'd very much appreciate some help on this.

We have a medium-large ironic installation where the baremetal nodes are constantly doing provisionings and deprovisionings.Our approach so far is to configure all the baremetal nodes in CSM UEFI mode so that both BIOS and UEFI images can be run.
And things have worked fairly well with this.
Lately, I'm having this weird "Failed to create config drive on disk" issue and it is happening only with BIOS images on certain baremetal nodes.


Here are the important snippets from the ironic conductor and the IPA that I've managed to narrow down.
==================================
Ironic conductor (power-on)
2020-02-18 13:07:18.541 INFO Successfully set node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 power state to power on by rebooting.
020-02-18 13:07:18.560 INFO Node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 moved to provision state "wait call-back" from state "deploying"; target provision state is "active"




==================================
Ironic Python Agent: (I can provide the full log on request. Only relevant logs provided here for the sake of brevity).
wipefs --force --all Feb 18 21:08:17 ironic-python-agent: CMD "wipefs --force --all /dev/sda" returned: 0 in 0.023s 
Feb 18 21:08:17 ironic-python-agentt: Execution completed, command line is "wipefs --force --all /dev/sda" Feb 18 21:08:17 ironic-python-agent: Command stdout is: "" execute /usr/share/ironic-python-agent/venv/lib/python2.7/site-packages/ironic_lib/utils.py:103Feb 18 21:08:17 ironic-python-agent: Command stderr is: "" execute /usr/share/ironic-python-agent/venv/lib/python2.7/site-packages/ironic_lib/utils.py:104
sgdisk -ZFeb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:18.321 15063 DEBUG oslo_concurrency.processutils [-] CMD "sgdisk -Z /dev/sda" returned: 0 in 1.017s 
Feb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:18.323 15063 DEBUG ironic_lib.utils [-] Execution completed, command line is "sgdisk -Z /dev/sda" Feb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:18.323 15063 DEBUG ironic_lib.utils [-] Command stdout is: "Creating new GPT entries in memory.Feb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: GPT data structures destroyed! You may now partition the disk using fdisk or other utilities.
fuser /dev/sda Feb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:18.332 15063 DEBUG oslo_concurrency.processutils [-] CMD "fuser /dev/sda" returned: 0 in 0.006s 
Feb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:18.332 15063 DEBUG ironic_lib.utils [-] Execution completed, command line is "fuser /dev/sda"Feb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:18.332 15063 DEBUG ironic_lib.utils [-] Command stdout is: " 15221" Feb 18 21:08:18 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:18.332 15063 DEBUG ironic_lib.utils [-] Command stderr is: "/dev/sda:
fuser /dev/sdaFeb 18 21:08:19 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:19.336 15063 DEBUG oslo_concurrency.processutils [-] CMD "fuser /dev/sda" returned: 1 in 0.012s 
Feb 18 21:08:19 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:19.336 15063 DEBUG ironic_lib.utils [-] Execution completed, command line is "fuser /dev/sda" Feb 18 21:08:19 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:19.336 15063 INFO ironic_lib.disk_utils [-] Disk metadata on /dev/sda successfully destroyed for node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97

start iscsi:Feb 18 21:08:19 host-10-33-23-71 ironic-python-agent[15063]: 2020-02-18 21:08:19.336 15063 DEBUG ironic_python_agent.extensions.iscsi [-] Starting ISCSI target with iqn iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 on device /dev/sda start_iscsi_targetFeb 18 21:08:19 host-10-33-23-71 kernel: Rounding down aligned max_sectors from 4294967295 to 4294967288Feb 18 21:08:19 host-10-33-23-71 kernel: db_root: cannot open: /etc/targetFeb 18 21:08:19 host-10-33-23-71 WARNING ironic_python_agent.extensions.iscsi [-] Linux-IO is not available, falling back to TGT. Error: Cannot set dbroot to /etc/target. Please check if this directory exists..: RTSLibError: Cannot set dbroot to /etc/target. Please check if this directory exists.Feb 18 21:08:19 host-10-33-23-71 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): tgtd Feb 18 21:08:19 host-10-33-23-71 DEBUG oslo_concurrency.processutils [-] CMD "tgtadm --lld iscsi --mode target --op show" returned: 0 in 0.002s Feb 18 21:08:19 host-10-33-23-71 DEBUG ironic_lib.utils [-] Execution completed, command line is "tgtadm --lld iscsi --mode target --op show" Feb 18 21:08:19 host-10-33-23-71 DEBUG ironic_lib.utils [-] Command stdout is: "" Feb 18 21:08:19 host-10-33-23-71 DEBUG ironic_lib.utils [-] Command stderr is: "" 
Feb 18 21:08:19 host-10-33-23-71 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): tgtadm --lld iscsi --mode target --op new --tid 1 --targetname iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 Feb 18 21:08:19 host-10-33-23-71 DEBUG oslo_concurrency.processutils [-] CMD "tgtadm --lld iscsi --mode target --op new --tid 1 --targetname iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97" returned: 0 in 0.002s Feb 18 21:08:19 host-10-33-23-71 DEBUG ironic_lib.utils [-] Execution completed, command line is "tgtadm --lld iscsi --mode target --op new --tid 1 --targetname iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97" Feb 18 21:08:19 host-10-33-23-71 DEBUG ironic_lib.utils [-] Command stdout is: "" Feb 18 21:08:19 host-10-33-23-71 DEBUG ironic_lib.utils [-] Command stderr is: ""Feb 18 21:08:19 host-10-33-23-71 INFO root [-] Command iscsi.start_iscsi_target completed: Command name: start_iscsi_target, params: {u'wipe_disk_metadata': True, u'iqn': u'iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97', u'portal_port': 3260}, status: SUCCEEDED, result: {'iscsi_target_iqn': u'iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97'}.




====================================Back to Ironic conductor020-02-18 13:08:25.953 346408 DEBUG RPC heartbeat called for node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 heartbeat 2020-02-18 13:08:25.997 346408 DEBUG Heartbeat from node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 heartbeat 2020-02-18 13:08:26.033 346408 Node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 moved to provision state "deploying" from state "wait call-back"; target provision state is "active"


Successful login to iSCSI:
Login to [iface: default, target: iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97, portal: 10.33.23.71,3260] successful.

qemu-img info2020-02-18 13:08:29.072 346408 DEBUG CMD "/usr/bin/python2 -m oslo_concurrency.prlimit --as=1073741824 -- env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/ea6f8eda-402c-4fb0-a2c4-61c83bc73f97/disk" returned: 0 in 0.067s 
2020-02-18 13:08:29.073 346408 DEBUG Execution completed, command line is "env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/ea6f8eda-402c-4fb0-a2c4-61c83bc73f97/disk" 2020-02-18 13:08:29.074 346408 DEBUG Command stdout is: "image: /var/lib/ironic/images/ea6f8eda-402c-4fb0-a2c4-61c83bc73f97/diskfile format: rawvirtual size: 9.8G (10485760000 bytes)disk size: 5.4G

copying image via dd: 2020-02-18 13:08:49.020 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf 
 dd if=/var/lib/ironic/images/ea6f8eda-402c-4fb0-a2c4-61c83bc73f97/disk of=/dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 bs=1M oflag=direct" returned: 0 in 19.945s 2020-02-18 13:08:49.021 346408 DEBUG Execution completed, command line is "dd if=/var/lib/ironic/images/ea6f8eda-402c-4fb0-a2c4-61c83bc73f97/disk of=/dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 bs=1M oflag=direct" 2020-02-18 13:08:49.022 346408 DEBUG Command stdout is: "" execute /usr/lib/python2.7/site-packages/ironic_lib/utils.py:1032020-02-18 13:08:49.022 346408 DEBUG Command stderr is: "10000+0 records in 10000+0 records out 10485760000 bytes (10 GB) copied, 19.7712 s, 530 MB/s

partprobe2020-02-18 13:09:03.341 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf 
 partprobe /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 14.318s 2020-02-18 13:09:03.341 346408 DEBUG Execution completed, command line is "partprobe /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" 2020-02-18 13:09:03.342 346408 DEBUG Command stdout is: "" 2020-02-18 13:09:03.342 346408 DEBUG Command stderr is: "" 

lsblk:2020-02-18 13:09:03.519 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf 
 lsblk -Po name,label /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 0.176s 2020-02-18 13:09:03.519 346408 DEBUG Execution completed, command line is "lsblk -Po name,label /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" 2020-02-18 13:09:03.519 346408 DEBUG Command stdout is: "NAME="sdb" LABEL="" NAME="sdb1" LABEL="" " execute /usr/lib/python2.7/site-packages/ironic_lib/utils.py:1032020-02-18 13:09:03.520 346408 DEBUG iCommand stderr is: ""

 Adding configDrive partition:2020-02-18 13:09:03.772 346408 DEBUG Adding config drive partition 64 MiB to device: /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 for node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 create_config_drive_partition 
blkid2020-02-18 13:09:03.959 346408 CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -p -o value -s PTTYPE /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 0.186s 
2020-02-18 13:09:03.960 346408 Execution completed, command line is "blkid -p -o value -s PTTYPE /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" 2020-02-18 13:09:03.960 346408 Command stdout is: "dos2020-02-18 13:09:03.960 346408 Command stderr is: "" 


parted2020-02-18 13:09:03.961 346408 DEBUG Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf  parted -s -m /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 unit MiB print execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:3722020-02-18 13:09:04.136 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf parted -s -m /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 unit MiB print" returned: 0 in 0.175s 2020-02-18 13:09:04.137 346408 DEBUG Execution completed, command line is "parted -s -m /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 unit MiB print" 2020-02-18 13:09:04.137 346408 DEBUG Command stdout is: "BYT;/dev/sdb:953870MiB:scsi:512:512:msdos:IET VIRTUAL-DISK:;1:1.00MiB:9999MiB:9998MiB:ext4::boot;

blkid2020-02-18 13:09:04.321 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -p -o value -s PTTYPE /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 0.182s 
2020-02-18 13:09:04.321 346408 DEBUG Execution completed, command line is "blkid -p -o value -s PTTYPE /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" 2020-02-18 13:09:04.321 346408 DEBUG ironic_lib.utils [req-34f931af-69e5-4ff4-b37b-6b6df8d7f560 - - - - -] Command stdout is: "dos2020-02-18 13:09:04.322 346408 DEBUG ironic_lib.utils [req-34f931af-69e5-4ff4-b37b-6b6df8d7f560 - - - - -] Command stderr is: "" 

partprobe2020-02-18 13:09:04.510 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf 
 partprobe -d -s /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 0.188s 2020-02-18 13:09:04.511 346408 DEBUG Execution completed, command line is "partprobe -d -s /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" 2020-02-18 13:09:04.512 346408 DEBUG Command stdout is: "/dev/sdb: msdos partitions 1 " 2020-02-18 13:09:04.512 346408 DEBUG Command stderr is: "" 



blockdev --getsize642020-02-18 13:09:05.045 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf blockdev --getsize64 /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 0.532s 
2020-02-18 13:09:05.046 346408 DEBUG Execution completed, command line is "blockdev --getsize64 /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" 2020-02-18 13:09:05.046 346408 DEBUG Command stdout is: "1000204886016" 2020-02-18 13:09:05.046 346408 DEBUG Command stderr is: "" 

parted/mkpart2020-02-18 13:09:05.241 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf 
 parted -a optimal -s -- /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 mkpart primary fat32 -64MiB -0" returned: 0 in 0.194s 2020-02-18 13:09:05.241 346408 DEBUG Execution completed, command line is "parted -a optimal -s -- /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 mkpart primary fat32 -64MiB -0" 2020-02-18 13:09:05.242 346408 DEBUG Command stdout is: "" 2020-02-18 13:09:05.242 346408 DEBUG Command stderr is: "Warning: The resulting partition is not properly aligned for best performance.

partprobe2020-02-18 13:09:05.516 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf partprobe /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 0.187s
2020-02-18 13:09:05.517 346408 DEBUG Execution completed, command line is "partprobe /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" 2020-02-18 13:09:05.517 346408 DEBUG Command stdout is: "" 2020-02-18 13:09:05.518 346408 DEBUG Command stderr is: "" 

sgdisk -v:   IS THERE ANY ISSUE WITH THE BELOW OUTPUT2020-02-18 13:09:05.707 346408 CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf sgdisk -v /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" returned: 0 in 0.189s 
2020-02-18 13:09:05.708 346408 Execution completed, command line is  "sgdisk -v /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1" execute /usr/lib/python2.7/site-packages/ironic_lib/utils.py:101
2020-02-18 13:09:05.708 346408 DEBUG ironic_lib.utils [req-34f931af-69e5-4ff4-b37b-6b6df8d7f560 - - - - -] Command stdout is: "***************************************************************Found invalid GPT and valid MBR; converting MBR to GPT formatin memory.***************************************************************Warning! Secondary partition table overlaps the last partition by33 blocks!You will need to delete this partition or resize it in another utility.Warning! Secondary partition table overlaps the last partition by33 blocks!You will need to delete this partition or resize it in another utility.Identified 1 problems!
2020-02-18 13:09:05.709 346408 DEBUG ironic_lib.utils [req-34f931af-69e5-4ff4-b37b-6b6df8d7f560 - - - - -] Command stderr is: "" 


parted2020-02-18 13:09:05.899 346408 DEBUG CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf 
 parted -s -m /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 unit MiB print" returned: 0 in 0.189s 2020-02-18 13:09:05.899 346408 DEBUG Execution completed, command line is "parted -s -m /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1 unit MiB print" 2020-02-18 13:09:05.900 346408 DEBUG Command stdout is: "BYT;/dev/sdb:953870MiB:scsi:512:512:msdos:IET VIRTUAL-DISK:;1:1.00MiB:9999MiB:9998MiB:ext4::boot;2:953806MiB:953870MiB:64.0MiB:::lba;" execute /usr/lib/python2.7/site-packages/ironic_lib/utils.py:1032020-02-18 13:09:05.900 346408 DEBUG ironic_lib.utils [req-34f931af-69e5-4ff4-b37b-6b6df8d7f560 - - - - -] Command stderr is: "" 


2020-02-18 13:09:05.927 346408 DEBUG Waiting for the config drive partition /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1-part2 on node ea6f8eda-402c-4fb0-a2c4-61c83bc73f97 to be ready for writing. create_config_drive_partition /usr/lib/python2.7/site-packages/ironic_lib/disk_utils.py:8692020-02-18 13:09:05.927 346408 DEBUG oslo_concurrency.processutils [req-34f931af-69e5-4ff4-b37b-6b6df8d7f560 - - - - -] Running cmd (subprocess): test -e /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1-part2 execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:3722020-02-18 13:09:05.945 346408 DEBUG oslo_concurrency.processutils [req-34f931af-69e5-4ff4-b37b-6b6df8d7f560 - - - - -] u'test -e /dev/disk/by-path/ip-10.33.23.71:3260-iscsi-iqn.2008-10.org.openstack:ea6f8eda-402c-4fb0-a2c4-61c83bc73f97-lun-1-part2' failed. Retrying. execute /usr/lib/python2.7/site-packages/oslo_concurrency/processutils.py:461
The code retries several times followed by the config drive failure error.Again, this happens on a few nodes only and happens only when I try to run BIOS based images.  UEFI based images provision just fine.
Any help will be appreciated.thanks,Fred.




  
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack-discuss/attachments/20200219/607b5a1d/attachment-0001.html>