VMware Cloud Community
isantisteban
Contributor
Contributor
‎10-12-2021 01:18 PM

vcsa 7.0.2 does not allow creating backups, vcha service does not start

In early August, we changed the certificate for machine_ssl to use a hybrid environment at the certificate level. The vcsa backup has operated perfectly until October 9, taking the vcsa backup copies every day, from that day the vcha service does not work and manually starting it reports:

root@vcenter [ ~ ]# service-control --status
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-vsan-health vmware-vsm vsphere-ui vstats vtsdb wcp
Stopped:
vmcam vmware-imagebuilder vmware-netdumper vmware-rbd-watchdog vmware-vcha
root@vcenter [ ~ ]# service-control --start vmware-vcha
Operation not cancellable. Please wait for it to finish...
Performing start operation on service vcha...
Error executing start on service vcha. Details {
"detail": [
{
"id": "install.ciscommon.service.failstart",
"translatable": "An error occurred while starting service '%(0)s'",
"args": [
"vcha"
],
"localized": "An error occurred while starting service 'vcha'"
}
],
"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": [
"vcha"
],
"localized": "An error occurred while starting service 'vcha'"
}
],
"componentKey": null,
"problemId": null,
"resolution": null
}

But there is no clue that indicates what exactly happens, the service when launching it manually the service log says:

