<html xmlns:v="urn:schemas-microsoft-com:vml" xmlns:o="urn:schemas-microsoft-com:office:office" xmlns:w="urn:schemas-microsoft-com:office:word" xmlns:m="http://schemas.microsoft.com/office/2004/12/omml" xmlns="http://www.w3.org/TR/REC-html40">
<head>
<meta http-equiv="Content-Type" content="text/html; charset=us-ascii">
<meta name="Generator" content="Microsoft Word 15 (filtered medium)">
<style><!--
/* Font Definitions */
@font-face
        {font-family:"Cambria Math";
        panose-1:2 4 5 3 5 4 6 3 2 4;}
@font-face
        {font-family:DengXian;
        panose-1:2 1 6 0 3 1 1 1 1 1;}
@font-face
        {font-family:Calibri;
        panose-1:2 15 5 2 2 2 4 3 2 4;}
@font-face
        {font-family:"\@DengXian";
        panose-1:2 1 6 0 3 1 1 1 1 1;}
/* Style Definitions */
p.MsoNormal, li.MsoNormal, div.MsoNormal
        {margin:0in;
        font-size:11.0pt;
        font-family:"Calibri",sans-serif;}
a:link, span.MsoHyperlink
        {mso-style-priority:99;
        color:#0563C1;
        text-decoration:underline;}
span.EmailStyle19
        {mso-style-type:personal-reply;
        font-family:"Calibri",sans-serif;
        color:windowtext;}
.MsoChpDefault
        {mso-style-type:export-only;
        font-size:10.0pt;}
@page WordSection1
        {size:8.5in 11.0in;
        margin:1.0in 1.0in 1.0in 1.0in;}
div.WordSection1
        {page:WordSection1;}
--></style><!--[if gte mso 9]><xml>
<o:shapedefaults v:ext="edit" spidmax="1026" />
</xml><![endif]--><!--[if gte mso 9]><xml>
<o:shapelayout v:ext="edit">
<o:idmap v:ext="edit" data="1" />
</o:shapelayout></xml><![endif]-->
</head>
<body lang="EN-US" link="#0563C1" vlink="#954F72" style="word-wrap:break-word">
<div class="WordSection1">
<p class="MsoNormal">Hi<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">I make a summary.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">The root cause is, there is a timer in mgr-restful-plugin to check ceph-mgr readiness, and there is a timer in service manager to audit mgr-restful-plugin. These two timer timeout setting doesn’t match or not properly calibrated.<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Thanks!<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<div>
<p class="MsoNormal">Martin, Chen<o:p></o:p></p>
<p class="MsoNormal">IOTG, Software Engineer<o:p></o:p></p>
<p class="MsoNormal">021-61164330<o:p></o:p></p>
</div>
<p class="MsoNormal"><o:p> </o:p></p>
<div>
<div style="border:none;border-top:solid #E1E1E1 1.0pt;padding:3.0pt 0in 0in 0in">
<p class="MsoNormal"><b>From:</b> Chen, Haochuan Z <br>
<b>Sent:</b> Friday, April 30, 2021 3:26 PM<br>
<b>To:</b> Church, Robert <Robert.Church@windriver.com>; Qian, Bin <Bin.Qian@windriver.com><br>
<b>Cc:</b> starlingx-discuss@lists.starlingx.io<br>
<b>Subject:</b> LP1918420 issue debug and fix solution proposal<o:p></o:p></p>
</div>
</div>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">Hi Bob and Qian bin<o:p></o:p></span></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">I check this issue, describe the fail reason. You can download the log file to check<o:p></o:p></span></p>
<p class="MsoNormal"><a href="https://bugs.launchpad.net/starlingx/+bug/1918420">https://bugs.launchpad.net/starlingx/+bug/1918420</a><o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">log file<o:p></o:p></span></p>
<p class="MsoNormal"><a href="https://bugs.launchpad.net/starlingx/+bug/1918420/+attachment/5493137/+files/ALL_NODES_20210428.182915.tar">https://bugs.launchpad.net/starlingx/+bug/1918420/+attachment/5493137/+files/ALL_NODES_20210428.182915.tar</a><o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">In the above log file, at 14:19, controller-0 reboot, at this time controller-0 is active. Then controller-1 begin to swact to active.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:12.0pt">From controller-1 sm.log file, sm on controller-1 enable services, and launch enabled service audit. but mgr-restful-plugin audit fail.<o:p></o:p></span></p>
<p class="MsoNormal"><i>2021-04-28T15:19:50.000 controller-1 sm: debug time[993.980] log<816> INFO: sm[91418]: sm_node_swact_monitor.cpp(37):
<b><span style="color:red">Swact update: controller-1 is now active</span></b><o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:50.000 controller-1 sm: debug time[993.980] log<817> INFO: sm[91418]: sm_node_swact_monitor.cpp(57): Swact has completed successfully.<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:50.000 controller-1 sm: debug time[993.980] log<818> INFO: sm[91418]: sm_service_group_fsm.c(904): Service group (vim-services) was in the go-active state and is now in the active state.<o:p></o:p></i></p>
<p class="MsoNormal"><i>…<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:51.000 controller-1 sm: debug time[994.849] log<820> INFO: sm[91418]: sm_main_event_handler.c(170): Set node (controller-1) requested, action=2, admin_state=unlocked, oper_state=enabled, avail_status=available, seqno=1.<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:51.000 controller-1 sm: debug time[995.073] log<821> INFO: sm[91418]: sm_main_event_handler.c(170): Set node (controller-0) requested, action=2, admin_state=unlocked, oper_state=enabled, avail_status=available, seqno=2.<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:51.000 controller-1 sm: debug time[995.329] log<822> INFO: sm[91418]: sm_service_audit.c(176): Action (audit-enabled) timeout with result (failed), state (unknown), status (unknown), and condition (unknown) for service
 (mgr-restful-plugin), reason_text=, exit_code=-65534.<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:51.000 controller-1 sm: debug time[995.329] log<823> INFO: sm[91418]: sm_service_action.c(345): Aborting service (mgr-restful-plugin) with kill signal, pid=527592.<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:51.000 controller-1 sm: debug time[995.329] log<824> INFO: sm[91418]: sm_service_audit.c(75):
