Confusing behaviour if a host is unlocked before the VIM has finished disabling services after a host-lock

[Steven Webster]

Brief Description
-----------------
If a user locks a host, then unlocks it soon after (before the VIM has disabled all of the services), the lock appears to get cancelled, and the VIM enables all of the services again.

I believe this is by design, but there are a couple of issues:

1. A system host-show shows the host's task seemingly 'stuck' in 'Locking-', even after the unlock is issued and rejected.
2. The user is not notified that the previous lock has been cancelled. The host-unlock simply gives the message:

"Avoiding 'unlock' action on already 'unlocked' host compute-0"

Additional info:
-----------------

I have seen this while testing the potential fix for https://launchpad.net/bugs/1846818.

In the above potential fix, the VIM waits until all pods are terminated before locking the host. This can take up to 30 seconds. If a host-unlock is issued before the pods are terminated, the VIM will take away the NoExecute taint on the node and restart all of the terminating pods.

So from a user's perspective of:

1. lock a host
2. make a system change
3. unlock the host

They may not be getting behaviour that they expect if 2,3) happen before the VIM has disabled all of the services. I think the user should be given some indication that the initial 'lock' action has been cancelled. I'm also not sure the task should be 'Locking-' if that's the case (the lock being cancelled) either.

If the unlock happens after the pods are terminated, the VIM has disabled services, and the host is actually locked, everything works as expected.

sysinv logs:

host-lock:

2019-10-08 19:00:58.470 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 ihost_patch_start_2019-10-08-19-00-58 patch
2019-10-08 19:00:58.470 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 1. delta_handle ['action']
2019-10-08 19:00:58.470 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 ihost check_lock
2019-10-08 19:00:58.470 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 host check_lock_worker
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 action=lock ihost_val_prenotify: {'ihost_action': 'lock'} ihost_val: {'ihost_action': 'lock', 'task': u'Locking'}
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 host.update.ihost_val_prenotify {'ihost_action': 'lock'}
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 action_check action=lock, notify_vim=True notify_mtce=True rc=True
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 post action_check hostupdate action=lock notify_vim=True notify_mtc=True skip_notify_mtce=False
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 stage_action lock
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 _handle_lock_action
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 Action staged: lock
2019-10-08 19:00:58.478 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 post action_stage hostupdate action=lock notify_vim=True notify_mtc=True skip_notify_mtce=True
2019-10-08 19:00:58.479 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 2. delta_handle ['action']
2019-10-08 19:00:58.479 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 post delta_handle hostupdate action=lock notify_vim=True notify_mtc=True skip_notify_mtce=True
2019-10-08 19:00:58.479 95074 INFO sysinv.api.controllers.v1.host [-] update ihost_val_prenotify: {'ihost_action': 'lock'}
2019-10-08 19:00:58.490 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 apply ihost_val {'ihost_action': 'lock', 'task': u'Locking'}
2019-10-08 19:00:58.490 95074 INFO sysinv.api.controllers.v1.host [-] Notify VIM host action compute-1 action=lock
2019-10-08 19:00:58.490 95074 WARNING sysinv.api.controllers.v1.vim_api [-] vim_host_action hostname=compute-1, action=lock
2019-10-08 19:00:58.491 95074 WARNING sysinv.api.controllers.v1.vim_api [-] vim_host_action hostname=compute-1, action=lock api_cmd=http://localhost:30001/nfvi-plugins/v1/hosts/c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4 headers={'Content-type': 'application/json', 'User-Agent': 'sysinv/1.0'} payload={'action': 'lock', 'hostname': u'compute-1', 'uuid': u'c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4'}
2019-10-08 19:00:58.491 95074 INFO sysinv.api.controllers.v1.rest_api [-] PATCH cmd:http://localhost:30001/nfvi-plugins/v1/hosts/c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4 hdr:{'Content-type': 'application/json', 'User-Agent': 'sysinv/1.0'} payload:{"action": "lock", "hostname": "compute-1", "uuid": "c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4"}
2019-10-08 19:00:58.502 95074 INFO sysinv.api.controllers.v1.rest_api [-] Response={}
2019-10-08 19:00:58.595 95074 INFO sysinv.api.controllers.v1.host [-] Provisioned storage node(s) []
2019-10-08 19:00:58.609 95074 INFO sysinv.api.controllers.v1.host [-] host compute-1 ihost_patch_end_2019-10-08-19-00-58 patch
2019-10-08 19:01:11.024 95074 INFO sysinv.api.controllers.v1.host [-] Provisioned storage node(s) []