2021-10-12T18:43:57.797+02:00 - time the service was last started, Section for vCenterHA, pid=1727, version=7.0.2, build=18355781, option=Release
2021-10-12T18:43:57.784+02:00 none -[01727] [Originator@6876 sub=Default] 000055c965cba490
2021-10-12T18:43:57.791+02:00 info -[01727] [Originator@6876 sub=Default] Glibc malloc guards disabled.
2021-10-12T18:43:57.791+02:00 info -[01727] [Originator@6876 sub=Default] Initialized SystemFactory
2021-10-12T18:43:57.797+02:00 warning vcha[01727] [Originator@6876 sub=Default] Unrecognized log/level '' using 'info'
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=Default] Logging uses fast path: true
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=Default] The bora/lib logs WILL be handled by VmaCore
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=Default] Initialized channel manager
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=Default] Current working directory: /storage/log/vmware/vmon
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=ThreadPool] Catch work item exceptions disabled.
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=FairScheduler] Priority level 4 is now active.
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=WorkQueue.vmacoreDefaultIOCompletionQueue] Created: WorkQueue.vmacoreDefaultIOCompletionQueue, type = fair, priority = 4, itemWeight = 1
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=FairScheduler] Priority level 8 is now active.
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=WorkQueue.vmacoreDefaultIOQueue] Created: WorkQueue.vmacoreDefaultIOQueue, type = fair, priority = 8, itemWeight = 1
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=FairScheduler] Priority level 16 is now active.
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=WorkQueue.vmacoreDefaultLongTaskQueue] Created: WorkQueue.vmacoreDefaultLongTaskQueue, type = fair, priority = 16, itemWeight = 1
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=ThreadPool] Registered foreign worker - allocated: 1, idle: 0
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=ThreadPool] Registered foreign worker - allocated: 2, idle: 0
2021-10-12T18:43:57.797+02:00 info vcha[01727] [Originator@6876 sub=ThreadPool] Registered foreign worker - allocated: 3, idle: 0
2021-10-12T18:43:57.798+02:00 info vcha[01727] [Originator@6876 sub=ThreadPool] Registered foreign worker - allocated: 4, idle: 0
2021-10-12T18:43:57.799+02:00 info vcha[01768] [Originator@6876 sub=ThreadPool] Entering worker thread loop
2021-10-12T18:43:57.799+02:00 info vcha[01767] [Originator@6876 sub=ThreadPool] Entering worker thread loop
2021-10-12T18:43:57.801+02:00 info vcha[01769] [Originator@6876 sub=ThreadPool] Entering worker thread loop
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=ThreadPool] Thread pool fair initial threads spawned. IO: 2, Min workers: 4, Max workers: 13, Reservation ratio: 9
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Default] Syscommand enabled: true
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Default] ReaperManager Initialized
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Default] Setting up signal handlers
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/etc/vmware/config": No such file or directory.
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/etc/vmware/config": No such file or directory.
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /etc/vmware/config. Using default values.
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Libs] Could not expand environment variable HOME.
2021-10-12T18:43:57.801+02:00 info vcha[01727] [Originator@6876 sub=Libs] Could not expand environment variable HOME.
2021-10-12T18:43:57.801+02:00 info vcha[01772] [Originator@6876 sub=ThreadPool] Entering IO thread loop
2021-10-12T18:43:57.801+02:00 info vcha[01770] [Originator@6876 sub=ThreadPool] Entering worker thread loop
2021-10-12T18:43:57.801+02:00 info vcha[01773] [Originator@6876 sub=ThreadPool] Entering fair thread loop
2021-10-12T18:43:57.801+02:00 info vcha[01768] [Originator@6876 sub=ThreadPool] Spawning additional worker - allocated: 5, idle: 0
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/usr/lib/vmware/settings": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/settings": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /usr/lib/vmware/settings. Using default values.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "/usr/lib/vmware/config": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "/usr/lib/vmware/config": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] PREF Optional preferences file not found at /usr/lib/vmware/config. Using default values.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "~/.vmware/config": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "~/.vmware/config": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] PREF Optional preferences file not found at ~/.vmware/config. Using default values.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] DictionaryLoad: Cannot open file "~/.vmware/preferences": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] [msg.dictionary.load.openFailed] Cannot open file "~/.vmware/preferences": No such file or directory.
2021-10-12T18:43:57.802+02:00 info vcha[01727] [Originator@6876 sub=Libs] PREF Optional preferences file not found at ~/.vmware/preferences. Using default values.
2021-10-12T18:43:57.804+02:00 info vcha[01727] [Originator@6876 sub=Libs] lib/ssl: OpenSSL using FIPS_drbg for RAND
2021-10-12T18:43:57.804+02:00 info vcha[01727] [Originator@6876 sub=Libs] lib/ssl: protocol list tls1.2
2021-10-12T18:43:57.804+02:00 info vcha[01727] [Originator@6876 sub=Libs] lib/ssl: protocol list tls1.2 (openssl flags 0x17000000)
2021-10-12T18:43:57.804+02:00 info vcha[01727] [Originator@6876 sub=Libs] lib/ssl: cipher list ECDHE+AESGCM:RSA+AESGCM:ECDHE+AES:RSA+AES
2021-10-12T18:43:57.804+02:00 info vcha[01727] [Originator@6876 sub=Libs] lib/ssl: curves list prime256v1:secp384r1:secp521r1
2021-10-12T18:43:57.805+02:00 info vcha[01771] [Originator@6876 sub=ThreadPool] Entering IO thread loop
2021-10-12T18:43:57.805+02:00 info vcha[01774] [Originator@6876 sub=ThreadPool] Entering worker thread loop
2021-10-12T18:43:57.825+02:00 info vcha[01727] [Originator@6876 sub=Default] Vmacore::InitSSL: handshakeTimeoutUs = 20000000
2021-10-12T18:43:57.825+02:00 info vcha[01727] [Originator@6876 sub=Default] Service is running in FIPS mode.
2021-10-12T18:43:57.825+02:00 info vcha[01727] [Originator@6876 sub=Default] Creating SSL Contexts
2021-10-12T18:43:57.827+02:00 error vcha[01727] [Originator@6876 sub=Default] Failed to initialize the SSL context: N7Vmacore6Crypto15CryptoExceptionE(Crypto Exception: error:02001002:system library:fopen:No such file or directory: unable to load BIO)
--> [context]zKq7AVECAQAAAEUWGAEOdmNoYQAAcnY0bGlidm1hY29yZS5zbwAAAaopAAmfKgBDaS8AJF8lAGlqJQAOcyUAdHMlAUHYCHZjaGEAAbA+BgGMDgYBiZcFAlcrAmxpYmMuc28uNgABQQEG[/context]
2021-10-12T18:43:57.830+02:00 panic vcha[01727] [Originator@6876 sub=Default]
-->
--> Panic: Failed to initialize the SSL context.
--> Backtrace:
--> [backtrace begin] product: vCenterHA, version: 7.0.2, build: build-18355781, tag: vcha, cpu: x86_64, os: linux, buildType: release
--> backtrace[00] libvmacore.so[0x003477F7]
--> backtrace[01] libvmacore.so[0x0029AA2D]: Vmacore::System::Stacktrace::CaptureFullWork(unsigned int)
--> backtrace[02] libvmacore.so[0x002A9E47]: Vmacore::System::SystemFactory::CreateBacktrace(Vmacore::Ref<Vmacore::System::Backtrace>&)
--> backtrace[03] libvmacore.so[0x0033AA00]
--> backtrace[04] libvmacore.so[0x0033AB24]: Vmacore::PanicExit(char const*)
--> backtrace[05] libvmacore.so[0x002FE851]
--> backtrace[06] libvmacore.so[0x002FE8EF]
--> backtrace[07] vcha[0x0008DA22]
--> backtrace[08] vcha[0x00063EB0]
--> backtrace[09] vcha[0x00060E8C]
--> backtrace[10] vcha[0x00059789]
--> backtrace[11] libc.so.6[0x00022B57]
--> backtrace[12] vcha[0x00060141]
--> [backtrace end]

 

