vsan-health service was not able to start

vsan-health 서비스가 남기는 로그의 rotation이 올바르게 동작하지 않는 경우, vsan-health 서비스를 중지했다가 다시 실행할 때 시작이 안되는 경우에 대해 소개합니다.

## vCenter 7.0

 

[문제 증상]

vCenter의 MACHINE_SSL 인증서 만료로 인해, 수동으로 인증서를 교체한 후 vCenter 서비스를 종료했다가 다시 시작한 후

1) vCenter의 vROPS, vSAN 관련 Plug-in의 상태가 실패로 표시되고,

 

2) VM을 생성할 때 vSAN Storage Policy를 사용 및 조회를 할 수 없는 상황이 발생했습니다.

 

[분석 내역]

1. 우선, UI에서 Plug-in 상태가 실패로 보이기 때문에 이를 확인하기 위해 UI 관련 로그가 기록되는 vsphere_client_virgo.log 파일을 살펴봅니다.

해당 로그를 살펴보면, 다음과 같이 PluginDownloadException 관련 Call Stack이 기재되어 있습니다.

로그만 보면, https://vcenter.contoso.com:443/ui/plugins/h4va.zip를 다운로드 시도할 때 HTTP Response Code 401 에러를 Return 받는 것으로 확인됩니다.

UI 로그만 보면, Plug-in 관련 파일을 다운로드 시도하기 위해서 vCenter에 접근할 때, 인증 관련 오류가 발생하고 이는 서버 인증서가 올바르지 않은 것으로 추정됩니다.

## /var/log/vmware/vsphere-ui/logs/vsphere_client_virgo.log [2022-12-05T07:48:43.133Z] [ERROR] plugin-discovery-bus-thread  70005754 100260 200011 c.v.v.p.discovery.directory.impl.DirectoryExtensionManagerImpl    Error while waiting for plugin package to deploy. java.util.concurrent.ExecutionException: com.vmware.vise.plugin.download.PluginDownloadException: java.io.IOException: Server returned HTTP response code: 401 for URL: https://vcenter.contoso.com:443/ui/plugins/h4va.zip         at java.util.concurrent.FutureTask.report(FutureTask.java:122)         at java.util.concurrent.FutureTask.get(FutureTask.java:192)         at com.vmware.vise.util.concurrent.QueuingCachedThreadPool$ExpiringTask.get(QueuingCachedThreadPool.java:1638)         at com.vmware.vise.plugin.discovery.directory.impl.DirectoryExtensionManagerImpl.waitForPackagesToDeploy(DirectoryExtensionManagerImpl.java:284)         at com.vmware.vise.plugin.discovery.directory.impl.DirectoryExtensionManagerImpl.deployPackages(DirectoryExtensionManagerImpl.java:265)         at com.vmware.vise.plugin.discovery.directory.impl.DirectoryExtensionManagerImpl.deployNewPackages(DirectoryExtensionManagerImpl.java:156)         at com.vmware.vise.plugin.discovery.impl.PluginDiscoveryAgent.deployNewPackages(PluginDiscoveryAgent.java:104)         at com.vmware.vise.plugin.discovery.impl.PluginDiscoveryAgent.deployNewPackages(PluginDiscoveryAgent.java:88)         at com.vmware.vise.plugin.discovery.impl.PluginDiscoveryAgent.onPluginDiscoveryOnLoginRequest(PluginDiscoveryAgent.java:63)         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)         at java.lang.reflect.Method.invoke(Method.java:498)         at com.google.common.eventbus.Subscriber.invokeSubscriberMethod(Subscriber.java:87)         at com.google.common.eventbus.Subscriber$SynchronizedSubscriber.invokeSubscriberMethod(Subscriber.java:144)         at com.google.common.eventbus.Subscriber$1.run(Subscriber.java:72)         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)         at java.lang.Thread.run(Thread.java:748) <snippet> [2022-12-05T07:48:43.076Z] [ERROR] async-task-executor-pool-600  com.vmware.vise.extensionfw.plugins.impl.PluginStatusServiceImpl  DOWNLOAD_FAILED: Error downloading plugin package com.vmware.vsphere.client.h5vsan:7.0.2.200 from https://vcenter.contoso.com:443/vsanHealth/plugins/vsan-h5-client.zip. Reason: Download error. Make sure that the URL is reachable and the thumbprint is correct. [2022-12-01T14:35:18.492Z] [ERROR] async-task-executor-pool-249  com.vmware.vise.vim.extension.VcExtensionManager                  Downloading plugin package: 'com.vmware.vrops.install:7.0.2.200' registered in vCenter: 'PCLCSA01.POSCO.NET (70a994c4-ee0f-418c-aa88-6e54a79addbe)' has failed. java.util.concurrent.CompletionException: com.vmware.vise.plugin.download.PluginDownloadException: j avax.net.ssl.SSLHandshakeException: Server certificate chain is not trusted and thumbprint doesn't match

 

