ironic locks and times out the tripleo deployment

[wes hayutin]

https://logs.rdoproject.org/openstack-periodic/git.openstack.org/openstack-infra/tripleo-ci/master/legacy-periodic-tripleo-ci-centos-7-ovb-3ctlr_1comp-featureset001-master/cb21587/logs/undercloud/home/zuul/overcloud_prep_images.log.txt.gz

2018-07-17 12:16:40 | + openstack overcloud node provide --all-manageable
2018-07-17 12:16:45 | Waiting for messages on queue 'tripleo' with no timeout.
2018-07-17 13:39:19 | Connection is already closed.
2018-07-17 13:39:19 | [{u'result': u'Node a2e41bab-2eb2-465c-a5d9-8e09c780ce6f did not reach state "available", the state is "clean wait", error: None'}, {u'result': u'Node 78db094d-30c2-4544-8548-969839f518f4 did not reach state "available", the state is "[u\'clean wait\', u\'clean wait\']", error: [None, None]'}, {u'result': u'Node c78ab18d-3013-4379-a1ef-69b641920ed5 did not reach state "available", the state is "clean wait", error: None'}, {u'result': u'Node 6c4137b3-9daa-4b8b-8976-e8900942ac87 did not reach state "available", the state is "clean wait", error: None'}]

https://logs.rdoproject.org/openstack-periodic/git.openstack.org/openstack-infra/tripleo-ci/master/legacy-periodic-tripleo-ci-centos-7-ovb-3ctlr_1comp-featureset001-master/cb21587/logs/undercloud/var/log/containers/ironic/ironic-conductor.log.txt.gz#_2018-07-17_11_48_05_245

2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service [req-cc7fa5c8-c42a-42b0-b7b4-fd285bc13006 - - - - -] Error starting thread.: DriverLoadError: Driver, hardware type or interface ilo-pxe could not be loaded. Reason: [Errno 13] Permission denied: '/var/lib/ironic/httpboot/boot.ipxe'.
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service Traceback (most recent call last):
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/oslo_service/service.py", line 792, in run_service
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service service.start()
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/common/rpc_service.py", line 54, in start
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service self.manager.init_host(admin_context)
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/conductor/base_manager.py", line 140, in init_host
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service self._collect_periodic_tasks(admin_context)
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/conductor/base_manager.py", line 268, in _collect_periodic_tasks
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service for ifaces in driver_factory.all_interfaces().values():
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/common/driver_factory.py", line 271, in all_interfaces
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service return {iface: interfaces(iface) for iface in _INTERFACE_LOADERS}
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/common/driver_factory.py", line 271, in <dictcomp>
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service return {iface: interfaces(iface) for iface in _INTERFACE_LOADERS}
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/common/driver_factory.py", line 262, in interfaces
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service return _get_all_drivers(_INTERFACE_LOADERS[interface_type]())
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/common/driver_factory.py", line 323, in __init__
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service self.__class__._init_extension_manager()
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/oslo_concurrency/lockutils.py", line 274, in inner
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service return f(*args, **kwargs)
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/common/driver_factory.py", line 393, in _init_extension_manager
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service on_missing_entrypoints_callback=missing_callback))
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/stevedore/named.py", line 81, in __init__
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service verify_requirements)
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/stevedore/extension.py", line 203, in _load_plugins
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service self._on_load_failure_callback(self, ep, err)
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service File "/usr/lib/python2.7/site-packages/ironic/common/driver_factory.py", line 378, in _catch_driver_not_found
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service raise exception.DriverLoadError(driver=ep.name, reason=exc)
2018-07-17 11:48:05.245 ERROR /var/log/extra/docker/containers/ironic_conductor/stdout.log: 7 ERROR oslo_service.service DriverLoadError: Driver, hardware type or interface ilo-pxe could not be loaded. Reason: [Errno 13] Permission denied: '/var/lib/ironic/httpboot/boot.ipxe'.

()[ironic@undercloud /]$ ls -la /var/lib/ironic/httpboot/
total 387580
drwxr-xr-x. 2 root root 86 Jul 17 17:11 .
drwxr-xr-x. 4 ironic ironic 59 Jul 17 17:31 ..
-rwxr-xr-x. 1 root root 6233824 Jul 17 17:11 agent.kernel
-rw-r--r--. 1 root root 390638373 Jul 17 17:11 agent.ramdisk
-rw-r--r--. 1 ironic ironic 758 Jul 17 17:00 boot.ipxe
-rw-r--r--. 1 ironic-inspector ironic-inspector 470 Jul 17 16:35 inspector.ipxe