All certificates are valid and within their date of operations. There has been no system change or update.

Any idea how to reactivate the service? Thanks

Labels (2)
10 Replies
g3nrix
Contributor
Contributor
‎01-05-2022 04:18 AM

Same problem after upgrading cluster hosts. ESXi version_7.0.2-0.25.18538813. VCSA backup now doesn't work.

 
 

 

 

vcha-35.log
0 Kudos
balc50
Contributor
Contributor
‎06-02-2022 01:13 AM

And same exact error found in vcha log even on 7.0.3, build-19192837.

No fix found yet?

0 Kudos
g3nrix
Contributor
Contributor
‎06-02-2022 02:37 AM

You should have a snapshot of your vCenter VM by following the below steps:

    1. Access the Host Client from where the vCenter VM is running.
    2. Go to the vCenter VM and then "Actions" and "Take a snapshot"
    3. Make sure to keep the checkbox of "Take it with the Virtual Machine's memory"

Disable the VCHA service as it is not used on the vCenter using the below commands:

    1. cd /usr/lib/vmware-vmon
    2. vmon-cli -S DISABLED -U vcha

Retrying the backup resulted in an error: "Db health is UNHEALTHY, Backup Failed. Disable health check to take backup in current state." The solution presented at https://kb.vmware.com/s/article/86084 helped. The backup is now working

balc50
Contributor
Contributor
‎06-02-2022 03:11 AM

Thank you for reply, i tried and did them all steps, from snapshot to db check but in my case the vcha was always disabled (but ran the step also now) and also the backup config had the 'db health check' disabled - but anyway, i still got same message that "Invalid vCenter Server Status: All required services are not up! Stopped services: 'vcha' ".

The funny bit is that we have other vcsa and all other have vcha disabled and are at same build version yet none have this error for backup. I'll open a case with support when our contact guy will be back or see if latest update is applicable and maybe will 'cure' this vc.

0 Kudos
mdraz209
Contributor
Contributor
‎12-13-2022 08:25 AM

Just checking in to see if you have had any success with addressing this issue. I am now encountering it on 7.0.3.00800 with the exact same symptoms with the vcha service and the "Failed to initialize the SSL context" error in the logs. Thanks!

0 Kudos
Zarranto23
Contributor
Contributor
‎01-12-2023 05:52 AM

Hi any update on this topic @balc50 ? some Fix? i receive the same error after the the upgrade to 7.0 up 3j. 

Thanks  a lot

0 Kudos
gabrielqwe
Contributor
Contributor
‎01-13-2023 09:55 AM

Try this it should be fixed

 

https://www.stephenwagner.com/2021/10/10/vmware-vcsa-update-upgrade-backup-restore-tips-tricks/

0 Kudos
mdraz209
Contributor
Contributor
‎02-23-2023 02:17 PM

I appreciate the link but this does not have any information regarding the vcha service and the "Failed to initialize the SSL context" error in the logs.

This is still an ongoing issue that I will attempt to open a case with Support for and update here if I get any relevant information.

0 Kudos
mdraz209
Contributor
Contributor
‎03-08-2023 07:55 AM

I was able to get this resolved with the assistance of Support, however it's not really clear what caused the issue and support wasn't sure either. Here are the steps we took:

  1. Restart vCenter and try backing up again. If this doesn't work, then move on to the next steps.

 

  1. Open an SSH session to the vCenter
  2. Log in as root.
  3. Enter shell
  4. run: /usr/bin/dbcc -fbss embedded

