VCSA Update "Error in method invocation Timeout happens while sending message to microservice"

[csgrpowell]

Hi All,

I have been trying to patch our VCSA instance and running into issues getting the latest patch. Yesterday I was able to successfully update to 6.7.0.31000. Today, I am trying to install 6.7.0.31100.

I am getting this error when running the pre-check:

After looking at the logs, I am seeing some errors showing FileNotFound and exceptions within the update process.

Does anyone have any tips on how I can get the patches installed or if there is a greater issue going on?

I do have backups of the config and Veeam backups from before upgrading.

Thanks in advance!

Rhys

[MikeStoica]

Did you checked the appliance logs in /var/log/vmware/applmgmt/ ?

[csgrpowell]

Hi Mike,

Thanks for the reply - the second screenshot in my original post contains output from the log /var/log/vmware/applmgmt/

I have included some of the output that is generated when I attempt to update/stage or pre-check.

2019-06-14T13:48:54.310 [3524]DEBUG:vmware.appliance.update.update_b2b:List returns [{'size': 1893, 'description': {'args': ['Patch for vCenter Server Appliance 6.7 with security fixes for PhotonOS'], 'id': 'com.applmgmt.plain_message', 'default_message': 'Patch for vCenter Server Appliance 6.7 with security fixes for PhotonOS'}, 'severity': 'CRITICAL', 'release_date': '2019-05-30T00:00:00.000Z', 'reboot_required': True, 'version': '6.7.0.31100', 'priority': 'LOW', 'update_type': 'FIX'}]

2019-06-14T13:48:54.314 [3524]INFO:twisted:"127.0.0.1" - - [14/Jun/2019:13:48:53 +0000] "GET /rest/appliance/update/pending?source_type=LOCAL_AND_ONLINE HTTP/1.0" 200 398 "https://vcenter..org:5480/ui/update" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"

2019-06-14T13:48:56.776 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:00.418 [3524]DEBUG:vmware.vherd.transport.vapi:Only [] block []

2019-06-14T13:49:00.419 [3524]DEBUG:vmware.vherd.transport.vapi:State 'UP_TO_DATE'

2019-06-14T13:49:00.421 [3524]DEBUG:vmware.appliance.health.impl:com.vmware.appliance.version1.system.time.get()

2019-06-14T13:49:00.425 [3524]INFO:twisted:"127.0.0.1" - - [14/Jun/2019:13:48:59 +0000] "GET /rest/appliance/system/time HTTP/1.0" 200 106 "https://vcenter..org:5480/ui/update" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"

2019-06-14T13:49:01.776 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:06.776 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:10.310 [3524]INFO:vmware.appliance.vapi.auth:Authorization request for service_id: com.vmware.appliance.update.pending, operation_id: get

2019-06-14T13:49:10.310 [3524]DEBUG:vmware.vherd.base.authorization_local:Verify privileges user (root) privilege ['ModifyConfiguration']

2019-06-14T13:49:10.310 [3524]DEBUG:root:Validated user privileges in localstore or SSO

2019-06-14T13:49:10.311 [3524]DEBUG:vmware.vherd.transport.vapi:Only ['INSTALL_IN_PROGRESS'] block []

2019-06-14T13:49:10.311 [3524]DEBUG:vmware.vherd.transport.vapi:State 'UP_TO_DATE'

2019-06-14T13:49:10.312 [3524]ERROR:vmware.appliance.update.update_functions:Can't read JSON file /storage/core/software-update/stage/stageDir.json [Errno 2] No such file or directory: '/storage/core/software-update/stage/stageDir.json'

2019-06-14T13:49:10.312 [3524]DEBUG:vmware.appliance.update.update_b2b:staged discovery failed: FileNotFoundError(2, 'No such file or directory') 'Traceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1101, in _discoverUpdateAtStageArea\n    stageDir = readJsonFile(stagePathFile)[\'StageDir\']\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_functions.py", line 212, in readJsonFile\n    with open(filename) as f:\nFileNotFoundError: [Errno 2] No such file or directory: \'/storage/core/software-update/stage/stageDir.json\'\n'