2. 이에 1차적인 Action Plan으로 인증서를 다시 갱신해봤으나, 문제 증상이 달라지지 않는 것을 확인했습니다.

 

3. 다음으로 문제가 되었던 vCenter에서 시작되어야 하는 서비스인 "vmware-vsan-health" 서비스가 중지되어 있는 것으로 확인되어 왜 해당 서비스가 정상적으로 시작되지 못했는지 분석을 진행하였습니다.

## service-control --status -all Running:  applmgmt lookupsvc lwsmd observability observability-vapi pschealth vlcm vmafdd vmcad vmdird vmonapi vmware-analytics vmware-certificateauthority vmware-certificatemanagement vmware-cis-license vmware-content-library vmware-eam vmware-envoy vmware-hvc vmware-infraprofile vmware-perfcharts vmware-pod vmware-postgres-archiver vmware-rhttpproxy vmware-sca vmware-sps vmware-statsmonitor vmware-stsd vmware-topologysvc vmware-trustmanagement vmware-updatemgr vmware-vapi-endpoint vmware-vdtc vmware-vmon vmware-vpostgres vmware-vpxd vmware-vpxd-svcs vmware-vsm vsphere-ui vstats vtsdb wcp   Stopped:  vmcam vmware-imagebuilder vmware-netdumper vmware-rbd-watchdog vmware-vcha vmware-vsan-health

 

4. vmware-vsan-health 서비스를 수동으로 시작하면서 서비스 관련 로그를 살펴보면, 서비스가 정상적으로 시작 요청을 받았지만, 서비스 시작에 필요한 timeout 시간을 초과하면서 서비스가 종료되는 것을 확인할 수 있습니다.

 

## service-control --start vmware-vsan-health 2022-12-06T14:38:26.723Z| host-24788| I005: <vsan-health-healthcmd> Constructed command: /usr/bin/python /usr/lib/vmware-vpx/vsan-health/vsanhealth-vmon-apihealth.py 2022-12-06T14:38:26.967Z| host-24788| I005: <vsan-health> Re-check service health since it is still initializing. 2022-12-06T14:38:27.550Z| host-24788| I005: <vsan-health> Service start operation timed out. 2022-12-06T14:38:27.550Z| host-24788| W003: <vsan-health> Found empty StopSignal parameter in config file. Defaulting to SIGTERM 2022-12-06T14:38:27.552Z| host-24788| W003: <vsan-health> Service exited. Exit code 1

 

5. 로그를 확인하다보니, 특이한 점으로 몇 달 전에도 정상적으로 vmware-vsan-health 서비스가 시작되지 못한 내용이 있습니다.

해당 시점에 서비스 관련 rotation 로그 파일을 보니, 이상하게도 9월 19일자 로그 파일만 20M가 아닌 8.6G로 쌓여있는 것을 볼 수 있습니다.

