Fail to upgrade vcenter from 7.0u2 to 7.0u3c

vCenter 업그레이드 시도 시 오류 발생하는 현상에 대해서 다뤄봅니다.

## vCenter 7.0

 

vCenter를 업그레이드 할 때 다음과 같은 오류 메시지와 함께 실패하는 이슈가 있었습니다.

사실 이런 메시지가 발생하면, 어디에서 오류가 유발되었는지 바로 알아내기는 어렵습니다.

 

오늘은 업그레이드 실패 시 vCenter에서 어떠한 로그들을 봐야하는지 살펴보는 시간이 되겠습니다.

 

우선, 가장 먼저 Patch 관련 로그인 /storage/log/vmware/applmgmt/PatchRunner.log 파일을 확인합니다.

## /storage/log/vmware/applmgmt/PatchRunner.log

로그를 확인해보면, 설치 마무리 시점에 모든 서비스를 재시작 하게 되는데, 이번 케이스의 경우에는 vmware-vpxd 서비스가 정상적으로 시작되지 못하는 것을 볼 수 있습니다.

2022-11-01T04:07:08.14Z INFO __main__ Start executing Discovery of vCSA patching components with following arguments 'PatchRunner.py discovery -o /tmp/tmpjd7kdh1h -d /storage/core/software-update/updates/7.0.3.01000/patch_runner --disableStdoutLogging' ... 2022-11-01T04:21:55.930Z INFO service_manager Starting service 'vmware-vpxd' ... 2022-11-01T04:21:55.930Z INFO service_manager Executing command '[['/bin/service-control', '--start', 'vmware-vpxd']]' 2022-11-01T04:21:59.689Z INFO service_manager Command '[['/bin/service-control', '--start', 'vmware-vpxd']]' has exit-code='1' and stdout: Operation not cancellable. Please wait for it to finish... Performing start operation on service vpxd... stderr: Error executing start on service vpxd. Details {     "detail": [         {             "id": "install.ciscommon.service.failstart",             "translatable": "An error occurred while starting service '%(0)s'",             "args": [                 "vpxd"             ],             "localized": "An error occurred while starting service 'vpxd'"         }     ],     "componentKey": null,     "problemId": null,     "resolution": null } Service-control failed. Error: {     "detail": [         {             "id": "install.ciscommon.service.failstart",             "translatable": "An error occurred while starting service '%(0)s'",             "args": [                 "vpxd"             ],             "localized": "An error occurred while starting service 'vpxd'"         }     ],     "componentKey": null,     "problemId": null,     "resolution": null } ... 2022-11-01T04:22:00.919Z WARNING root stopping status aggregation... 2022-11-01T04:22:00.920Z ERROR __main__ Patch vCSA failed 2022-11-01T04:25:15.595Z INFO __main__ Start executing Discovery of vCSA patching components with following arguments 'PatchRunner.py discovery -o /tmp/tmpu27o9r9u -d /storage/seat/software-updatem_ombvwz/stage/patch_runner --disableStdoutLogging' 2022-11-01T04:25:15.599Z INFO vmware_b2b.patching.phases.discoverer This is a Resume Flow, skipping running Discovery hook again 2022-11-01T04:25:15.600Z ERROR __main__ Discovery of vCSA patching components failed

 

그렇다면, 왜 vmware-vpxd 서비스가 정상적으로 시작되지 못했느냐를 확인해야 합니다.

vmware-vpxd 는 아직 서비스가 올라오지 않았기 때문에 vpxd.log를 봐도 해당 시점의 내용은 남아 있지 않습니다.

여기서는 /var/log/firstboot/vpxd_update.log 에서 관련된 내용을 파악할 수 있습니다.

## /var/log/firstboot/vpxd_update.log

해당 로그를 살펴보면, vpxd를 loookupservice에 다시 등록을 시도할 때 문제가 발생하고 있습니다.