* Note: For me, when I ran this command in #4, I was notified that the directory did not exist.

 

Next we cleared the backup history and scheduled backups.

  1. Open an SSH session to the vCenter
  2. Log in as root
  3. Enter Shell
  4. Run this command: cd /storage/applmgmt/backup_restore 
  5. Move 'backup-history.json' and 'backup_schedule.json' to a different location 
  6. Restart the VAMI backup, which should now complete.

* Note: I still was unable to run a backup after these steps. I was met with the same error.

 

I was then asked to reboot vCenter again and then try backing up. After rebooting, several services did not restart so I did the following:

  1. Opened an SSH session into vCenter again as root
  2. Entered Shell
  3. Ran: service-control --start --all
  4. Tried the backup again and this time it was successful.

Hope this helps anyone else that runs into this issue.

 

 

 

0 Kudos
isantisteban
Contributor
Contributor
‎04-11-2023 11:12 AM

I have hopefully tried following your instructions, but unfortunately the problems persist, specifically the problem is in the vcha service. These are the problems with forcing the vcha service to start:

service-control --start vmware-vcha

Operation not cancellable. Please wait for it to finish...

Performing start operation on service vcha...

Error executing start on service vcha. Details {

    "detail": [

        {

            "id": "install.ciscommon.service.failstart",

            "translatable": "An error occurred while starting service '%(0)s'",

            "args": [

                "vcha"

            ],

            "localized": "An error occurred while starting service 'vcha'"

        }

    ],

    "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": [

                "vcha"

            ],

            "localized": "An error occurred while starting service 'vcha'"

        }

    ],

    "componentKey": null,

    "problemId": null,

    "resolution": null

Interestingly, I discovered that the backup actually occurs, according to what the log gives me. I have verified it myself. But I can't detect where these backups are stored on the server while the remote transfer is taking place. That would at least give me the option of manually saving these backups, until I find a solution. Therefore, I rule out that the problem is really the backup and I focus on the vcha service, I don't understand what this service has to do with the vcenter backup itself.

This is a snippet of the backup log:

2023-04-11T19:32:23.393 [] [MainProcess:PID-31090] [VCDB::_estimate_size_partial_vcdb:VCDB.py:404] INFO: Estimated size of total data: 159642770.28353018

2023-04-11T19:32:23.393 [] [MainProcess:PID-31090] [VCDB::_estimate_size_partial_vcdb:VCDB.py:406] INFO: Calculating schema size.

2023-04-11T19:32:23.393 [] [MainProcess:PID-31090] [VCDB::_estimate_size_partial_vcdb:VCDB.py:409] INFO: Execute command: ['/opt/vmware/vpostgres/current/bin/pg_dump', '-U', 'postgres', '-d', 'VCDB', '-p', '5432', '-F', 'custom', '--compress', '0', '--schema-only']

2023-04-11T19:32:23.393 [] [MainProcess:PID-31090] [postgres_utils::CountCmdOutputSize:postgres_utils.py:153] INFO: Executing command: ['/opt/vmware/vpostgres/current/bin/pg_dump', '-U', 'postgres', '-d', 'VCDB', '-p', '5432', '-F', 'custom', '--compress', '0', '--schema-only']

2023-04-11T19:32:27.836 [] [MainProcess:PID-31090] [postgres_utils::CountCmdOutputSize:postgres_utils.py:161] INFO: Output size of the command is: "2680001".

2023-04-11T19:32:27.836 [] [MainProcess:PID-31090] [VCDB::_estimate_size_partial_vcdb:VCDB.py:412] INFO: Schema dump size is: "2680001"

2023-04-11T19:32:27.836 [] [MainProcess:PID-31090] [VCDB::_estimate_size_partial_vcdb:VCDB.py:414] INFO: Total dump size is: "162322771.28353018"

2023-04-11T19:32:27.836 [] [MainProcess:PID-31090] [VCDB::_estimate_size_partial_vcdb:VCDB.py:417] INFO: Estimated partial VCDB size is: "194787325.5402362"

2023-04-11T19:32:27.837 [] [MainProcess:PID-31090] [VCDB::VCDBSize:VCDB.py:471] INFO: Estimated size: 

 original_size=194787325.5402362, 

 compressed_size=25322352.320230708, 

 encrypted_size=27854587.55225378

 

Thank you

 

Tags (2)
0 Kudos