host-unlock:

2019-10-08 19:01:11.978 95073 INFO sysinv.api.controllers.v1.host [-] compute-1 ihost_patch_start_2019-10-08-19-01-11 patch
2019-10-08 19:01:11.978 95073 INFO sysinv.api.controllers.v1.host [-] compute-1 1. delta_handle ['action']
2019-10-08 19:01:11.990 95073 INFO sysinv.api.controllers.v1.host [-] host unlock check didn't pass, so set the ihost_action back to None and re-raise the exception
2019-10-08 19:01:12.001 95073 WARNING wsme.api [-] Client-side error: Avoiding 'unlock' action on already 'unlocked' host compute-1
2019-10-08 19:01:13.950 95074 INFO sysinv.api.controllers.v1.host [-] compute-0 ihost_patch_start_2019-10-08-19-01-13 patch
2019-10-08 19:01:13.950 95074 INFO sysinv.api.controllers.v1.host [-] compute-0 1. delta_handle ['availability']
2019-10-08 19:01:13.978 95074 INFO sysinv.api.controllers.v1.host [-] host compute-0 ihost_patch_end_2019-10-08-19-01-13 patch
2019-10-08 19:01:14.040 95073 INFO sysinv.api.controllers.v1.host [-] compute-0 1. delta_handle ['uptime', 'task']
2019-10-08 19:01:29.809 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 ihost_patch_start_2019-10-08-19-01-29 patch
2019-10-08 19:01:29.809 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 ihost_patch_end. No changes from mtce/1.0.
2019-10-08 19:01:48.883 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 ihost_patch_start_2019-10-08-19-01-48 patch
2019-10-08 19:01:48.883 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 1. delta_handle ['action']
2019-10-08 19:01:48.883 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 Pending update_vim_progress_status services-disabled
2019-10-08 19:01:48.884 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 action=services-disabled ihost_val_prenotify: {} ihost_val: {}
2019-10-08 19:01:48.884 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 action_check action=services-disabled, notify_vim=False notify_mtce=True rc=True
2019-10-08 19:01:48.884 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 post action_check hostupdate action=services-disabled notify_vim=False notify_mtc=True skip_notify_mtce=False
2019-10-08 19:01:48.884 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 stage_action services-disabled
2019-10-08 19:01:48.884 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 _handle_vim_services_disabled'
2019-10-08 19:01:48.884 95074 WARNING sysinv.api.controllers.v1.host [-] compute-1 Admin action task not Locking or Force Locking upon receipt of 'services-disabled'.
2019-10-08 19:01:48.884 95074 WARNING sysinv.api.controllers.v1.host [-] compute-1 Exit _handle_vim_services_disabled
2019-10-08 19:01:48.884 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 stage_action aborting request services-disabled ['action']
2019-10-08 19:01:48.884 95074 INFO sysinv.api.controllers.v1.host [-] compute-1 ihost_patch_end stage_action rc exit_return_host

vim logs:

2019-10-08T19:00:58.491 controller-0 VIM_Thread[94895] DEBUG _vim_nfvi_events.py.63 Host action, host_uuid=c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4, host_name=compute-1, do_action=lock.
2019-10-08T19:00:58.492 controller-0 VIM_Thread[94895] INFO _host_state_enabled.py.33 Exiting state (enabled) for compute-1.
2019-10-08T19:00:58.492 controller-0 VIM_Thread[94895] INFO _host_state_disabling.py.27 Entering state (disabling) for compute-1.
2019-10-08T19:00:58.496 controller-0 VIM_Thread[94895] INFO _host_director.py.395 Notify other directors that the host compute-1 services are disabling.
2019-10-08T19:00:58.496 controller-0 VIM_Thread[94895] INFO _instance_director.py.1339 Host compute-1 services disabling.
2019-10-08T19:00:58.497 controller-0 VIM_Thread[94895] INFO _instance_director.py.495 No hypervisors available, can't evacuate instances off of host compute-1.
2019-10-08T19:00:58.498 controller-0 VIM_Thread[94895] INFO _host_director.py.408 Notify other directors that the host compute-1 services are disabled.
2019-10-08T19:00:58.499 controller-0 VIM_Thread[94895] INFO _instance_director.py.1392 Host compute-1 services disabled.
2019-10-08T19:00:58.499 controller-0 VIM_Thread[94895] DEBUG _instance_director.py.1408 Canceling previous host operation host-lock, before continuing with host operation host-lock for compute-1.
2019-10-08T19:00:58.499 controller-0 VIM_Thread[94895] INFO _instance_director.py.495 No hypervisors available, can't evacuate instances off of host compute-1.
2019-10-08T19:00:58.499 controller-0 VIM_Thread[94895] INFO _host.py.838 Host compute-1 FSM State-Change: prev_state=enabled, state=disabling, event=lock.
2019-10-08T19:00:58.500 controller-0 VIM_Thread[94895] INFO _host_director.py.475 Host compute-1 state change notification.
2019-10-08T19:00:58.501 controller-0 VIM_Thread[94895] DEBUG nfvi_infrastructure_api.py.2308 Host rest-api patch path: /nfvi-plugins/v1/hosts/c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4.
2019-10-08T19:00:58.519 controller-0 VIM_Infrastructure-Worker-0_Thread[95092] INFO kubernetes_client.py.68 Adding services=disabled:NoExecute taint to node compute-1
2019-10-08T19:01:05.436 controller-0 VIM_Thread[94895] DEBUG _host_tasks.py.619 Task (audit-disabled-host_compute-0) complete.
2019-10-08T19:01:05.438 controller-0 VIM_Thread[94895] INFO _vim_nfvi_audits.py.150 Ignoring audit reply for host compute-1
2019-10-08T19:01:13.747 controller-0 VIM_Thread[94895] INFO _vim_nfvi_audits.py.150 Ignoring audit reply for host compute-1
2019-10-08T19:01:17.514 controller-0 VIM_Thread[94895] INFO _host_task_work.py.1038 Get-Terminating-Pods callback for container, pods kube-multus-ds-amd64-jp7qp,kube-sriov-cni-ds-amd64-d6rmd terminating
2019-10-08T19:01:22.125 controller-0 VIM_Thread[94895] DEBUG _host.py.666 Host State-Change detected: nfvi_admin_state=unlocked host_admin_state=unlocked, nfvi_oper_state=disabled host_oper_state=disabled, nfvi_avail_state=intest host_avail_status=offline, locking=False unlocking=False fsm current_state=disabled for compute-0.
2019-10-08T19:01:22.129 controller-0 VIM_Thread[94895] INFO _vim_nfvi_audits.py.150 Ignoring audit reply for host compute-1
2019-10-08T19:01:27.932 controller-0 VIM_Thread[94895] INFO _host_task_work.py.1038 Get-Terminating-Pods callback for container, pods kube-multus-ds-amd64-jp7qp,kube-sriov-cni-ds-amd64-d6rmd terminating
2019-10-08T19:01:38.353 controller-0 VIM_Thread[94895] INFO _host_task_work.py.1038 Get-Terminating-Pods callback for container, pods kube-multus-ds-amd64-jp7qp,kube-sriov-cni-ds-amd64-d6rmd terminating
2019-10-08T19:01:38.940 controller-0 VIM_Thread[94895] DEBUG _host_tasks.py.619 Task (audit-disabled-host_compute-0) complete.
2019-10-08T19:01:48.862 controller-0 VIM_Thread[94895] INFO _host_task_work.py.1043 Get-Terminating-Pods callback for container, no pods are terminating
2019-10-08T19:01:48.904 controller-0 VIM_Thread[94895] INFO _host_director.py.421 Notify other directors that the host compute-1 is disabled.
2019-10-08T19:01:48.905 controller-0 VIM_Thread[94895] INFO _instance_director.py.1427 Host compute-1 disabled.
2019-10-08T19:01:48.905 controller-0 VIM_Thread[94895] DEBUG _instance_director.py.1432 Canceling host operation host-lock for compute-1.
2019-10-08T19:01:48.905 controller-0 VIM_Thread[94895] DEBUG _host_tasks.py.279 Task (disable-host_compute-1) complete.
2019-10-08T19:01:48.912 controller-0 VIM_Thread[94895] INFO _host_state_disabling.py.36 Exiting state (disabling) for compute-1.
2019-10-08T19:01:48.913 controller-0 VIM_Thread[94895] INFO _host_state_disabled.py.30 Entering state (disabled) for compute-1.
2019-10-08T19:01:48.915 controller-0 VIM_Thread[94895] INFO _host.py.838 Host compute-1 FSM State-Change: prev_state=disabling, state=disabled, event=task-completed.
2019-10-08T19:01:48.916 controller-0 VIM_Thread[94895] INFO _host_director.py.475 Host compute-1 state change notification.
2019-10-08T19:01:55.692 controller-0 VIM_Thread[94895] INFO _vim_nfvi_audits.py.150 Ignoring audit reply for host compute-1
2019-10-08T19:02:03.997 controller-0 VIM_Thread[94895] INFO _vim_nfvi_audits.py.150 Ignoring audit reply for host compute-1
2019-10-08T19:02:12.285 controller-0 VIM_Thread[94895] DEBUG _host_tasks.py.619 Task (audit-disabled-host_compute-0) complete.
2019-10-08T19:02:12.287 controller-0 VIM_Thread[94895] INFO _vim_nfvi_audits.py.150 Ignoring audit reply for host compute-1
2019-10-08T19:02:17.062 controller-0 VIM_Thread[94895] DEBUG _vim_nfvi_events.py.98 Host state-change, nfvi_host_uuid=f19f78f9-13b6-40c1-9b5f-cfd43a58eef2, nfvi_host_name=compute-0, nfvi_host_admin_state=unlocked, nfvi_host_oper_state=enabled, nfvi_host_avail_status=available.
2019-10-08T19:02:17.067 controller-0 VIM_Thread[94895] DEBUG _host.py.666 Host State-Change detected: nfvi_admin_state=unlocked host_admin_state=unlocked, nfvi_oper_state=enabled host_oper_state=disabled, nfvi_avail_state=available host_avail_status=intest, locking=False unlocking=False fsm current_state=disabled for compute-0.
2019-10-08T19:02:17.068 controller-0 VIM_Thread[94895] INFO _host_state_disabled.py.42 Exiting state (disabled) for compute-0.
2019-10-08T19:02:17.069 controller-0 VIM_Thread[94895] INFO _host_state_enabling.py.27 Entering state (enabling) for compute-0.
2019-10-08T19:02:17.070 controller-0 VIM_Thread[94895] INFO _host.py.838 Host compute-0 FSM State-Change: prev_state=disabled, state=enabling, event=enable.
2019-10-08T19:02:17.072 controller-0 VIM_Thread[94895] INFO _host_director.py.475 Host compute-0 state change notification.
2019-10-08T19:02:17.072 controller-0 VIM_Thread[94895] DEBUG nfvi_infrastructure_api.py.2308 Host rest-api patch path: /nfvi-plugins/v1/hosts/f19f78f9-13b6-40c1-9b5f-cfd43a58eef2.
2019-10-08T19:02:17.088 controller-0 VIM_Infrastructure-Worker-0_Thread[95092] INFO kubernetes_client.py.103 Removing services:NoExecute taint from node compute-0
2019-10-08T19:02:17.575 controller-0 VIM_Thread[94895] DEBUG _host_tasks.py.186 Task (enable-host_compute-0) complete.
2019-10-08T19:02:17.576 controller-0 VIM_Thread[94895] INFO _host_director.py.383 Notify other directors that the host compute-0 is enabled.
2019-10-08T19:02:17.576 controller-0 VIM_Thread[94895] INFO _instance_director.py.1757 No hypervisors available, can't recover instances.
2019-10-08T19:02:17.576 controller-0 VIM_Thread[94895] INFO _host_state_enabling.py.35 Exiting state (enabling) for compute-0.
2019-10-08T19:02:17.576 controller-0 VIM_Thread[94895] INFO _host_state_enabled.py.27 Entering state (enabled) for compute-0.
2019-10-08T19:02:17.576 controller-0 VIM_Thread[94895] INFO _host.py.838 Host compute-0 FSM State-Change: prev_state=enabling, state=enabled, event=task-completed.
2019-10-08T19:02:17.578 controller-0 VIM_Thread[94895] INFO _host_director.py.475 Host compute-0 state change notification.
2019-10-08T19:02:20.691 controller-0 VIM_Thread[94895] INFO _vim_nfvi_audits.py.150 Ignoring audit reply for host compute-0
2019-10-08T19:02:20.691 controller-0 VIM_Thread[94895] INFO _host_state_disabled.py.42 Exiting state (disabled) for compute-1.
2019-10-08T19:02:20.692 controller-0 VIM_Thread[94895] INFO _host_state_enabling.py.27 Entering state (enabling) for compute-1.
2019-10-08T19:02:20.693 controller-0 VIM_Thread[94895] INFO _host.py.838 Host compute-1 FSM State-Change: prev_state=disabled, state=enabling, event=enable.
2019-10-08T19:02:20.694 controller-0 VIM_Thread[94895] INFO _host_director.py.475 Host compute-1 state change notification.
2019-10-08T19:02:20.712 controller-0 VIM_Infrastructure-Worker-0_Thread[95092] INFO kubernetes_client.py.103 Removing services:NoExecute taint from node compute-1
2019-10-08T19:02:20.948 controller-0 VIM_Thread[94895] DEBUG _host_tasks.py.186 Task (enable-host_compute-1) complete.
2019-10-08T19:02:20.948 controller-0 VIM_Thread[94895] INFO _host_director.py.383 Notify other directors that the host compute-1 is enabled.
2019-10-08T19:02:20.948 controller-0 VIM_Thread[94895] INFO _instance_director.py.1757 No hypervisors available, can't recover instances.
2019-10-08T19:02:20.948 controller-0 VIM_Thread[94895] INFO _host_state_enabling.py.35 Exiting state (enabling) for compute-1.
2019-10-08T19:02:20.948 controller-0 VIM_Thread[94895] INFO _host_state_enabled.py.27 Entering state (enabled) for compute-1.