2022-11-01T04:21:56.673Z INFO vpxd_update Start vpxd-prop update 2022-11-01T04:21:56.728Z INFO vpxd_update Invoking resourcebundle generation... 2022-11-01T04:21:56.729Z INFO vpxd_update Initiating catalog.zip creation process 2022-11-01T04:21:58.368Z INFO vpxd_update Successfully generated the catalog.zip file 2022-11-01T04:21:58.368Z INFO vpxd_update Replacing vpxd-service-spec.prop with vpxd-service-spec.prop.rpmnew... 2022-11-01T04:21:58.371Z INFO vpxd_update Search Lookup service for VPXD with serviceId: 564510ab-8728-4412-a1a2-bf429ca1c4d0 2022-11-01T04:21:58.384Z INFO vpxd_update Found service registration for VPXD in Lookup service 2022-11-01T04:21:58.384Z INFO vpxd_update Invoking Component Manager registration 2022-11-01T04:21:58.608Z ERROR vpxd_update VMware vCenter server patch failed. VPXD re-registration with Lookup Service failed. Exception: (vmodl.fault.SystemError) {    dynamicType = <unset>,    dynamicProperty = (vmodl.DynamicProperty) [],    msg = 'LookupFaultServiceFault',    faultCause = <unset>,    faultMessage = (vmodl.LocalizableMessage) [],    reason = 'Invalid fault' }

 

LookupFaultServiceFault 메시지를 확인했기 때문에 다음으로는 lookupservice 관련하여 확인을 해보겠습니다.

## var/log/vmware/lookupsvc/lookupserver-default.log

아래 로그를 보시면, 389 포트는 LDAP 서비스를 Listening 하는 포트인데 이 포트로 LDAP 관련 처리가 실패하는 것을 알 수 있습니다.

그렇다면, vCenter에서 누가 LDAP 서비스를 담당하고 있을까요? 즉, 389 포트로 Listening 하고 있는 프로세스는 무엇일까요? 답은 vmdird 프로세스 입니다. 

이제는 vmdird 프로세스를 확인해 볼 차례입니다.

[2022-11-01T04:21:28.923Z pool-2-thread-5                                                           WARN  com.vmware.sso.interop.ldap.LdapErrorChecker] Error received by LDAP client: com.vmware.sso.interop.ldap.OpenLdapClientLibrary, error code: 53 [2022-11-01T04:21:28.925Z pool-2-thread-5                                                           ERROR com.vmware.vim.lookup.impl.LdapStorage] LDAP action failed; host=vc01.contoso.com, port=389 com.vmware.sso.interop.ldap.UnwillingToPerformLdapException: Server is unwilling to perform         at com.vmware.sso.interop.ldap.LdapErrorChecker$32.RaiseLdapError(LdapErrorChecker.java:467) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapErrorChecker.CheckError(LdapErrorChecker.java:863) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.OpenLdapClientLibrary.CheckError(OpenLdapClientLibrary.java:1219) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.OpenLdapClientLibrary.ldap_delete_s(OpenLdapClientLibrary.java:1071) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapConnection$8.call(LdapConnection.java:813) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapConnection$8.call(LdapConnection.java:810) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapConnection.execute(LdapConnection.java:715) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapConnection.deleteObjectTreeInternal(LdapConnection.java:809) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapConnection.deleteObjectTreeInternal(LdapConnection.java:802) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapConnection.deleteObjectTreeInternal(LdapConnection.java:802) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.sso.interop.ldap.LdapConnection.deleteObjectTree(LdapConnection.java:642) ~[ldap-lib-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.LdapStorage.deleteServiceEntry(LdapStorage.java:1061) ~[lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.LdapStorage$8.action(LdapStorage.java:585) ~[lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.LdapStorage$8.action(LdapStorage.java:575) ~[lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.LdapStorage$LdapQuery.execute(LdapStorage.java:2286) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.LdapStorage.update(LdapStorage.java:590) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.LdapStorage.update(LdapStorage.java:567) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.ServiceRegistrationImpl.set(ServiceRegistrationImpl.java:105) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.impl.ServiceRegistrationImpl.set(ServiceRegistrationImpl.java:99) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.vlsi.ServiceRegistrationImpl$6.call(ServiceRegistrationImpl.java:204) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.vlsi.ServiceRegistrationImpl$6.call(ServiceRegistrationImpl.java:175) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.vlsi.util.VmodlEnhancer.invokeVmodlMethod(VmodlEnhancer.java:67) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at com.vmware.vim.lookup.vlsi.ServiceRegistrationImpl.set(ServiceRegistrationImpl.java:175) [lookupservice-impl-0.0.1-SNAPSHOT.jar:?]         at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_321]         at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_321]         at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_321]         at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_321]         at com.vmware.vim.vmomi.server.impl.InvocationTask.run(InvocationTask.java:99) [vlsi-server-7.0.0-SNAPSHOT.jar:?]         at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_321]         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_321]         at java.lang.Thread.run(Thread.java:748) [?:1.8.0_321]

 