또한, 케이스가 접수되었던 시점인 12월 5일에도 9월 19일처럼 로그 파일이 20M가 아닌 24G로 쌓여 있는 것이 확인됩니다.

## /var/log/vmware/cloudvm/service-control.log 2022-09-19T02:53:59.803Z INFO service-control ********** Start ['--start', 'vmware-vsan-health'] ********** 2022-09-19T02:53:59.806Z INFO service-control Perform start operation. vmon_profile=None, svc_names=['vmware-vsan-health'], include_coreossvcs=False, include_leafossvcs=False 2022-09-19T02:53:59.807Z INFO service-control Performing start operation on service vsan-health... 2022-09-19T02:53:59.900Z INFO service-control Successfully started service vsan-health 2022-09-19T02:56:23.754Z INFO service-control ********** Start ['--restart', 'vmware-vsan-health'] ********** 2022-09-19T02:56:23.756Z INFO service-control Perform restart operation. vmon_profile=None, svc_names=['vmware-vsan-health'], include_coreossvcs=False, include_leafossvcs=False 2022-09-19T02:58:22.441Z INFO service-control ********** Start ['--restart', 'vmware-vsan-health'] ********** 2022-09-19T02:58:22.443Z INFO service-control Perform restart operation. vmon_profile=None, svc_names=['vmware-vsan-health'], include_coreossvcs=False, include_leafossvcs=False 2022-09-19T02:58:22.491Z ERROR service-control Service-control failed. Error: Failed to restart service vsan-health. vmon-cli RC=5, stderr=Restart service request failed. Error: Operation not allowed in current service state 2022-09-19T03:02:09.219Z INFO service-control ********** Start ['--restart', 'vmware-vsan-health'] ********** 2022-09-19T03:02:09.221Z INFO service-control Perform restart operation. vmon_profile=None, svc_names=['vmware-vsan-health'], include_coreossvcs=False, include_leafossvcs=False 2022-09-19T03:02:09.256Z ERROR service-control Service-control failed. Error: Failed to restart service vsan-health. vmon-cli RC=5, stderr=Restart service request failed. Error: Operation not allowed in current service state 2022-09-19T03:05:55.272Z INFO service-control Successfully restarted service vsan-health 2022-09-19T03:05:55.276Z ERROR service-control Service-control failed. Error: [Errno 5] Input/output error ## /var/log/vmware/vsan-health  20M Aug 20 20:38 vmware-vsan-health-service-12625.log  20M Aug 20 22:28 vmware-vsan-health-service-12626.log  20M Aug 21 00:18 vmware-vsan-health-service-12627.log  20M Aug 21 02:08 vmware-vsan-health-service-12628.log  20M Aug 21 03:58 vmware-vsan-health-service-12629.log  20M Aug 21 05:43 vmware-vsan-health-service-12630.log  20M Aug 21 07:33 vmware-vsan-health-service-12631.log  20M Aug 21 09:08 vmware-vsan-health-service-12632.log 8.6G Sep 19 03:05 vmware-vsan-health-service-12633.log  20M Sep 19 04:38 vmware-vsan-health-service-12634.log  20M Sep 19 06:23 vmware-vsan-health-service-12635.log  20M Sep 19 07:59 vmware-vsan-health-service-12636.log  20M Sep 19 09:28 vmware-vsan-health-service-12637.log  20M Sep 19 11:08 vmware-vsan-health-service-12638.log  20M Sep 19 11:58 vmware-vsan-health-service-12639.log  20M Sep 19 13:11 vmware-vsan-health-service-12640.log  20M Sep 19 14:33 vmware-vsan-health-service-12641.log  20M Sep 19 15:48 vmware-vsan-health-service-12642.log  20M Sep 19 17:24 vmware-vsan-health-service-12643.log  20M Sep 19 19:04 vmware-vsan-health-service-12644.log  20M Sep 19 20:54 vmware-vsan-health-service-12645.log  20M Sep 19 22:39 vmware-vsan-health-service-12646.log  20M Sep 20 00:25 vmware-vsan-health-service-12647.log  20M Sep 20 02:09 vmware-vsan-health-service-12648.log  20M Sep 20 03:57 vmware-vsan-health-service-12649.log  20M Sep 20 05:49 vmware-vsan-health-service-12650.log  20M Sep 20 07:35 vmware-vsan-health-service-12651.log  20M Sep 20 09:14 vmware-vsan-health-service-12652.log  24G Dec  5 00:10 vmware-vsan-health-service.log

 

