Bug 1848560

It looks like d12125c2-39ab-4708-962e-c0e9a5045fed was successfully deployed by Ironic.  The question is what is the validation attempting to do?  Its expected that the node will be locked during certain operations and a retry must be done.

In this case the request was at:
2020-06-15 14:35:41.210 21 DEBUG wsme.api [req-1781b693-4795-4852-abd4-31bc2a2e0fe5 d5239e4a006144dca7633c05f0892463 aafcf1d1d98544cba6e392415d4c8070 - default default] Client-side error: Node d12125c2-39ab-4708-962e-c0e9a5045fed is locked by host undercloud-0.redhat.local, please retry after the current operation is completed.
Traceback (most recent call last):

From ironic-conductor.log we see around that time that the node was reserved for port create:
2020-06-15 14:31:52.381 7 DEBUG ironic.conductor.manager [req-0e9a1cd1-2d7e-427a-907a-3428029afdfd d5239e4a006144dca7633c05f0892463 aafcf1d1d98544cba6e392415d4c8070 - default default] RPC create_node called for node d12125c2-39ab-4708-962e-c0e9a5045fed. create_node /usr/lib/python3.6/site-packages/ironic/conductor/manager.py:137
2020-06-15 14:31:52.437 7 DEBUG ironic.conductor.manager [req-f5ba4e47-dd52-4cd6-9a91-e90f2c74c109 d5239e4a006144dca7633c05f0892463 aafcf1d1d98544cba6e392415d4c8070 - default default] RPC create_port called for port a3bd5f36-d891-4782-8417-ad155c30105b. create_port /usr/lib/python3.6/site-packages/ironic/conductor/manager.py:2630
2020-06-15 14:31:52.446 7 DEBUG ironic.conductor.task_manager [req-f5ba4e47-dd52-4cd6-9a91-e90f2c74c109 d5239e4a006144dca7633c05f0892463 aafcf1d1d98544cba6e392415d4c8070 - default default] Attempting to get exclusive lock on node d12125c2-39ab-4708-962e-c0e9a5045fed (for port create) __init__ /usr/lib/python3.6/site-packages/ironic/conductor/task_manager.py:222
2020-06-15 14:31:52.456 7 DEBUG ironic.conductor.task_manager [req-f5ba4e47-dd52-4cd6-9a91-e90f2c74c109 d5239e4a006144dca7633c05f0892463 aafcf1d1d98544cba6e392415d4c8070 - default default] Node d12125c2-39ab-4708-962e-c0e9a5045fed successfully reserved for port create (took 0.01 seconds) reserve_node /usr/lib/python3.6/site-packages/ironic/conductor/task_manager.py:277

Actually the snippet above from ironic-conductor.log is incorrect. Its really this power state change that happened prior to the client request:
020-06-15 14:35:27.461 7 DEBUG ironic.conductor.task_manager [req-eab36144-4926-4481-b87b-24514ba3454e 699cfc39630348d48cc54f811936d6c5 a6ee2da2d16a483ea4c85a75445c0519 - default default] Node d12125c2-39ab-4708-962e-c0e9a5045fed successfully reserved for changing node power state (took 0.01 seconds) reserve_node /usr/lib/python3.6/site-packages/ironic/conductor/task_manager.py:277

So the node is locked to change power state.  We see an attempt to get the lock here, which probably corresponds to the access failure:
2020-06-15 14:35:39.112 7 DEBUG ironic.conductor.task_manager [req-1781b693-4795-4852-abd4-31bc2a2e0fe5 d5239e4a006144dca7633c05f0892463 aafcf1d1d98544cba6e392415d4c8070 - default default] Attempting to get exclusive lock on node d12125c2-39ab-4708-962e-c0e9a5045fed (for provision action provide) __init__ /usr/lib/python3.6/site-packages/ironic/conductor/task_manager.py:222

Then the lock is released here:
2020-06-15 14:35:43.082 7 INFO ironic.conductor.utils [req-eab36144-4926-4481-b87b-24514ba3454e 699cfc39630348d48cc54f811936d6c5 a6ee2da2d16a483ea4c85a75445c0519 - default default] Successfully set node d12125c2-39ab-4708-962e-c0e9a5045fed power state to power off by power off.
2020-06-15 14:35:43.087 7 DEBUG ironic.conductor.task_manager [req-eab36144-4926-4481-b87b-24514ba3454e 699cfc39630348d48cc54f811936d6c5 a6ee2da2d16a483ea4c85a75445c0519 - default default] Successfully released exclusive lock for changing node power state on node d12125c2-39ab-4708-962e-c0e9a5045fed (lock was held 15.63 sec) release_resources /usr/lib/python3.6/site-packages/ironic/conductor/task_manager.py:356

Note that the "lock was held 15.63 sec".  It was in this time that the request came in and could not get the lock.

To summarize, this isn't an Ironic issue.  Ironic is acting properly by locking the node when its performing a power operation.  The validation should retry the access to ironic, or wait until it is available.

Changing component to tripleo-validations so that team can take a look.

OK. We don't really have any ironic related validations that I know of, at least nothing we specifically added, but will look.

I really don't see how this could be happening based on the existing code as I understand it, but it is fairly clear that the commands being issued to the stack are running faster than the nodes and related configuration are being applied. At which point, its not an ironic bug at all nor even a bug related to the validation code itself, but how the commands are being issued.

If this issue cannot be reproduced readily, I suspect it should be closed as not a bug.

OK, this sounds similar to an issue I debugged yesterday[1]. When running "openstack overcloud node introspect --all-manageable --provide" the nodes are powered down and then the provide workflow is called. If the power-down doesn't complete before the set_provision_state lock attempt times-out then the node-locked error is raised.

I think our choices to solve this are:
a) In the set_node_state workflow[2], add a retry loop on set_provision_state
b) Since this issue occurs when it takes at least 15 seconds to power down then this must be happening for customers regularly. Lets come up with some appropriate values for ironic.conf [conductor] node_locked_retry_interval, node_locked_retry_attempts and set those from tripleo-heat-templates as tripleo opinionated defaults.

I'd prefer b) because I think its preferable for the retry mechanism to be as low down the stack as possible, the mechanism is already there, and we just need to tweak its parameters.

[1] https://bugzilla.redhat.com/show_bug.cgi?id=1668028#c21
[2] https://opendev.org/openstack/tripleo-common/src/branch/stable/train/workbooks/baremetal.yaml#L27

I've posted a potential fix upstream, this should be backported as far as 13.x if it works

Linking to merged stable/train commit

The fix is already in the 16.1.2 build, I'm just updating this bz to reflect that.

 openstack-tripleo-common-11.4.1-1.20200914165651.el8ost.noarch.rpm is packaged in z2, so moving to z3

This time I found the actual version where this change landed in a package on August 25th. I'm setting back to z2 to update this bug with the historic fix.

Verified by https://rhos-ci-jenkins.lab.eng.tlv2.redhat.com/view/DFG/view/ceph/view/rhos/job/DFG-ceph-rhos-16.1_director-rhel-virthost-3cont_2comp_6ceph-ipv4-geneve-monolithic/ as it does not fail

According to our records, this should be resolved by openstack-tripleo-common-11.4.1-1.20200914165651.el8ost.  This build is available now.