Unlock active controller failed: host-unlock rejected: Not patch current. 'sw-patch host-install controller-0' is required.

[Alexandru Dimofte]

Brief Description
-----------------
Sanity Test failed regarding unlocking active controller. The observed error was:
Client-side error: host-unlock rejected: Not patch current. 'sw-patch host-install controller-0' is required.

Severity
--------
<Major: System/Feature is usable but degraded>

Steps to Reproduce
------------------
Try to unlock active controller

Expected Behavior
------------------
Should work fine.

Actual Behavior
----------------
Test is failing, and the error message was:
sysinv 2022-01-20 19:56:21.552 112687 WARNING wsme.api [-] Client-side error: host-unlock rejected: Not patch current. 'sw-patch host-install controller-0' is required.: ClientSideError: host-unlock rejected: Not patch current. 'sw-patch host-install controller-0' is required.

Reproducibility
---------------
I don't yet know if this is 100% reproductible. I guess it is sporadic.

System Configuration
--------------------
Observed on bare-metal Simplex configuration.

Branch/Pull Time/Commit
-----------------------
master - 20220120T161508Z

Last Pass
---------
few days ago. I can't tell an exact image because the latest images were affected by other critical or major bugs too and many tests failed because of that or because of this issue...

Timestamp/Logs
--------------
will be attached

Test Activity
-------------
Sanity

Workaround
----------
-

[Al Bailey (albailey1974)]

According to the bash log
Unlock gets invoked at 19:56:18
Patch gets host-installed at 19:56:21

this is the bash log:
2022-01-20T19:56:18.000 controller-0 -sh: info HISTORY: PID=842101 UID=42425 system --os-username 'admin' --os-password xxxxxx --os-project-name admin --os-auth-url http://192.168.204.1:5000/v3 --os-user-domain-name Default --os-project-domain-name Default --os-endpoint-type internalURL --os-region-name RegionOne host-unlock controller-0
2022-01-20T19:56:21.000 controller-0 -sh: info HISTORY: PID=842101 UID=42425 echo $?
2022-01-20T19:56:21.000 controller-0 -sh: info HISTORY: PID=842101 UID=42425 sudo sw-patch host-install controller-0

According to the patching log, the host-install takes 2 minutes and runs from 19:56:21 to 19:58:29
2022-01-20T19:56:21: sw-patch-agent[95835]: patch_agent.py(606): INFO: Handling install
...
2022-01-20T19:58:29: sw-patch-controller-daemon[95877]: patch_controller.py(146): INFO: Agent controller-0 (192.168.204.2) reporting out_of_date=False, requires_reboot=False

After 19:58:29 the host unlock will be permitted.
I do not know what the sanity steps are here.
Check if there is a missing step or something being done in parallel instead of after the patch.

[Ghada Khalil (gkhalil)]

This issue is not reported in the most recent stx master sanity which was green.
Sanity report: http://lists.starlingx.io/pipermail/starlingx-discuss/2022-January/012698.html

There were no software changes in the most recent load related to this code area which hasn't changed any time recently.

@Alex, can you please look into the sanity steps as per Al's comments above? Perhaps there is some condition in the sanity suire which triggers the unlock attempt too early.

[Ghada Khalil (gkhalil)]

I'm assigning this back to Alex since it doesn't appear to be a software issue, but is more likely a sanity automation issue.