6. vmware-vsan-health 서비스의 rotation 설정 파일을 확인하였지만, 예상대로 올바르게 20M가 쌓이도록 되어 있었고 특이한 점을 확인하지 못하였습니다.

## /etc/vmware-vsan-health/logger.conf "vsanHealthFile":{     "backupCount":20,     "class":"logger.Handlers.VpxdStyleRotatingFileHandler",     "filename":"vmware-vsan-health-service",     "formatter":"vsanHealthFormatter",     "maxBytes":20971520,     "maxCount":100,     "maxTime":604800 },

 

7. 해당 내용을 Research 해본 결과, /var/log/vmware/vsan-health 폴더 하위에 있는 파일들은 vmware-vsan-health 서비스 시작 시에 없어도 무방한 파일들이었기 때문에 우선 문제 해결을 위해서 해당 폴더 하위에 있는 모든 파일을 제거하고 서비스를 시작하였고 다음과 같이 정상적으로 시작된 것을 확인하였습니다.

또한, vCenter에서 실패 상태로 조회되었던 Plug-in도 vmware-vsan-health 서비스가 올바르게 시작되고 나서 상태가 정상으로 변경되는 것도 확인되었습니다.

 

8. 결국은 vmware-vsan-health 서비스가 시작될 때, rotation 시마다 적재된 로그 파일들을 읽어들이는 과정에서 과도하게 크게 생성된 로그 파일 때문에 이를 읽는 과정에 시간이 오래 소요되게 되고 이로 인해 결국 지정된 timeout 내에 서비스가 시작되지 못한 것입니다.

 

9. 내부에서 추가 Research를 해보니, 두 가지 원인으로 인해 유사한 증상이 발생할 수 있습니다.

1) vCenter의 /storage/log filesystem의 용량이 부족하여, vmware-vsan-health 서비스 로그를 수동으로 지우는 경우, vmware-vsan-health 서비스 관련 python script 중 하나가 실행될 때, exception이 발생하면서 log rotation이 제대로 동작하지 않을 수 있습니다.

이 현상은 vCenter 7.0 U2c 에서 해결된 것으로 기술되어 있습니다.

VMware vCenter Server 7.0 Update 2c Release Notes https://docs.vmware.com/en/VMware-vSphere/7.0/rn/vsphere-vcenter-server-70u2c-release-notes.html vCenter Server services might fail due to full log directory In rare cases, if the vmware-vsan-health-service.log fails to rotate, vCenter Server services might fail when the log directory becomes full.  This issue is resolved in this release.

 

2) 두 번째로는 임의의 다른 프로세스가 vmware-vsan-health-service.log 파일을 접근하고 있는 경우, vmware-vsan-health 서비스의 log rotation 모듈이 rotation을 완료한 후 초기화된 vmware-vsan-health-service.log 파일을 생성해야 하는데 그렇지 못하는 경우가 있을 수도 있습니다.

 

오늘은 vCenter의 여러 필수 서비스 중 하나인 vmware-vsan-health 서비스 시작 시에 timeout으로 인해 실패하는 현상에 대해서 살펴봤습니다.

vmware-vsan-health-service.log는 rotation 설정에 따라서 주기적으로 20M 파일이 계속 생성되며 어떤 이유로 인해 해당 로그 파일의 rotation이 정상적으로 되지 않는 경우에 서비스 실패로 이어질 수 있습니다.