2019-06-14T13:49:10.312 [3524]DEBUG:vmware.appliance.update.update_functions:/var/run/vmware/applmgmt directory created successfully

2019-06-14T13:49:10.312 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents not mounted

2019-06-14T13:49:10.313 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents directory created successfully

2019-06-14T13:49:10.313 [3524]DEBUG:vmware.appliance.update.update_functions:Running /bin/mount -o ro /dev/cdrom /mnt/iso-contents

2019-06-14T13:49:10.374 [3524]DEBUG:vmware.appliance.update.update_functions:runCommandAndCheckResult failed: Exception('mount failed for /dev/cdrom', '', 'mount: no medium found on /dev/sr0\n')

2019-06-14T13:49:10.375 [3524]DEBUG:vmware.appliance.update.update_functions:('mount failed for /dev/cdrom', '', 'mount: no medium found on /dev/sr0\n')

2019-06-14T13:49:10.385 [3524]INFO:vmware.appliance.update.update_functions:Update manifest found in None

2019-06-14T13:49:10.385 [3524]DEBUG:vmware.appliance.update.update_b2b:discoverUpdateAt: manifest:/mnt/iso-contents packages:/mnt/iso-contents copyfunc:<function copy at 0x7fb16db84158>

2019-06-14T13:49:10.386 [3524]DEBUG:vmware.appliance.update.update_functions:Can't remove directory /storage/core/software-update/tmp: [Errno 2] No such file or directory: '/storage/core/software-update/tmp'

2019-06-14T13:49:10.386 [3524]DEBUG:vmware.appliance.update.update_functions:/storage/core/software-update/tmp directory created successfully

2019-06-14T13:49:10.386 [3524]DEBUG:vmware.appliance.update.update_functions:Can't remove directory /storage/core/software-update/tmp/iso: [Errno 2] No such file or directory: '/storage/core/software-update/tmp/iso'

2019-06-14T13:49:10.386 [3524]DEBUG:vmware.appliance.update.update_functions:/storage/core/software-update/tmp/iso directory created successfully

2019-06-14T13:49:10.387 [3524]DEBUG:vmware.appliance.update.update_b2b:ISO discovery failed: RpmManifestNotFoundException() 'Traceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 989, in _discoverUpdateAt\n    tempFolder)\n  File "/usr/lib/python3.5/shutil.py", line 241, in copy\n    copyfile(src, dst, follow_symlinks=follow_symlinks)\n  File "/usr/lib/python3.5/shutil.py", line 120, in copyfile\n    with open(src, \'rb\') as fsrc:\nFileNotFoundError: [Errno 2] No such file or directory: \'/mnt/iso-contents/manifest-latest.xml\'\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1126, in _discoverUpdateAtIso\n    _discoverUpdateAt(manifestDir, packagesDir, copyFileFunc, \'iso\')\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 999, in _discoverUpdateAt\n    raise RpmManifestNotFoundException\nvmware.appliance.update.update_b2b.RpmManifestNotFoundException\n'

2019-06-14T13:49:10.387 [3524]DEBUG:vmware.appliance.update.update_functions:/var/run/vmware/applmgmt directory created successfully

2019-06-14T13:49:10.388 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents not mounted

2019-06-14T13:49:10.401 [3524]INFO:vmware.appliance.update.update_functions:ISO unmounted successfully

2019-06-14T13:49:10.401 [3524]DEBUG:vmware.appliance.update.update_b2b:discoverLocalUpdate failed.

Traceback (most recent call last):

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 989, in _discoverUpdateAt

    tempFolder)

  File "/usr/lib/python3.5/shutil.py", line 241, in copy

    copyfile(src, dst, follow_symlinks=follow_symlinks)

  File "/usr/lib/python3.5/shutil.py", line 120, in copyfile

    with open(src, 'rb') as fsrc:

FileNotFoundError: [Errno 2] No such file or directory: '/mnt/iso-contents/manifest-latest.xml'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1160, in discoverLocalUpdatesNoException

    _discoverLocalUpdates()

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1152, in _discoverLocalUpdates

    _discoverUpdateAtIso()

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1131, in _discoverUpdateAtIso

    raise e

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1126, in _discoverUpdateAtIso

    _discoverUpdateAt(manifestDir, packagesDir, copyFileFunc, 'iso')

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 999, in _discoverUpdateAt

    raise RpmManifestNotFoundException