<b><span style="color:red">Max retires not met for action (audit-enabled) of service (mgr-restful-plugin), attempts=1</span></b>.<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:19:51.000 controller-1 sm: debug time[995.330] log<825> ERROR: sm[91418]: sm_service_audit.c(227): Failed to query service based on pid (527592), error=NOT_FOUND.<o:p></o:p></i></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">From controller-1, mgr-restful-plugin.log, at 15:19:51, we could find as just swact, “ceph mgr services list –format json”, will still return link
<a href="https://controller-0:7999">https://controller-0:7999</a>”, (it will take a while then return “controller-1:7999”)<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:12.0pt">As at this time controller-0 is rebooting, so mgr-restful-plugin ping to ceph mgr service doesn’t work. This makes sm audit fail<o:p></o:p></span></p>
<p class="MsoNormal"><i>2021-04-28 15:19:47,994 99448 WARNING mgr-restful-plugin REST API ping failed: reason=HTTPSConnectionPool(host=<b><span style="color:red">'controller-0'</span></b>, port=7999): Max retries exceeded with url: / (Caused by ConnectTimeoutError(<urllib3.connection.VerifiedHTTPSConnection
 object at 0x7f4d0cd23e90>, 'Connection to controller-0 timed out. (connect timeout=15)'))<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:19:47,994 99448 INFO mgr-restful-plugin REST API ping failure count=0<o:p></o:p></i></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">After 2 times audit fail, sm will disable all service and try to swact to controller-0, but as controller-0 is still doesn’t recovery, so sm always make such loop, enable service and disable service.<o:p></o:p></span></p>