cli:

[sysadmin@controller-0 ~(keystone_admin)]$ system host-show compute-1; system host-lock compute-1
+-----------------------+--------------------------------------------+
| Property | Value |
+-----------------------+--------------------------------------------+
| action | none |
| administrative | unlocked |
| availability | available |
| bm_ip | None |
| bm_type | None |
| bm_username | None |
| boot_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| capabilities | {} |
| clock_synchronization | ntp |
| config_applied | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| config_status | None |
| config_target | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| console | tty0 |
| created_at | 2019-10-08T17:34:04.045189+00:00 |
| hostname | compute-1 |
| id | 3 |
| install_output | text |
| install_state | completed |
| install_state_info | None |
| inv_state | inventoried |
| invprovision | provisioned |
| location | {} |
| mgmt_ip | 192.168.204.6 |
| mgmt_mac | 08:00:27:48:33:46 |
| operational | enabled |
| personality | worker |
| reserved | False |
| rootfs_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| serialid | None |
| software_load | 19.09 |
| task | |
| tboot | false |
| ttys_dcd | None |
| updated_at | 2019-10-08T19:00:04.123706+00:00 |
| uptime | 2215 |
| uuid | c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4 |
| vim_progress_status | services-enabled |
+-----------------------+--------------------------------------------+
+-----------------------+--------------------------------------------+
| Property | Value |
+-----------------------+--------------------------------------------+
| action | none |
| administrative | unlocked |
| availability | available |
| bm_ip | None |
| bm_type | None |
| bm_username | None |
| boot_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| capabilities | {} |
| clock_synchronization | ntp |
| config_applied | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| config_status | None |
| config_target | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| console | tty0 |
| created_at | 2019-10-08T17:34:04.045189+00:00 |
| hostname | compute-1 |
| id | 3 |
| install_output | text |
| install_state | completed |
| install_state_info | None |
| inv_state | inventoried |
| invprovision | provisioned |
| location | {} |
| mgmt_ip | 192.168.204.6 |
| mgmt_mac | 08:00:27:48:33:46 |
| operational | enabled |
| personality | worker |
| reserved | False |
| rootfs_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| serialid | None |
| software_load | 19.09 |
| task | Locking |
| tboot | false |
| ttys_dcd | None |
| updated_at | 2019-10-08T19:00:04.123706+00:00 |
| uptime | 2215 |
| uuid | c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4 |
| vim_progress_status | services-enabled |
+-----------------------+--------------------------------------------+
[sysadmin@controller-0 ~(keystone_admin)]$ system host-show compute-1
+-----------------------+--------------------------------------------+
| Property | Value |
+-----------------------+--------------------------------------------+
| action | none |
| administrative | unlocked |
| availability | available |
| bm_ip | None |
| bm_type | None |
| bm_username | None |
| boot_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| capabilities | {} |
| clock_synchronization | ntp |
| config_applied | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| config_status | None |
| config_target | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| console | tty0 |
| created_at | 2019-10-08T17:34:04.045189+00:00 |
| hostname | compute-1 |
| id | 3 |
| install_output | text |
| install_state | completed |
| install_state_info | None |
| inv_state | inventoried |
| invprovision | provisioned |
| location | {} |
| mgmt_ip | 192.168.204.6 |
| mgmt_mac | 08:00:27:48:33:46 |
| operational | enabled |
| personality | worker |
| reserved | False |
| rootfs_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| serialid | None |
| software_load | 19.09 |
| task | Locking- |
| tboot | false |
| ttys_dcd | None |
| updated_at | 2019-10-08T19:01:02.020588+00:00 |
| uptime | 2215 |
| uuid | c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4 |
| vim_progress_status | services-enabled |
+-----------------------+--------------------------------------------+

