Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.

Bug 1978343

Summary: Overcloud deployment for partition image with uefi boot mode failed
Product: Red Hat OpenStack Reporter: Julia Kreger <jkreger>
Component: openstack-ironic-python-agentAssignee: Julia Kreger <jkreger>
Status: CLOSED ERRATA QA Contact: Paras Babbar <pbabbar>
Severity: urgent Docs Contact:
Priority: urgent    
Version: 16.1 (Train)CC: jkreger, pbabbar, pweeks, racedoro, sbaker, spower
Target Milestone: z7Keywords: Regression, Triaged
Target Release: 16.1 (Train on RHEL 8.2)   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: openstack-ironic-python-agent-5.0.4-1.20210707193303.9920532.el8ost Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1977417 Environment:
Last Closed: 2021-12-09 20:20:10 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 1977417    
Bug Blocks:    

Description Julia Kreger 2021-07-01 15:37:45 UTC 
+++ This bug was initially created as a clone of Bug #1977417 +++

Description of problem:

There has been regression job failing at the ovewrcloud deployment for UEFI boot partition images


iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3. Attempt 1 out of 3. Error: [Errno 2] No such file or directory: '/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3' is_block_device /usr/lib/python3.6/site-packages/ironic_lib/disk_utils.py:373
2021-06-24 11:46:14.759 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf mkfs -t vfat -n efi-part /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part1" returned: 0 in 0.378s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:14.759 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "mkfs -t vfat -n efi-part /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part1" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:14.759 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "mkfs.fat 4.1 (2017-01-24)
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:14.760 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "mkfs.fat: warning - lowercase labels might not work properly with DOS or Windows
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:14.760 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Starting dd process. dd /usr/lib/python3.6/site-packages/ironic_lib/utils.py:166
2021-06-24 11:46:14.761 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/tmp/configdrived8lv7rs6 of=/dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part2 bs=1M oflag=direct execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:15.038 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/tmp/configdrived8lv7rs6 of=/dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part2 bs=1M oflag=direct" returned: 0 in 0.277s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:15.039 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "dd if=/tmp/configdrived8lv7rs6 of=/dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part2 bs=1M oflag=direct" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:15.039 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:15.040 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "0+1 records in
0+1 records out
548864 bytes (549 kB, 536 KiB) copied, 0.00883609 s, 62.1 MB/s
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:15.040 7 INFO ironic_lib.disk_utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Configdrive for node 35eae434-6f4f-456c-8d17-b70364ea74a5 successfully copied onto partition /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part2
2021-06-24 11:46:15.040 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Running cmd (subprocess): /usr/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 -- env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/35eae434-6f4f-456c-8d17-b70364ea74a5/disk execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:15.117 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "/usr/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 -- env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/35eae434-6f4f-456c-8d17-b70364ea74a5/disk" returned: 0 in 0.077s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:15.118 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/35eae434-6f4f-456c-8d17-b70364ea74a5/disk" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:15.118 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "image: /var/lib/ironic/images/35eae434-6f4f-456c-8d17-b70364ea74a5/disk
file format: raw
virtual size: 4.03 GiB (4331012096 bytes)
disk size: 2.67 GiB
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:15.119 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:15.119 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Starting dd process. dd /usr/lib/python3.6/site-packages/ironic_lib/utils.py:166
2021-06-24 11:46:15.119 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/var/lib/ironic/images/35eae434-6f4f-456c-8d17-b70364ea74a5/disk of=/dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part3 bs=1M oflag=direct execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:15.576 7 DEBUG ironic_lib.disk_utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Checking for swap device (None) on node e8b3117e-73c0-4542-9eb5-189a0ff8b380. work_on_disk /usr/lib/python3.6/site-packages/ironic_lib/disk_utils.py:685
2021-06-24 11:46:15.577 7 DEBUG ironic_lib.disk_utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Checking for ephemeral device (None) on node e8b3117e-73c0-4542-9eb5-189a0ff8b380. work_on_disk /usr/lib/python3.6/site-packages/ironic_lib/disk_utils.py:685
2021-06-24 11:46:15.577 7 DEBUG ironic_lib.disk_utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Checking for configdrive device (/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part2) on node e8b3117e-73c0-4542-9eb5-189a0ff8b380. work_on_disk /usr/lib/python3.6/site-packages/ironic_lib/disk_utils.py:685
2021-06-24 11:46:15.577 7 DEBUG ironic_lib.disk_utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Checking for efi system partition device (/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part1) on node e8b3117e-73c0-4542-9eb5-189a0ff8b380. work_on_disk /usr/lib/python3.6/site-packages/ironic_lib/disk_utils.py:685
2021-06-24 11:46:15.578 7 DEBUG ironic_lib.disk_utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Checking for PReP Boot partition device (None) on node e8b3117e-73c0-4542-9eb5-189a0ff8b380. work_on_disk /usr/lib/python3.6/site-packages/ironic_lib/disk_utils.py:685
2021-06-24 11:46:15.578 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf mkfs -t vfat -n efi-part /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part1 execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:15.918 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf mkfs -t vfat -n efi-part /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part1" returned: 0 in 0.340s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:15.919 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "mkfs -t vfat -n efi-part /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part1" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:15.919 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "mkfs.fat 4.1 (2017-01-24)
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:15.920 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "mkfs.fat: warning - lowercase labels might not work properly with DOS or Windows
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:15.920 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Starting dd process. dd /usr/lib/python3.6/site-packages/ironic_lib/utils.py:166
2021-06-24 11:46:15.921 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/tmp/configdriveioo77ggz of=/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part2 bs=1M oflag=direct execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:16.273 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/tmp/configdriveioo77ggz of=/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part2 bs=1M oflag=direct" returned: 0 in 0.352s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:16.274 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "dd if=/tmp/configdriveioo77ggz of=/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part2 bs=1M oflag=direct" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:16.274 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:16.274 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "0+1 records in
0+1 records out
548864 bytes (549 kB, 536 KiB) copied, 0.0056366 s, 97.4 MB/s
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:16.275 7 INFO ironic_lib.disk_utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Configdrive for node e8b3117e-73c0-4542-9eb5-189a0ff8b380 successfully copied onto partition /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part2
2021-06-24 11:46:16.275 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): /usr/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 -- env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/e8b3117e-73c0-4542-9eb5-189a0ff8b380/disk execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:16.346 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "/usr/bin/python3 -m oslo_concurrency.prlimit --as=1073741824 -- env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/e8b3117e-73c0-4542-9eb5-189a0ff8b380/disk" returned: 0 in 0.071s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:16.348 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "env LC_ALL=C LANG=C qemu-img info /var/lib/ironic/images/e8b3117e-73c0-4542-9eb5-189a0ff8b380/disk" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:16.348 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "image: /var/lib/ironic/images/e8b3117e-73c0-4542-9eb5-189a0ff8b380/disk
file format: raw
virtual size: 4.03 GiB (4331012096 bytes)
disk size: 2.67 GiB
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:16.348 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:16.349 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Starting dd process. dd /usr/lib/python3.6/site-packages/ironic_lib/utils.py:166
2021-06-24 11:46:16.349 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/var/lib/ironic/images/e8b3117e-73c0-4542-9eb5-189a0ff8b380/disk of=/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3 bs=1M oflag=direct execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:18.525 7 DEBUG oslo_concurrency.processutils [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Running cmd (subprocess): ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6232 -U admin -R 1 -N 5 -f /tmp/tmp5va7_u8k power on execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:18.544 7 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6234 -U admin -R 1 -N 5 -f /tmp/tmplszosod1 power status execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:18.911 7 DEBUG oslo_concurrency.processutils [-] CMD "ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6234 -U admin -R 1 -N 5 -f /tmp/tmplszosod1 power status" returned: 0 in 0.367s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:18.912 7 DEBUG ironic.common.utils [-] Execution completed, command line is "ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6234 -U admin -R 1 -N 5 -f /tmp/tmplszosod1 power status" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:77
2021-06-24 11:46:18.913 7 DEBUG ironic.common.utils [-] Command stdout is: "Chassis Power is on
" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:78
2021-06-24 11:46:18.913 7 DEBUG ironic.common.utils [-] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:79
2021-06-24 11:46:18.951 7 WARNING ironic.common.nova [req-6cb487e6-4999-4244-b49b-6d0d3d27ce12 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Could not connect to Nova to send a power notification, please check configuration. An auth plugin is required to determine endpoint URL: keystoneauth1.exceptions.auth_plugins.MissingAuthPlugin: An auth plugin is required to determine endpoint URL
2021-06-24 11:46:18.952 7 INFO ironic.conductor.utils [req-6cb487e6-4999-4244-b49b-6d0d3d27ce12 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Successfully set node f3a2c8bb-3772-43af-986f-0338c9877695 power state to power on by rebooting.
2021-06-24 11:46:18.990 7 INFO ironic.conductor.manager [req-6cb487e6-4999-4244-b49b-6d0d3d27ce12 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Deploy step {'step': 'deploy', 'priority': 100, 'argsinfo': None, 'interface': 'deploy'} on node f3a2c8bb-3772-43af-986f-0338c9877695 being executed asynchronously, waiting for driver.
2021-06-24 11:46:18.990 7 DEBUG ironic.common.states [req-6cb487e6-4999-4244-b49b-6d0d3d27ce12 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Exiting old state 'deploying' in response to event 'wait' on_exit /usr/lib/python3.6/site-packages/ironic/common/states.py:294
2021-06-24 11:46:18.991 7 DEBUG ironic.common.states [req-6cb487e6-4999-4244-b49b-6d0d3d27ce12 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Entering new state 'wait call-back' in response to event 'wait' on_enter /usr/lib/python3.6/site-packages/ironic/common/states.py:300
2021-06-24 11:46:19.013 7 INFO ironic.conductor.task_manager [req-6cb487e6-4999-4244-b49b-6d0d3d27ce12 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Node f3a2c8bb-3772-43af-986f-0338c9877695 moved to provision state "wait call-back" from state "deploying"; target provision state is "active"
2021-06-24 11:46:19.021 7 DEBUG ironic.conductor.task_manager [req-6cb487e6-4999-4244-b49b-6d0d3d27ce12 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Successfully released exclusive lock for node deployment on node f3a2c8bb-3772-43af-986f-0338c9877695 (lock was held 37.03 sec) release_resources /usr/lib/python3.6/site-packages/ironic/conductor/task_manager.py:418
2021-06-24 11:46:19.600 7 DEBUG oslo_concurrency.processutils [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] CMD "ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6232 -U admin -R 1 -N 5 -f /tmp/tmp5va7_u8k power on" returned: 0 in 1.075s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:19.601 7 DEBUG ironic.common.utils [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Execution completed, command line is "ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6232 -U admin -R 1 -N 5 -f /tmp/tmp5va7_u8k power on" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:77
2021-06-24 11:46:19.601 7 DEBUG ironic.common.utils [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Command stdout is: "Chassis Power Control: Up/On
" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:78
2021-06-24 11:46:19.601 7 DEBUG ironic.common.utils [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:79
2021-06-24 11:46:24.603 7 DEBUG oslo_concurrency.processutils [-] Running cmd (subprocess): ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6232 -U admin -R 1 -N 5 -f /tmp/tmp696jluy5 power status execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:24.979 7 DEBUG oslo_concurrency.processutils [-] CMD "ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6232 -U admin -R 1 -N 5 -f /tmp/tmp696jluy5 power status" returned: 0 in 0.376s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:24.980 7 DEBUG ironic.common.utils [-] Execution completed, command line is "ipmitool -I lanplus -H 172.16.0.25 -L ADMINISTRATOR -p 6232 -U admin -R 1 -N 5 -f /tmp/tmp696jluy5 power status" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:77
2021-06-24 11:46:24.980 7 DEBUG ironic.common.utils [-] Command stdout is: "Chassis Power is on
" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:78
2021-06-24 11:46:24.980 7 DEBUG ironic.common.utils [-] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:79
2021-06-24 11:46:25.033 7 WARNING ironic.common.nova [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Could not connect to Nova to send a power notification, please check configuration. An auth plugin is required to determine endpoint URL: keystoneauth1.exceptions.auth_plugins.MissingAuthPlugin: An auth plugin is required to determine endpoint URL
2021-06-24 11:46:25.035 7 INFO ironic.conductor.utils [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Successfully set node b973205f-1ba4-41f3-891b-926cb14deba9 power state to power on by rebooting.
2021-06-24 11:46:25.072 7 INFO ironic.conductor.manager [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Deploy step {'step': 'deploy', 'priority': 100, 'argsinfo': None, 'interface': 'deploy'} on node b973205f-1ba4-41f3-891b-926cb14deba9 being executed asynchronously, waiting for driver.
2021-06-24 11:46:25.072 7 DEBUG ironic.common.states [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Exiting old state 'deploying' in response to event 'wait' on_exit /usr/lib/python3.6/site-packages/ironic/common/states.py:294
2021-06-24 11:46:25.073 7 DEBUG ironic.common.states [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Entering new state 'wait call-back' in response to event 'wait' on_enter /usr/lib/python3.6/site-packages/ironic/common/states.py:300
2021-06-24 11:46:25.094 7 INFO ironic.conductor.task_manager [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Node b973205f-1ba4-41f3-891b-926cb14deba9 moved to provision state "wait call-back" from state "deploying"; target provision state is "active"
2021-06-24 11:46:25.101 7 DEBUG ironic.conductor.task_manager [req-a56b4888-21f8-468b-9575-fc32d4e0b3bc 22768a7f421a410bb4e95f2b2e7d7225 547b256b9c23407aae72649e62070d01 - default default] Successfully released exclusive lock for node deployment on node b973205f-1ba4-41f3-891b-926cb14deba9 (lock was held 40.25 sec) release_resources /usr/lib/python3.6/site-packages/ironic/conductor/task_manager.py:418
2021-06-24 11:46:35.744 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/var/lib/ironic/images/35eae434-6f4f-456c-8d17-b70364ea74a5/disk of=/dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part3 bs=1M oflag=direct" returned: 0 in 20.625s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:35.745 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "dd if=/var/lib/ironic/images/35eae434-6f4f-456c-8d17-b70364ea74a5/disk of=/dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part3 bs=1M oflag=direct" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:35.745 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:35.746 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "4130+1 records in
4130+1 records out
4331012096 bytes (4.3 GB, 4.0 GiB) copied, 20.3845 s, 212 MB/s
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:35.746 7 INFO ironic_lib.disk_utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Image for 35eae434-6f4f-456c-8d17-b70364ea74a5 successfully populated
2021-06-24 11:46:35.746 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part3 execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:36.244 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part3" returned: 0 in 0.498s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:36.245 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part3" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:36.245 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "0e2479d0-bb44-41a6-a9d0-057f87c7eb83
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:36.246 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:36.246 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part1 execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:36.462 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf dd if=/var/lib/ironic/images/e8b3117e-73c0-4542-9eb5-189a0ff8b380/disk of=/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3 bs=1M oflag=direct" returned: 0 in 20.113s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:36.463 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "dd if=/var/lib/ironic/images/e8b3117e-73c0-4542-9eb5-189a0ff8b380/disk of=/dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3 bs=1M oflag=direct" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:36.463 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:36.463 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "4130+1 records in
4130+1 records out
4331012096 bytes (4.3 GB, 4.0 GiB) copied, 19.8009 s, 219 MB/s
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:36.464 7 INFO ironic_lib.disk_utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Image for e8b3117e-73c0-4542-9eb5-189a0ff8b380 successfully populated
2021-06-24 11:46:36.464 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3 execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:36.912 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part1" returned: 0 in 0.666s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:36.913 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.30:3260-iscsi-iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5-lun-1-part1" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:36.913 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "086A-91F7
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:36.914 7 DEBUG ironic_lib.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:36.914 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.30:3260 -T iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5 --logout execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:36.946 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3" returned: 0 in 0.482s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:36.947 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part3" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:36.948 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "0e2479d0-bb44-41a6-a9d0-057f87c7eb83
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:36.948 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:36.951 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part1 execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:37.288 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part1" returned: 0 in 0.340s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:37.289 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "blkid -s UUID -o value /dev/disk/by-path/ip-192.168.24.37:3260-iscsi-iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380-lun-1-part1" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:101
2021-06-24 11:46:37.289 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "087D-1CC8
" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:103
2021-06-24 11:46:37.289 7 DEBUG ironic_lib.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic_lib/utils.py:104
2021-06-24 11:46:37.290 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.37:3260 -T iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380 --logout execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:37.410 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.30:3260 -T iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5 --logout" returned: 0 in 0.495s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:37.411 7 DEBUG ironic.common.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "iscsiadm -m node -p 192.168.24.30:3260 -T iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5 --logout" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:77
2021-06-24 11:46:37.411 7 DEBUG ironic.common.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "Logging out of session [sid: 1, target: iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5, portal: 192.168.24.30,3260]
Logout of [sid: 1, target: iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5, portal: 192.168.24.30,3260] successful.
" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:78
2021-06-24 11:46:37.411 7 DEBUG ironic.common.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:79
2021-06-24 11:46:37.412 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.30:3260 -T iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5 -o delete execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:37.633 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.37:3260 -T iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380 --logout" returned: 0 in 0.343s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:37.634 7 DEBUG ironic.common.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "iscsiadm -m node -p 192.168.24.37:3260 -T iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380 --logout" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:77
2021-06-24 11:46:37.634 7 DEBUG ironic.common.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "Logging out of session [sid: 2, target: iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380, portal: 192.168.24.37,3260]
Logout of [sid: 2, target: iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380, portal: 192.168.24.37,3260] successful.
" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:78
2021-06-24 11:46:37.634 7 DEBUG ironic.common.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:79
2021-06-24 11:46:37.635 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Running cmd (subprocess): sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.37:3260 -T iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380 -o delete execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:379
2021-06-24 11:46:37.700 7 DEBUG oslo_concurrency.processutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.30:3260 -T iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5 -o delete" returned: 0 in 0.288s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:37.701 7 DEBUG ironic.common.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Execution completed, command line is "iscsiadm -m node -p 192.168.24.30:3260 -T iqn.2008-10.org.openstack:35eae434-6f4f-456c-8d17-b70364ea74a5 -o delete" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:77
2021-06-24 11:46:37.701 7 DEBUG ironic.common.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stdout is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:78
2021-06-24 11:46:37.701 7 DEBUG ironic.common.utils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:79
2021-06-24 11:46:37.703 7 DEBUG oslo_concurrency.lockutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Lock "master_image" acquired by "ironic.drivers.modules.image_cache.ImageCache.clean_up" :: waited 0.000s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:327
2021-06-24 11:46:37.703 7 DEBUG ironic.drivers.modules.image_cache [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Starting clean up for master image cache /var/lib/ironic/master_images clean_up /usr/lib/python3.6/site-packages/ironic/drivers/modules/image_cache.py:198
2021-06-24 11:46:37.703 7 DEBUG oslo_concurrency.lockutils [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Lock "master_image" released by "ironic.drivers.modules.image_cache.ImageCache.clean_up" :: held 0.001s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:339
2021-06-24 11:46:37.734 7 DEBUG ironic.drivers.modules.agent_base_vendor [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Configuring local boot for node 35eae434-6f4f-456c-8d17-b70364ea74a5 configure_local_boot /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_base_vendor.py:830
2021-06-24 11:46:37.734 7 DEBUG ironic.drivers.modules.agent_base_vendor [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Installing the bootloader for node 35eae434-6f4f-456c-8d17-b70364ea74a5 on partition 0e2479d0-bb44-41a6-a9d0-057f87c7eb83, EFI system partition 086A-91F7 configure_local_boot /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_base_vendor.py:856
2021-06-24 11:46:37.735 7 DEBUG ironic.drivers.modules.agent_client [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Executing agent command image.install_bootloader for node 35eae434-6f4f-456c-8d17-b70364ea74a5 _command /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_client.py:93
2021-06-24 11:46:37.888 7 DEBUG oslo_concurrency.processutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] CMD "sudo ironic-rootwrap /etc/ironic/rootwrap.conf iscsiadm -m node -p 192.168.24.37:3260 -T iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380 -o delete" returned: 0 in 0.253s execute /usr/lib/python3.6/site-packages/oslo_concurrency/processutils.py:416
2021-06-24 11:46:37.889 7 DEBUG ironic.common.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Execution completed, command line is "iscsiadm -m node -p 192.168.24.37:3260 -T iqn.2008-10.org.openstack:e8b3117e-73c0-4542-9eb5-189a0ff8b380 -o delete" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:77
2021-06-24 11:46:37.889 7 DEBUG ironic.common.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stdout is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:78
2021-06-24 11:46:37.889 7 DEBUG ironic.common.utils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Command stderr is: "" execute /usr/lib/python3.6/site-packages/ironic/common/utils.py:79
2021-06-24 11:46:37.890 7 DEBUG oslo_concurrency.lockutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Lock "master_image" acquired by "ironic.drivers.modules.image_cache.ImageCache.clean_up" :: waited 0.000s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:327
2021-06-24 11:46:37.890 7 DEBUG ironic.drivers.modules.image_cache [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Starting clean up for master image cache /var/lib/ironic/master_images clean_up /usr/lib/python3.6/site-packages/ironic/drivers/modules/image_cache.py:198
2021-06-24 11:46:37.891 7 DEBUG oslo_concurrency.lockutils [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Lock "master_image" released by "ironic.drivers.modules.image_cache.ImageCache.clean_up" :: held 0.001s inner /usr/lib/python3.6/site-packages/oslo_concurrency/lockutils.py:339
2021-06-24 11:46:37.910 7 DEBUG ironic.drivers.modules.agent_base_vendor [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Configuring local boot for node e8b3117e-73c0-4542-9eb5-189a0ff8b380 configure_local_boot /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_base_vendor.py:830
2021-06-24 11:46:37.910 7 DEBUG ironic.drivers.modules.agent_base_vendor [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Installing the bootloader for node e8b3117e-73c0-4542-9eb5-189a0ff8b380 on partition 0e2479d0-bb44-41a6-a9d0-057f87c7eb83, EFI system partition 087D-1CC8 configure_local_boot /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_base_vendor.py:856
2021-06-24 11:46:37.911 7 DEBUG ironic.drivers.modules.agent_client [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Executing agent command image.install_bootloader for node e8b3117e-73c0-4542-9eb5-189a0ff8b380 _command /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_client.py:93
2021-06-24 11:46:40.758 7 DEBUG ironic.drivers.modules.agent_client [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Agent command image.install_bootloader for node 35eae434-6f4f-456c-8d17-b70364ea74a5 returned result None, error {'type': 'CommandExecutionError', 'code': 500, 'message': "Command execution failed: Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmp6prdf97i\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmp6prdf97i: /dev/vda3 already mounted on /tmp/tmp6prdf97i.\\n'.", 'details': "Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmp6prdf97i\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmp6prdf97i: /dev/vda3 already mounted on /tmp/tmp6prdf97i.\\n'."}, HTTP status code 200 _command /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_client.py:131
2021-06-24 11:46:40.759 7 ERROR ironic.drivers.modules.agent_base_vendor [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Failed to install a bootloader when deploying node 35eae434-6f4f-456c-8d17-b70364ea74a5. Error: {'type': 'CommandExecutionError', 'code': 500, 'message': "Command execution failed: Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmp6prdf97i\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmp6prdf97i: /dev/vda3 already mounted on /tmp/tmp6prdf97i.\\n'.", 'details': "Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmp6prdf97i\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmp6prdf97i: /dev/vda3 already mounted on /tmp/tmp6prdf97i.\\n'."}
2021-06-24 11:46:40.759 7 DEBUG ironic.drivers.modules.agent_client [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Executing agent command log.collect_system_logs for node 35eae434-6f4f-456c-8d17-b70364ea74a5 _command /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_client.py:93
2021-06-24 11:46:40.958 7 DEBUG ironic.drivers.modules.agent_client [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Agent command image.install_bootloader for node e8b3117e-73c0-4542-9eb5-189a0ff8b380 returned result None, error {'type': 'CommandExecutionError', 'code': 500, 'message': "Command execution failed: Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmpngdpi3ts\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmpngdpi3ts: /dev/vda3 already mounted on /tmp/tmpngdpi3ts.\\n'.", 'details': "Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmpngdpi3ts\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmpngdpi3ts: /dev/vda3 already mounted on /tmp/tmpngdpi3ts.\\n'."}, HTTP status code 200 _command /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_client.py:131
2021-06-24 11:46:40.959 7 ERROR ironic.drivers.modules.agent_base_vendor [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Failed to install a bootloader when deploying node e8b3117e-73c0-4542-9eb5-189a0ff8b380. Error: {'type': 'CommandExecutionError', 'code': 500, 'message': "Command execution failed: Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmpngdpi3ts\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmpngdpi3ts: /dev/vda3 already mounted on /tmp/tmpngdpi3ts.\\n'.", 'details': "Installing GRUB2 boot loader to device /dev/vda failed with Unexpected error while running command.\nCommand: mount /dev/vda3 /tmp/tmpngdpi3ts\nExit code: 32\nStdout: ''\nStderr: 'mount: /tmp/tmpngdpi3ts: /dev/vda3 already mounted on /tmp/tmpngdpi3ts.\\n'."}
2021-06-24 11:46:40.959 7 DEBUG ironic.drivers.modules.agent_client [req-e3331fb8-dc50-4d62-a259-ef93e1577ba6 - - - - -] Executing agent command log.collect_system_logs for node e8b3117e-73c0-4542-9eb5-189a0ff8b380 _command /usr/lib/python3.6/site-packages/ironic/drivers/modules/agent_client.py:93
2021-06-24 11:46:41.358 7 DEBUG ironic.drivers.modules.agent_client [req-4656a066-7a01-460f-9c18-594a41c6ad51 - - - - -] Agent command log.collect_system_logs for node 35eae434-6f4f-456c-8d17-b70364ea74a5 returned result {'system_logs': 
Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. Deploy OSP16.2 Overcloud deployment on partition image with uefi boot mode
2. overcloud failed


Actual results:
overcloud deployment failed

Expected results:
overcloud deployment passed

Additional info:

--- Additional comment from Julia Kreger on 2021-06-29 17:31:27 UTC ---

This was introduced by the fix for BZ # 1966129, as for the stable/train backport, we tried to make it python2.7 compatible as RDO had recently complained about breaking py2 compatability. At this point, I'm going to make that fix python3 exclusive and it should be fine.

--- Additional comment from Julia Kreger on 2021-06-29 18:13:37 UTC ---


This is the actual root failure reported in the IPA logs:

Jun 24 07:53:07 host-192-168-24-36 ironic-python-agent[708]: 2021-06-24 07:53:07.311 708 DEBUG ironic_python_agent.extensions.image [-] Exception encountered while attempting to setup the EFI loader from a root filesystem. Error: 'ascii' codec can't decode byte 0xff in position 0: ordinal not in range(128) _try_preserve_efi_assets /usr/lib/python3.6/site-packages/ironic_python_agent/extensions/image.py:744
Jun 24 07:53:07 host-192-168-24-36 ironic-python-agent[708]: 2021-06-24 07:53:07.317 708 DEBUG ironic_python_agent.extensions.image [-] No EFI assets were preserved for setup or the ramdisk was unable to complete the setup. falling back to bootloader installation fromdeployed image. _install_grub2 /usr/lib/python3.6/site-packages/ironic_python_agent/extensions/image.py:501

An additional failure is ultimately what was being reported above, which is not critical, would then occur when attempting to fall back. We're going to handle that issue upstream since it is not a blocker nor an issue for our deployment cases, we just happen to be able to observe it in how this case is failing.

The root cause is an attempt to maintain compatibility for upstream RDO when we backpoted the original UEFI default configuration loading support to navigate the 8.4 bug with the efi shim loader resetting the NVRAM based upon the defaults. For the the backport, I changed the syntax to be python2 compatible, however python3 doesn't honor that syntax and requires an explicit statement of the encoding type. Python3 would then open the file as ascii and it would fail validation. Interestingly enough, this was not observed in upstream CI, but it is likely because upstream Ubuntu is used which does not have a file beginning marker, where as RHEL's default file *does* have the marker (0xFEFF), and the FF portion of FEFF fails the character encoding handling rules of python for ascii.
Comment 1 Julia Kreger 2021-07-13 18:59:46 UTC 
Downstream patch merged, updating fixedinversion.
Comment 20 errata-xmlrpc 2021-12-09 20:20:10 UTC 
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 (Red Hat OpenStack Platform 16.1.7 (Train) bug fix and enhancement 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-2021:3762