## var/log/vmware/vmdird/vmdird-syslog.log

vmdird 프로세스 관련 로그를 살펴보니, lookupservice에서 봤던 로그와 유사한 내용이 남아 있습니다.

아래 보시면, "(LDAP_UNWILLING_TO_PERFORM(53)" 로그가 보이는데 이는 lookupservice 로그에 남아 있던 "Server is unwilling to perform" 내용과 동일합니다.

조금 더 살펴보면, 왜 LDAP이 정상 동작하지 않고 있느냐를 알려주는데 그 이유는 현재 Directory(vmdird) 상태가 READ-ONLY 이기 때문입니다.

즉, Directory 쪽으로 LDAP 관련 Modify 요청이 있었는데 Directory 상태가 READ-ONLY 였기 때문에 처리가 될 수 없었던 것입니다.

가장 첫 번째 줄에 있는 USN 넘버로 유추하건데 다른 Directory를 서비스하는 vCenter와의 ELM 환경에서 Replication 중간에 vCenter가 복구가 되었거나 했을 수가 있습니다.

max USN은 1088444를 가리키는데 현재 처리한 USN이 1090970이기 때문에 올바른 상태라고 볼 수 없습니다.

2022-11-01T04:20:50.568783+00:00 err vmdird  t@139881321826048: ParseSyncRequestControlVal: ServerId f04a2d4e-f173-4534-98b0-fc7650645df1 has processed my USN (1090970), my max USN is (1088844). 2022-11-01T04:20:50.572111+00:00 err vmdird  t@139881321826048: ParseSyncRequestControlVal: To prevent data loss, vmdir will be set to READ-ONLY mode , retVal [-1], errCode [53] 2022-11-01T04:20:59.145828+00:00 err vmdird  t@139881321826048: InternalModifyEntry: VdirExecutePostModifyCommitPlugins - code(9114) 2022-11-01T04:20:59.145853+00:00 err vmdird  t@139881321826048: VmDirSendLdapResult: Request (Modify), Error (LDAP_UNWILLING_TO_PERFORM(53)), Message (Server in read-only mode), (0) socket (127.0.0.1) 2022-11-01T04:21:01.726818+00:00 err vmdird  t@139881363789568: _VmDirConsumePartner: vmdir is in READ_ONLY state

 

그렇다면, 실제로 Directory가 READ-ONLY 상태인가를 확인해 볼 필요가 있습니다.

vCenter는 Directory 상태를 확인할 수 있는 도구로 /usr/lib/vmware-vmdir/bin/vdcadmintool 를 제공합니다.

해당 도구를 vCenter에서 실행해서 6번 메뉴를 이용하면 상태를 확인할 수 있습니다.