While pods are still terminating:

[sysadmin@controller-0 ~(keystone_admin)]$ system host-unlock compute-1
Avoiding 'unlock' action on already 'unlocked' host compute-1

~~~ A minute or two or 1 hour later ~~~~

[sysadmin@controller-0 ~(keystone_admin)]$ system host-show compute-1
+-----------------------+--------------------------------------------+
| Property | Value |
+-----------------------+--------------------------------------------+
| action | none |
| administrative | unlocked |
| availability | available |
| bm_ip | None |
| bm_type | None |
| bm_username | None |
| boot_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| capabilities | {} |
| clock_synchronization | ntp |
| config_applied | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| config_status | None |
| config_target | 5d0880f6-5ab3-4d8e-baba-a30899715d65 |
| console | tty0 |
| created_at | 2019-10-08T17:34:04.045189+00:00 |
| hostname | compute-1 |
| id | 3 |
| install_output | text |
| install_state | completed |
| install_state_info | None |
| inv_state | inventoried |
| invprovision | provisioned |
| location | {} |
| mgmt_ip | 192.168.204.6 |
| mgmt_mac | 08:00:27:48:33:46 |
| operational | enabled |
| personality | worker |
| reserved | False |
| rootfs_device | /dev/disk/by-path/pci-0000:00:0d.0-ata-1.0 |
| serialid | None |
| software_load | 19.09 |
| task | Locking- |
| tboot | false |
| ttys_dcd | None |
| updated_at | 2019-10-08T19:01:11.992256+00:00 |
| uptime | 2280 |
| uuid | c4a7e3d5-045f-4f75-b9e7-a19e4afd34b4 |
| vim_progress_status | services-enabled |
+-----------------------+--------------------------------------------+