()[ironic@undercloud /]$ ls -Z /var/lib/ironic/httpboot/
-rwxr-xr-x. root root unconfined_u:object_r:var_lib_t:s0 agent.kernel
-rw-r--r--. root root unconfined_u:object_r:var_lib_t:s0 agent.ramdisk
-rw-r--r--. ironic ironic system_u:object_r:var_lib_t:s0 boot.ipxe
-rw-r--r--. ironic-inspector ironic-inspector system_u:object_r:var_lib_t:s0 inspector.ipxe
()[ironic@undercloud /]$

()[ironic@undercloud /]$ getenforce
Permissive
()[ironic@undercloud /]$ exit
exit
(undercloud) [stack@undercloud ~]$ getenforce
Permissive
(undercloud) [stack@undercloud ~]$

Also hitting this in libvirt reproducers on master.

[wes hayutin (weshayutin)]

introspection run w/ --debug. Had to ctrl-c after 10min

[wes hayutin (weshayutin)]

https://access.redhat.com/solutions/3349081 hrm.. maybe a reoccurring issue.

[wes hayutin (weshayutin)]

It's possible I'm conflating two errors in the same launchpad bug.. if so I am sorry.

On libvirt this seems to be the root cause

2018-07-17 19:39:43.247 6 ERROR ironic.drivers.modules.ipmitool [req-a411dd98-573e-4aff-97f4-3df8076f5cfe 562b3a2f67034a97aab1018052e24890 23fdf59430484eedac334be89826779d - default default│·······················
] IPMI Error while attempting "ipmitool -I lanplus -H 192.168.24.1 -L ADMINISTRATOR -p 6230 -U admin -R 12 -N 5 -f /tmp/tmphMeTTo power on" for node 1619da08-cdea-474a-9c51-578595a07c28. Er│·······················
ror: Unexpected error while running command. │·······················
Command: ipmitool -I lanplus -H 192.168.24.1 -L ADMINISTRATOR -p 6230 -U admin -R 12 -N 5 -f /tmp/tmphMeTTo power on │·······················
Exit code: 1 │·······················
Stdout: u'' │·······················
Stderr: u'Set Chassis Power Control to Up/On failed: Command not supported in present state\n': ProcessExecutionError: Unexpected error while running command. │·······················
2018-07-17 19:39:43.248 6 WARNING ironic.drivers.modules.ipmitool [req-a411dd98-573e-4aff-97f4-3df8076f5cfe 562b3a2f67034a97aab1018052e24890 23fdf59430484eedac334be89826779d - default defau│·······················
lt] IPMI power action power on failed for node 1619da08-cdea-474a-9c51-578595a07c28 with error: Unexpected error while running command. │·······················
Command: ipmitool -I lanplus -H 192.168.24.1 -L ADMINISTRATOR -p 6230 -U admin -R 12 -N 5 -f /tmp/tmphMeTTo power on │·······················
Exit code: 1 │·······················
Stdout: u'' │·······················
Stderr: u'Set Chassis Power Control to Up/On failed: Command not supported in present state\n'.: ProcessExecutionError: Unexpected error while running command. │·······················
2018-07-17 19:39:43.328 6 DEBUG ironic.conductor.task_manager [req-a411dd98-573e-4aff-97f4-3df8076f5cfe 562b3a2f67034a97aab1018052e24890 23fdf59430484eedac334be89826779d - default default] │·······················
Successfully released exclusive lock for changing node power state on nod...

[yatin (yatinkarel)]

It's the same neutron ovs destroy_patch_ports issue [1] fixed by https://review.rdoproject.org/r/#/c/14859/.

[1] https://logs.rdoproject.org/openstack-periodic/git.openstack.org/openstack-infra/tripleo-ci/master/legacy-periodic-tripleo-ci-centos-7-ovb-3ctlr_1comp-featureset001-master/cb21587/logs/undercloud/var/log/extra/docker/containers/neutron_ovs_agent/stdout.log.txt.gz