vmware.appliance.update.update_b2b.RpmManifestNotFoundException

2019-06-14T13:49:10.404 [3524]ERROR:vmware.appliance.update.update_functions:Can't read JSON file /storage/core/software-update/stage/rpm-manifest.json [Errno 2] No such file or directory: '/storage/core/software-update/stage/rpm-manifest.json'

2019-06-14T13:49:10.404 [3524]ERROR:vmware.appliance.update.update_pending:Returning: {'services_will_be_stopped': [{'description': {'args': ['vmware-pod'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-pod'}, 'service': 'vmware-pod'}, {'description': {'args': ['vmware-sts-idmd'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-sts-idmd'}, 'service': 'vmware-sts-idmd'}, {'description': {'args': ['vmware-cm'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-cm'}, 'service': 'vmware-cm'}, {'description': {'args': ['vmware-stsd'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-stsd'}, 'service': 'vmware-stsd'}, {'description': {'args': ['vmware-rhttpproxy'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-rhttpproxy'}, 'service': 'vmware-rhttpproxy'}, {'description': {'args': ['vmware-cis-license'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-cis-license'}, 'service': 'vmware-cis-license'}, {'description': {'args': ['vmware-sca'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-sca'}, 'service': 'vmware-sca'}, {'description': {'args': ['vmware-updatemgr'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-updatemgr'}, 'service': 'vmware-updatemgr'}, {'description': {'args': ['vsphere-client'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vsphere-client'}, 'service': 'vsphere-client'}, {'description': {'args': ['pschealth'], 'id': 'com.applmgmt.plain_message', 'default_message': 'pschealth'}, 'service': 'pschealth'}, {'description': {'args': ['vmonapi'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmonapi'}, 'service': 'vmonapi'}, {'description': {'args': ['vmware-topologysvc'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-topologysvc'}, 'service': 'vmware-topologysvc'}, {'description': {'args': ['vmafdd'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmafdd'}, 'service': 'vmafdd'}, {'description': {'args': ['vmware-content-library'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-content-library'}, 'service': 'vmware-content-library'}, {'description': {'args': ['vmware-vpostgres'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-vpostgres'}, 'service': 'vmware-vpostgres'}, {'description': {'args': ['applmgmt'], 'id': 'com.applmgmt.plain_message', 'default_message': 'applmgmt'}, 'service': 'applmgmt'}, {'description': {'args': ['vsphere-ui'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vsphere-ui'}, 'service': 'vsphere-ui'}, {'description': {'args': ['vmdnsd'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmdnsd'}, 'service': 'vmdnsd'}, {'description': {'args': ['vmware-perfcharts'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-perfcharts'}, 'service': 'vmware-perfcharts'}, {'description': {'args': ['vmware-vmon'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-vmon'}, 'service': 'vmware-vmon'}, {'description': {'args': ['vmware-certificatemanagement'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-certificatemanagement'}, 'service': 'vmware-certificatemanagement'}, {'description': {'args': ['vmware-sps'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-sps'}, 'service': 'vmware-sps'}, {'description': {'args': ['vmware-vpxd-svcs'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-vpxd-svcs'}, 'service': 'vmware-vpxd-svcs'}, {'description': {'args': ['vmware-vapi-endpoint'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-vapi-endpoint'}, 'service': 'vmware-vapi-endpoint'}, {'description': {'args': ['lwsmd'], 'id': 'com.applmgmt.plain_message', 'default_message': 'lwsmd'}, 'service': 'lwsmd'}, {'description': {'args': ['vmware-eam'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-eam'}, 'service': 'vmware-eam'}, {'description': {'args': ['vmware-vpxd'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-vpxd'}, 'service': 'vmware-vpxd'}, {'description': {'args': ['vmware-statsmonitor'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-statsmonitor'}, 'service': 'vmware-statsmonitor'}, {'description': {'args': ['vmware-vsm'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-vsm'}, 'service': 'vmware-vsm'}, {'description': {'args': ['vmcad'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmcad'}, 'service': 'vmcad'}, {'description': {'args': ['vmware-analytics'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-analytics'}, 'service': 'vmware-analytics'}, {'description': {'args': ['vmware-postgres-archiver'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-postgres-archiver'}, 'service': 'vmware-postgres-archiver'}, {'description': {'args': ['vmware-vsan-health'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmware-vsan-health'}, 'service': 'vmware-vsan-health'}, {'description': {'args': ['vmdird'], 'id': 'com.applmgmt.plain_message', 'default_message': 'vmdird'}, 'service': 'vmdird'}], 'contents': [], 'priority': 'LOW', 'size': 1893, 'description': {'args': ['Patch for vCenter Server Appliance 6.7 with security fixes for PhotonOS'], 'id': 'com.applmgmt.plain_message', 'default_message': 'Patch for vCenter Server Appliance 6.7 with security fixes for PhotonOS'}, 'severity': 'CRITICAL', 'eulas': [{'args': [], 'id': 'patch.plain.message', 'default_message': '\n\nVMWARE END USER LICENSE AGREEMEN'}], 'release_date': '2019-05-30T00:00:00.000Z', 'reboot_required': True, 'version': '6.7.0.31100', 'staged': False, 'update_type': 'FIX'}

2019-06-14T13:49:10.417 [3524]INFO:twisted:"127.0.0.1" - - [14/Jun/2019:13:49:09 +0000] "GET /rest/appliance/update/pending/6.7.0.31100 HTTP/1.0" 200 36152 "https://vcenter..org:5480/ui/update" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"

2019-06-14T13:49:11.481 [3524]INFO:vmware.appliance.vapi.auth:Authorization request for service_id: com.vmware.appliance.update.pending, operation_id: precheck

2019-06-14T13:49:11.481 [3524]DEBUG:vmware.vherd.base.authorization_local:Verify privileges user (root) privilege ['ModifyConfiguration']

2019-06-14T13:49:11.481 [3524]DEBUG:root:Validated user privileges in localstore or SSO

2019-06-14T13:49:11.482 [3524]DEBUG:vmware.vherd.transport.vapi:Only ['INSTALL_IN_PROGRESS'] block []

2019-06-14T13:49:11.482 [3524]DEBUG:vmware.vherd.transport.vapi:State 'UP_TO_DATE'

2019-06-14T13:49:11.483 [3524]ERROR:vmware.appliance.update.update_functions:Can't read JSON file /storage/core/software-update/stage/stageDir.json [Errno 2] No such file or directory: '/storage/core/software-update/stage/stageDir.json'

2019-06-14T13:49:11.483 [3524]DEBUG:vmware.appliance.update.update_b2b:staged discovery failed: FileNotFoundError(2, 'No such file or directory') 'Traceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1101, in _discoverUpdateAtStageArea\n    stageDir = readJsonFile(stagePathFile)[\'StageDir\']\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_functions.py", line 212, in readJsonFile\n    with open(filename) as f:\nFileNotFoundError: [Errno 2] No such file or directory: \'/storage/core/software-update/stage/stageDir.json\'\n'

2019-06-14T13:49:11.483 [3524]DEBUG:vmware.appliance.update.update_functions:/var/run/vmware/applmgmt directory created successfully

2019-06-14T13:49:11.483 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents not mounted

2019-06-14T13:49:11.488 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents directory created successfully

2019-06-14T13:49:11.489 [3524]DEBUG:vmware.appliance.update.update_functions:Running /bin/mount -o ro /dev/cdrom /mnt/iso-contents

2019-06-14T13:49:11.550 [3524]DEBUG:vmware.appliance.update.update_functions:runCommandAndCheckResult failed: Exception('mount failed for /dev/cdrom', '', 'mount: no medium found on /dev/sr0\n')

2019-06-14T13:49:11.551 [3524]DEBUG:vmware.appliance.update.update_functions:('mount failed for /dev/cdrom', '', 'mount: no medium found on /dev/sr0\n')

2019-06-14T13:49:11.561 [3524]INFO:vmware.appliance.update.update_functions:Update manifest found in None

2019-06-14T13:49:11.561 [3524]DEBUG:vmware.appliance.update.update_b2b:discoverUpdateAt: manifest:/mnt/iso-contents packages:/mnt/iso-contents copyfunc:<function copy at 0x7fb16db84158>

2019-06-14T13:49:11.562 [3524]DEBUG:vmware.appliance.update.update_functions:/storage/core/software-update/tmp/iso directory created successfully

2019-06-14T13:49:11.562 [3524]DEBUG:vmware.appliance.update.update_b2b:ISO discovery failed: RpmManifestNotFoundException() 'Traceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 989, in _discoverUpdateAt\n    tempFolder)\n  File "/usr/lib/python3.5/shutil.py", line 241, in copy\n    copyfile(src, dst, follow_symlinks=follow_symlinks)\n  File "/usr/lib/python3.5/shutil.py", line 120, in copyfile\n    with open(src, \'rb\') as fsrc:\nFileNotFoundError: [Errno 2] No such file or directory: \'/mnt/iso-contents/manifest-latest.xml\'\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1126, in _discoverUpdateAtIso\n    _discoverUpdateAt(manifestDir, packagesDir, copyFileFunc, \'iso\')\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 999, in _discoverUpdateAt\n    raise RpmManifestNotFoundException\nvmware.appliance.update.update_b2b.RpmManifestNotFoundException\n'

2019-06-14T13:49:11.563 [3524]DEBUG:vmware.appliance.update.update_functions:/var/run/vmware/applmgmt directory created successfully

2019-06-14T13:49:11.563 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents not mounted

2019-06-14T13:49:11.577 [3524]INFO:vmware.appliance.update.update_functions:ISO unmounted successfully

2019-06-14T13:49:11.577 [3524]DEBUG:vmware.appliance.update.update_b2b:discoverLocalUpdate failed.

Traceback (most recent call last):

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 989, in _discoverUpdateAt

    tempFolder)

  File "/usr/lib/python3.5/shutil.py", line 241, in copy

    copyfile(src, dst, follow_symlinks=follow_symlinks)

  File "/usr/lib/python3.5/shutil.py", line 120, in copyfile

    with open(src, 'rb') as fsrc:

FileNotFoundError: [Errno 2] No such file or directory: '/mnt/iso-contents/manifest-latest.xml'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1160, in discoverLocalUpdatesNoException

    _discoverLocalUpdates()

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1152, in _discoverLocalUpdates

    _discoverUpdateAtIso()

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1131, in _discoverUpdateAtIso

    raise e

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1126, in _discoverUpdateAtIso

    _discoverUpdateAt(manifestDir, packagesDir, copyFileFunc, 'iso')

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 999, in _discoverUpdateAt

    raise RpmManifestNotFoundException

vmware.appliance.update.update_b2b.RpmManifestNotFoundException

2019-06-14T13:49:11.585 [3524]DEBUG:vmware.appliance.update.ms_connector:sending message

2019-06-14T13:49:11.585 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:11.776 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:12.327 [3524]INFO:twisted:"127.0.0.1" - - [14/Jun/2019:13:49:11 +0000] "POST /api HTTP/1.1" 200 332 "-" "vAPI/2.100.0 Java/1.8.0_202 (Linux; 4.4.171-1.ph1; amd64)"

2019-06-14T13:49:12.474 [3524]DEBUG:vmware.appliance.extensions.authentication.authentication_sso:isExpired, notBefore: None, notOnOrAfter: None, now: 2019-06-14 13:49:12.474764, tolerance: 600

2019-06-14T13:49:12.474 [3524]DEBUG:vmware.appliance.extensions.authentication.authentication_sso:isExpired, notBefore: 2019-06-14T13:49:12.411Z, notOnOrAfter: 2019-06-14T13:59:12.411Z, now: 2019-06-14 13:49:12.474972, tolerance: 600

2019-06-14T13:49:12.475 [3524]INFO:vmware.appliance.vapi.auth:Authorization request for service_id: com.vmware.appliance.networking.proxy, operation_id: get

2019-06-14T13:49:12.475 [3524]DEBUG:vmware.appliance.extensions.authorization.authorization_sso:Required privileges = ['ViewConfiguration']

2019-06-14T13:49:12.586 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:12.604 [3524]DEBUG:vmware.appliance.extensions.authorization.authorization_sso:User=vmware..org\vsphere-webclient-fe7cb739-c8ac-4b06-9ade-c107cf1f2077, groups={'vmware..org\\LicenseService.Administrators', 'vmware..org\\SystemConfiguration.Administrators', 'vmware..org\\Everyone', 'vmware..org\\SolutionUsers', 'vmware..org\\Administrators', 'vmware..org\\ActAsUsers'}

2019-06-14T13:49:12.604 [3524]DEBUG:root:Validated user privileges in localstore or SSO

2019-06-14T13:49:12.605 [3524]DEBUG:vmware.vherd.transport.vapi:Only [] block []

2019-06-14T13:49:12.605 [3524]DEBUG:vmware.vherd.transport.vapi:State 'UP_TO_DATE'

2019-06-14T13:49:12.606 [3524]DEBUG:vmware.appliance.networking.proxy.proxy_impl:method=get, protocol=http

2019-06-14T13:49:12.609 [3524]INFO:twisted:"127.0.0.1" - - [14/Jun/2019:13:49:11 +0000] "POST /api HTTP/1.1" 200 242 "-" "vAPI/2.100.0 Java/1.8.0_202 (Linux; 4.4.171-1.ph1; amd64)"

2019-06-14T13:49:13.587 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:14.589 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:15.591 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:16.592 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:16.593 [3524]INFO:vmware.appliance.update.update_functions:Timeout happens while sending message to microservice

2019-06-14T13:49:16.593 [3524]ERROR:vmware.vapi.provider.local:Error in invoking com.vmware.appliance.update.pending in precheck - Timeout happens while sending message to microservice

Traceback (most recent call last):

  File "/usr/lib/vmware-vapi/lib/python/vapi_runtime-2.100.0-py2.py3-none-any.whl/vmware/vapi/provider/local.py", line 277, in invoke

    service_id, operation_id, input_value, ctx)

  File "/usr/lib/vmware-vapi/lib/python/vapi_runtime-2.100.0-py2.py3-none-any.whl/vmware/vapi/provider/local.py", line 248, in _invoke_int

    method_result = iface.invoke(ctx, method_id, input_value)

  File "/usr/lib/vmware-vapi/lib/python/vapi_runtime-2.100.0-py2.py3-none-any.whl/vmware/vapi/bindings/skeleton.py", line 365, in invoke

    meth_output = method(**meth_args)

  File "/usr/lib/applmgmt/vapi/py/vmware/appliance/vapi/update_impl.py", line 159, in precheck

    return worker.precheck(version)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_pending.py", line 105, in precheck

    MicroserviceConnector.execute(request)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/ms_connector.py", line 128, in execute

    Exception, 1, 5)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_functions.py", line 373, in executeFunctionUntilSuccessOrTimeout

    raise Exception("Timeout happens while " + ingDescription)

Exception: Timeout happens while sending message to microservice

2019-06-14T13:49:16.597 [3524]INFO:twisted:"127.0.0.1" - - [14/Jun/2019:13:49:15 +0000] "POST /rest/appliance/update/pending/6.7.0.31100?action=precheck HTTP/1.0" 500 218 "https://vcenter..org:5480/ui/update" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"

2019-06-14T13:49:16.775 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:21.776 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:26.776 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:29.359 [3524]INFO:vmware.appliance.vapi.auth:Authorization request for service_id: com.vmware.appliance.update.pending, operation_id: stage

2019-06-14T13:49:29.360 [3524]DEBUG:vmware.vherd.base.authorization_local:Verify privileges user (root) privilege ['ModifyConfiguration']

2019-06-14T13:49:29.361 [3524]DEBUG:root:Validated user privileges in localstore or SSO

2019-06-14T13:49:29.361 [3524]DEBUG:vmware.vherd.transport.vapi:Only ['INSTALL_IN_PROGRESS'] block []

2019-06-14T13:49:29.362 [3524]DEBUG:vmware.vherd.transport.vapi:State 'UP_TO_DATE'

2019-06-14T13:49:29.363 [3524]ERROR:vmware.appliance.update.update_functions:Can't read JSON file /storage/core/software-update/stage/stageDir.json [Errno 2] No such file or directory: '/storage/core/software-update/stage/stageDir.json'

2019-06-14T13:49:29.363 [3524]DEBUG:vmware.appliance.update.update_b2b:staged discovery failed: FileNotFoundError(2, 'No such file or directory') 'Traceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1101, in _discoverUpdateAtStageArea\n    stageDir = readJsonFile(stagePathFile)[\'StageDir\']\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_functions.py", line 212, in readJsonFile\n    with open(filename) as f:\nFileNotFoundError: [Errno 2] No such file or directory: \'/storage/core/software-update/stage/stageDir.json\'\n'

2019-06-14T13:49:29.363 [3524]DEBUG:vmware.appliance.update.update_functions:/var/run/vmware/applmgmt directory created successfully

2019-06-14T13:49:29.364 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents not mounted

2019-06-14T13:49:29.373 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents directory created successfully

2019-06-14T13:49:29.375 [3524]DEBUG:vmware.appliance.update.update_functions:Running /bin/mount -o ro /dev/cdrom /mnt/iso-contents

2019-06-14T13:49:29.434 [3524]DEBUG:vmware.appliance.update.update_functions:runCommandAndCheckResult failed: Exception('mount failed for /dev/cdrom', '', 'mount: no medium found on /dev/sr0\n')

2019-06-14T13:49:29.435 [3524]DEBUG:vmware.appliance.update.update_functions:('mount failed for /dev/cdrom', '', 'mount: no medium found on /dev/sr0\n')

2019-06-14T13:49:29.445 [3524]INFO:vmware.appliance.update.update_functions:Update manifest found in None

2019-06-14T13:49:29.445 [3524]DEBUG:vmware.appliance.update.update_b2b:discoverUpdateAt: manifest:/mnt/iso-contents packages:/mnt/iso-contents copyfunc:<function copy at 0x7fb16db84158>

2019-06-14T13:49:29.446 [3524]DEBUG:vmware.appliance.update.update_functions:/storage/core/software-update/tmp/iso directory created successfully

2019-06-14T13:49:29.447 [3524]DEBUG:vmware.appliance.update.update_b2b:ISO discovery failed: RpmManifestNotFoundException() 'Traceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 989, in _discoverUpdateAt\n    tempFolder)\n  File "/usr/lib/python3.5/shutil.py", line 241, in copy\n    copyfile(src, dst, follow_symlinks=follow_symlinks)\n  File "/usr/lib/python3.5/shutil.py", line 120, in copyfile\n    with open(src, \'rb\') as fsrc:\nFileNotFoundError: [Errno 2] No such file or directory: \'/mnt/iso-contents/manifest-latest.xml\'\n\nDuring handling of the above exception, another exception occurred:\n\nTraceback (most recent call last):\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1126, in _discoverUpdateAtIso\n    _discoverUpdateAt(manifestDir, packagesDir, copyFileFunc, \'iso\')\n  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 999, in _discoverUpdateAt\n    raise RpmManifestNotFoundException\nvmware.appliance.update.update_b2b.RpmManifestNotFoundException\n'

2019-06-14T13:49:29.447 [3524]DEBUG:vmware.appliance.update.update_functions:/var/run/vmware/applmgmt directory created successfully

2019-06-14T13:49:29.448 [3524]DEBUG:vmware.appliance.update.update_functions:/mnt/iso-contents not mounted

2019-06-14T13:49:29.461 [3524]INFO:vmware.appliance.update.update_functions:ISO unmounted successfully

2019-06-14T13:49:29.461 [3524]DEBUG:vmware.appliance.update.update_b2b:discoverLocalUpdate failed.

Traceback (most recent call last):

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 989, in _discoverUpdateAt

    tempFolder)

  File "/usr/lib/python3.5/shutil.py", line 241, in copy

    copyfile(src, dst, follow_symlinks=follow_symlinks)

  File "/usr/lib/python3.5/shutil.py", line 120, in copyfile

    with open(src, 'rb') as fsrc:

FileNotFoundError: [Errno 2] No such file or directory: '/mnt/iso-contents/manifest-latest.xml'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1160, in discoverLocalUpdatesNoException

    _discoverLocalUpdates()

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1152, in _discoverLocalUpdates

    _discoverUpdateAtIso()

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1131, in _discoverUpdateAtIso

    raise e

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 1126, in _discoverUpdateAtIso

    _discoverUpdateAt(manifestDir, packagesDir, copyFileFunc, 'iso')

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_b2b.py", line 999, in _discoverUpdateAt

    raise RpmManifestNotFoundException

vmware.appliance.update.update_b2b.RpmManifestNotFoundException

2019-06-14T13:49:29.462 [3524]INFO:vmware.appliance.update.update_pending:Running stage in microservice

2019-06-14T13:49:29.463 [3524]DEBUG:vmware.appliance.update.ms_connector:sending message

2019-06-14T13:49:29.463 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:30.465 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:31.466 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:31.776 [3524]INFO:vmware.vherd.transport.ssh_access_collector:Feature switch: VCSA_SSH_ACCESS_EVENT disabled.

2019-06-14T13:49:32.468 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:33.470 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:34.472 [3524]DEBUG:vmware.appliance.update.update_functions:Exception happens while sending message to microservice: FileNotFoundError(2, 'No such file or directory')

2019-06-14T13:49:34.472 [3524]INFO:vmware.appliance.update.update_functions:Timeout happens while sending message to microservice

2019-06-14T13:49:34.472 [3524]ERROR:vmware.vapi.provider.local:Error in invoking com.vmware.appliance.update.pending in stage - Timeout happens while sending message to microservice

Traceback (most recent call last):

  File "/usr/lib/vmware-vapi/lib/python/vapi_runtime-2.100.0-py2.py3-none-any.whl/vmware/vapi/provider/local.py", line 277, in invoke

    service_id, operation_id, input_value, ctx)

  File "/usr/lib/vmware-vapi/lib/python/vapi_runtime-2.100.0-py2.py3-none-any.whl/vmware/vapi/provider/local.py", line 248, in _invoke_int

    method_result = iface.invoke(ctx, method_id, input_value)

  File "/usr/lib/vmware-vapi/lib/python/vapi_runtime-2.100.0-py2.py3-none-any.whl/vmware/vapi/bindings/skeleton.py", line 365, in invoke

    meth_output = method(**meth_args)

  File "/usr/lib/applmgmt/vapi/py/vmware/appliance/vapi/update_impl.py", line 190, in stage

    return worker.stage(version)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_pending.py", line 133, in stage

    request)

  File "/usr/lib/applmgmt/base/py/vmware/vherd/base/decorators.py", line 35, in wrapper

    result = fn(*args, **kwargs)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_state.py", line 183, in change

    State._change(newState, allowedStates, taskSpec)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_state.py", line 167, in _change

    MicroserviceConnector.execute(taskSpec)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/ms_connector.py", line 128, in execute

    Exception, 1, 5)

  File "/usr/lib/applmgmt/update/py/vmware/appliance/update/update_functions.py", line 373, in executeFunctionUntilSuccessOrTimeout

    raise Exception("Timeout happens while " + ingDescription)

Exception: Timeout happens while sending message to microservice

2019-06-14T13:49:34.478 [3524]INFO:twisted:"127.0.0.1" - - [14/Jun/2019:13:49:33 +0000] "POST /rest/appliance/update/pending/6.7.0.31100?action=stage HTTP/1.0" 500 218 "https://vcenter..org:5480/ui/update" "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/74.0.3729.169 Safari/537.36"

root@vcenter [ /var/log/vmware/applmgmt ]# exit

[csgrpowell · Accepted solution]

It appears I am no longer having this issue.

I had to perform some unrelated maintenance which involved rebooting my hosts and all my VMs including this VCSA.

After bringing everything back online, I tested and this issue is gone.

Thanks,
Rhys