Severity
--------
Minor

Steps to Reproduce
------------------

May need the potential fix for https://launchpad.net/bugs/1846818 to reproduce (making the VIM take longer to disable services)

- Standard system.
- lock a host
- wait one second and unlock the host

Expected Behavior
------------------
The user should be given more information about why the unlock could not be completed, or the interaction between the VIM/sysinv should change to account for this scenario.

Actual Behavior
----------------

The host will not unlock until the host is locked again and the VIM has been allowed to finish disabling services

Reproducibility
---------------

100%

System Configuration
--------------------
2 controller, 2 worker standard config

Branch/Pull Time/Commit
-----------------------
BUILD_DATE="2019-10-08 11:31:10 -0500" with fix pulled from https://launchpad.net/bugs/1846818

[Ghada Khalil (gkhalil)]

Appears to be a day 1 limitation; assigning to stx.config TL for review and recommendation.
For now, I will mark this as low priority / not gating.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/696176

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/696176
Committed: https://git.openstack.org/cgit/starlingx/config/commit/?id=d70d45669d4c24ab23a8e0964812952c1fa19f54
Submitter: Zuul
Branch: master

commit d70d45669d4c24ab23a8e0964812952c1fa19f54
Author: John Kung <email address hidden>
Date: Tue Nov 26 15:21:40 2019 -0500

    Disallow host-unlock if a lock operation is in progress

    If host-unlock is issued while a host-lock or host-lock force operation
    is already in progress, restore the original host action and reject the
    host-unlock in order to allow the lock operation to terminate normally.

    Change-Id: Ib82da93aa4a55f5cd3f41ab904745bea7c4e3afb
    Closes-Bug: 1847330
    Signed-off-by: John Kung <email address hidden>