root@vc-sitea [ ~ ]# /usr/lib/vmware-vmdir/bin/vdcadmintool ================== Please select: 0. exit 1. Test LDAP connectivity 2. Force start replication cycle 3. Reset account password 4. Set log level and mask 5. Set vmdir state 6. Get vmdir state 7. Get vmdir log level and mask ==================

 

문제가 되었던 vCenter에서는 vmdir state가 실제로 Normal이 아닌, "VmDir State is - Read only" 로 표시되는 것을 확인할 수 있었습니다.

 

추가로 고객사 환경은 총 3대의 vCenter가 Linked Mode로 연결이 되어 있었기 때문에 각 vCenter간 복제 상태에 대해서도 확인할 필요가 있어 이 부분도 확인을 하였습니다.

이는 /usr/lib/vmware-vmdir/bin/vdcrepadmin 도구를 이용하면 알 수 있으며, 해당 결과는 아래와 같이 vCenter 3대를 각각 vc01, vc02, vc03 이라고 했을 때, vc01과 vc02, vc03간의 복제 상태가 모두 정상적이지 않았습니다. 

반면에 vc02와 vc03에서 vc01로의 복제 상태는 정상으로 표현되어 있습니다.

root@vc01 [ ~ ]# /usr/lib/vmware-vmdir/bin/vdcrepadmin -f showpartnerstatus -h localhost -u administrator password: Partner: vc02.contoso.com Host available:   Yes Status available: No Partner: vc03.contoso.com Host available:   Yes Status available: No root@vc02 [ ~ ]# /usr/lib/vmware-vmdir/bin/vdcrepadmin -f showpartnerstatus -h localhost -u administrator password: Partner: vc01.contoso.com Host available:   Yes Status available: Yes My last change number:             941006 Partner has seen my change number: 935006 Partner is 6000 changes behind. root@vc03 [ ~ ]# /usr/lib/vmware-vmdir/bin/vdcrepadmin -f showpartnerstatus -h localhost -u administrator password: Partner: vc03.contoso.com Host available:   Yes Status available: Yes My last change number:             948895 Partner has seen my change number: 947773 Partner is 1122 changes behind.

 

이제 문제의 원인이 어디서 유발되었고, 상태 정보를 확인하였기 때문에 어떻게 문제를 해결해야 하는지를 고민해야 합니다.

이 케이스의 경우에는 우선 복제 상태를 정상화 시키는 것이 우선이었기 때문에 기존 문제가 되는 복제 연결을 초기화하고 다시 기존과 동일하게 복제 연결을 생성해주는 방향으로 접근하였습니다.

해당 작업 순서가 다소 복잡하나, VMware 내부에서는 이를 Script로 제공하고 있어 고객사에서는 해당 Script를 이용하여, vc01의 복제 연결을 제거하고 vc01 ↔ vc02 간의 복제 연결을 다시 생성하였으며, 이 후 동일하게 vc01 ↔ vc03 간의 복제 연결도 마찬가지로 생성해주었습니다.

## 실 작업은 VMware GSS 를 통해 Script를 제공받으시어 진행하실 것을 권고 드립니다.

 

해당 작업을 모두 완료하고 나서 모든 vCenter의 Directory 상태와 복제 파트너 간 상태를 조회하면 모두 정상적으로 돌아온 것을 알 수 있습니다.

이 상태에서 업그레이드 실패한 vCenter에서 다시 업그레이드를 진행하여 정상적으로 업그레이드가 완료되었습니다.

 

오늘은 vCenter 업그레이드 실패가 Directory 서비스의 상태 문제로 인해서도 영향 받을 수 있다는 것을 알 수 있는 기회였습니다.

향후에도 vCenter 업그레이드가 실패할 때, 단순히 UI에서 나오는 메시지만을 가지고 Research 하는 것이 아닌, 정확히 어떤 부분에서 업그레이드가 실패했는지를 추적해 볼 수 있는 사례가 되길 바랍니다.