<p class="MsoNormal"><i>2021-04-28T15:22:30.000 controller-1 sm: debug time[1153.993] log<1678> INFO: sm[91418]: sm_service_domain_filter.c(338): Uncontrolled swact start<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:22:30.000 controller-1 sm: debug time[1153.993] log<1679> INFO: sm[91418]: sm_node_swact_monitor.cpp(29): Swact has started, host will be standby<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:22:30.000 controller-1 sm: debug time[1153.993] log<1680> INFO: sm[91418]: sm_service_domain_filter.c(338): Uncontrolled swact start<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:22:30.000 controller-1 sm: debug time[1153.993] log<1681> INFO: sm[91418]: sm_node_swact_monitor.cpp(29): Swact has started, host will be standby<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:22:30.000 controller-1 sm: debug time[1153.993] log<1682> INFO: sm[91418]: sm_service_domain_filter.c(338): Uncontrolled swact start<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28T15:22:30.000 controller-1 sm: debug time[1153.993] log<1683> INFO: sm[91418]: sm_node_swact_monitor.cpp(29): Swact has started, host will be standby</i><o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">In such short period, user make request to sysinv-conductor to remove system application,  as cluster-host-ip service is disabled by sm, application remove fail.<o:p></o:p></span></p>
<p class="MsoNormal"><i>sysinv 2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes [-] Exception generating bootstrap token: CalledProcessError: Command '['kubeadm', '--kubeconfig=/etc/kubernetes/admin.conf', 'config', 'view']' returned non-zero
 exit status 1<o:p></o:p></i></p>
<p class="MsoNormal"><i>sysinv 2021-04-28 15:35:21.663 1072608 WARNING sysinv.conductor.kube_app [-] Failed to clear Armada locks.: MaxRetryError: HTTPSConnectionPool(host=<b><span style="color:red">'192.168.206.1'</span></b>, port=6443): Max retries exceeded
 with url: /apis/armada.process/v1/namespaces/kube-system/locks/locks.armada.process.lock (Caused by NewConnectionError('<urllib3.connection.VerifiedHTTPSConnection object at 0x7fb256c28650>: Failed to establish a new connection: [Errno 111] ECONNREFUSED',))<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes Traceback (most recent call last):<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes   File "/usr/lib64/python2.7/site-packages/sysinv/puppet/kubernetes.py", line 168, in _get_kubernetes_join_cmd<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes     subprocess.check_call(cmd, stdout=f)  # pylint: disable=not-callable<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes   File "/usr/lib64/python2.7/subprocess.py", line 542, in check_call<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes     raise CalledProcessError(retcode, cmd)<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes CalledProcessError: Command '['kubeadm', '--kubeconfig=/etc/kubernetes/admin.conf', 'config', 'view']' returned non-zero exit status 1<o:p></o:p></i></p>
<p class="MsoNormal"><i>2021-04-28 15:35:27.492 1072608 ERROR sysinv.puppet.kubernetes<o:p></o:p></i></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">In mgr-restful-plugin.py, the timer to check ceph-mgr service ready, it will count 5, timeout 15s and if fail, wait 3s and check again.<o:p></o:p></span></p>
<p class="MsoNormal"><span style="font-size:12.0pt">In sm, audit mgr-restful-plugin, timeout attempt 2 times, timeout 15s, smaller than above timeout setting. Propose in sm, timeout change to 20s(longer than 15s+3s), change timeout attempt change to 3 times.
<o:p></o:p></span></p>
<p class="MsoNormal"><i>INSERT INTO "SERVICE_ACTIONS" VALUES('mgr-restful-plugin','audit-enabled','lsb-script','','mgr-restful-plugin','status','',2,2,2,15,40);<o:p></o:p></i></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal"><span style="font-size:12.0pt">My patch for your idea.<o:p></o:p></span></p>
<p class="MsoNormal"><a href="https://review.opendev.org/c/starlingx/ha/+/788897">https://review.opendev.org/c/starlingx/ha/+/788897</a><o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Thanks!<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
<p class="MsoNormal">Martin, Chen<o:p></o:p></p>
<p class="MsoNormal">IOTG, Software Engineer<o:p></o:p></p>
<p class="MsoNormal">021-61164330<o:p></o:p></p>
<p class="MsoNormal"><o:p> </o:p></p>
</div>
</body>
</html>