RPC timeout error when creating barbican secret on host-bulk-add after controller-0 is up

[Yang Liu]

Brief Description
-----------------
After controller-0 is installed and configured, run system host-bulk-add <xmlfile>, the cmd will fail due to RPC timeout.

Severity
--------
Major

Steps to Reproduce
------------------
- Install and configure controller-0 using ansible
- unlock controller-0 and wait for it available and pods are running
- system host-bulk-add other hosts

TC-name: system install

Expected Behavior
------------------
- hosts successfully added

Actual Behavior
----------------
[2019-08-09 14:06:49,438] 301 DEBUG MainThread ssh.send :: Send 'system --os-endpoint-type internalURL --os-region-name RegionOne host-bulk-add hosts_bulk_add.xml'
[2019-08-09 14:08:51,518] 423 DEBUG MainThread ssh.expect :: Output:
Error:
 controller: Timeout while waiting on RPC response - topic: "sysinv.conductor_manager", RPC method: "create_barbican_secret" info: "<unknown>"
 controller: Timeout while waiting on RPC response - topic: "sysinv.conductor_manager", RPC method: "create_barbican_secret" info: "<unknown>"

Reproducibility
---------------
Reproducible
This is seen on multiple systems on 0808 and later loads, and was not seen on 0805 load.
To work around it, rerun this command after some time.

System Configuration
--------------------
AIO-DX, Standard, Dedicated storage systems

Branch/Pull Time/Commit
-----------------------
We see this issue on both master the stx2.0 branches.
stx master as of 20190809
stx.2.0 as of 20190808

Last Pass
---------
20190805

Timestamp/Logs
--------------
# controller-0 is up and pods are running
[2019-08-09 14:06:46,730] 301 DEBUG MainThread ssh.send :: Send 'kubectl get pod -n=kube-system -o=wide'
NAME READY STATUS RESTARTS AGE IP NODE NOMINATED NODE READINESS GATES
calico-kube-controllers-64d7b76bbd-xwqn2 1/1 Running 1 44m 172.16.192.68 controller-0 <none> <none>
calico-node-grtkc 1/1 Running 1 44m 192.168.204.3 controller-0 <none> <none>
coredns-5c4849b47c-k9vqm 1/1 Running 1 44m 172.16.192.67 controller-0 <none> <none>
coredns-5c4849b47c-lrrjv 0/1 Pending 0 44m <none> <none> <none> <none>
kube-apiserver-controller-0 1/1 Running 3 43m 192.168.204.3 controller-0 <none> <none>
kube-controller-manager-controller-0 1/1 Running 1 43m 192.168.204.3 controller-0 <none> <none>
kube-multus-ds-amd64-nhvzv 1/1 Running 1 44m 192.168.204.3 controller-0 <none> <none>
kube-proxy-6sxg6 1/1 Running 1 44m 192.168.204.3 controller-0 <none> <none>
kube-scheduler-controller-0 1/1 Running 1 44m 192.168.204.3 controller-0 <none> <none>
kube-sriov-cni-ds-amd64-qm6hl 1/1 Running 1 44m 192.168.204.3 controller-0 <none> <none>
tiller-deploy-9c6df7f79-2j862 1/1 Running 1 44m 192.168.204.3 controller-0 <none> <none>

# cmd failed
[2019-08-09 14:06:49,438] 301 DEBUG MainThread ssh.send :: Send 'system --os-endpoint-type internalURL --os-region-name RegionOne host-bulk-add hosts_bulk_add.xml'
[2019-08-09 14:08:51,518] 423 DEBUG MainThread ssh.expect :: Output:
Error:
 controller: Timeout while waiting on RPC response - topic: "sysinv.conductor_manager", RPC method: "create_barbican_secret" info: "<unknown>"
 controller: Timeout while waiting on RPC response - topic: "sysinv.conductor_manager", RPC method: "create_barbican_secret" info: "<unknown>"

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

[John Kung (john-kung)]

This issue could be related to change from https://bugs.launchpad.net/starlingx/+bug/1834673. At least the return code reported in bug 1834673 did not cover the rpc timeout case.

Revert request for suspect update is in Gerrit: https://review.opendev.org/#/c/675698/

[zhipeng liu (zhipengs)]

Hi John,

RPC timeout causes command failure should be expected action, right?
In my patch, it explicitly report command error and let user to try it again later.
If we revert this patch, we just ignore the timeout issue.

For timeout case, we need handle it in bulk_add functions, the place where we catch
the timeout exception.

So this is another issue existed all the time.
We'd better merge my original patch, and add a new patch to fix timeout case instead of reverting my patch, right?

Thanks!
Zhipeng

[John Kung (john-kung)]

hi Zhipeng, The errors/timeout on barbican bmc password storage needs to be handled. I would recommend resubmitting the review with the bulk_add function updated so that the bmc password timeout/error cases can be reviewed wholistically.
Thanks, John

[John Kung (john-kung)]

I reverted https://bugs.launchpad.net/starlingx/+bug/1834673 because it was suspect to trigger this issue, and the commit did not handle the bmc passowrd retrieval timeout case from barbican. I suspect the issue with the rpc timeout would still occur (even with the update reverted).

Investigation is required into the reason for the rpc timeout on rpcapi.create_barbican_secret() and better handling of the timeout condition to return an error code to the client.

[Ghada Khalil (gkhalil)]

Marking as stx.3.0 / medium priority given that re-running the cmd goes thru. Still this should be investigated and the root-cause determined/addressed.

[Alexander Kozyrev (akozyrev)]

sysinv-conductor is stuck for 2 minutes during startup and unable to handle any RPC requests.
The refresh_helm_repo_information() function executes “sudo -u sysadmin helm repo update” and waits for it.
Helm tries to reach external https://kubernetes-charts.storage.googleapis.com and timeouts after 2 minutes.
Any command (since sysinv-api is up and allows to execute them) is expected to fail during this time window.

[zhipeng liu (zhipengs)]

Hi Alex,

Any further proposal for this ticket?

Thanks!
Zhipeng

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

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

commit 783ed056966344b4c3a715bae470a149798957d1
Author: Alex Kozyrev <email address hidden>
Date: Thu Sep 12 12:07:54 2019 -0400

    Move Helm chart repo refresh from Sysinv conductor to agent

    sysinv-conductor is stuck for 2 minutes during startup and unable to
    handle any RPC requests. The refresh_helm_repo_information() function
    executes “sudo -u sysadmin helm repo update” and waits for it.
    Helm tries to reach external repo and timeouts after 2 minutes.
    Any command (since sysinv-api is up and allows to execute them)
    is expected to fail during this time window. Unblock conductor by
    moving actual "helm repo update" invokation to sysinv agent.
    Let conductor make a RPC call instead. And remove helm refresh from
    conductor init - this would be called as part of application upload.

    Change-Id: I29249146eaaebfe51a0f67e3ffaae9ce48784107
    Closes-Bug: 1839665
    Signed-off-by: Alex Kozyrev <email address hidden>

[Yang Liu (yliu12)]

Have not seen this issue in daily sanity for the past 2 weeks.