Seems there is a bug with collecting metrics when VM is cloned

[MVKozlov]

When I start cloning (vcenter, esxi v6.7) The collector fails with error. After cloning is finished, the error going away

Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,345 INFO:Start collecting metrics from vcenter.xxx.local
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,345 INFO:Starting vm metrics collection
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,345 INFO:Fetching vim.VirtualMachine inventory
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,345 INFO:Retrieving service instance content
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,347 INFO:Fetching tags
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,348 INFO:START: _vmware_get_vm_perf_manager_metrics
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,351 INFO:Fetching vim.Datastore inventory
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,352 INFO:Starting host metrics collection
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,352 INFO:Fetching vim.HostSystem inventory
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,352 INFO:START: _vmware_get_host_perf_manager_metrics
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,458 INFO:Retrieved service instance content
Sep  7 09:49:02 gorets vmware_exporter[806568]: Unhandled error in Deferred:
Sep  7 09:49:02 gorets vmware_exporter[806568]: Traceback (most recent call last):
Sep  7 09:49:02 gorets vmware_exporter[806568]: --- <exception caught here> ---
Sep  7 09:49:02 gorets vmware_exporter[806568]:   File "/usr/local/lib/python3.8/dist-packages/vmware_exporter/vmware_exporter.py", line 1501, in _vmware_get_vms
Sep  7 09:49:02 gorets vmware_exporter[806568]:     virtual_machines, vm_labels, vm_tags = yield parallelize(
Sep  7 09:49:02 gorets vmware_exporter[806568]:   File "/usr/local/lib/python3.8/dist-packages/vmware_exporter/defer.py", line 100, in parallelize
Sep  7 09:49:02 gorets vmware_exporter[806568]:     results = yield defer.DeferredList(args, fireOnOneErrback=True)
Sep  7 09:49:02 gorets vmware_exporter[806568]: twisted.internet.defer.FirstError: FirstError[#1, [Failure instance: Traceback: <class 'IndexError'>: string index out of range
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:460:callback
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:568:_startRunCallbacks
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:654:_runCallbacks
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:1475:gotResult
Sep  7 09:49:02 gorets vmware_exporter[806568]: --- <exception caught here> ---
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:1418:_inlineCallbacks
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/vmware_exporter/vmware_exporter.py:1097:vm_labels
Sep  7 09:49:02 gorets vmware_exporter[806568]: ]]
Sep  7 09:49:02 gorets vmware_exporter[806568]: Unhandled error in Deferred:
Sep  7 09:49:02 gorets vmware_exporter[806568]: Traceback (most recent call last):
Sep  7 09:49:02 gorets vmware_exporter[806568]: --- <exception caught here> ---
Sep  7 09:49:02 gorets vmware_exporter[806568]:   File "/usr/local/lib/python3.8/dist-packages/vmware_exporter/vmware_exporter.py", line 1394, in _vmware_get_vm_perf_manager_metrics
Sep  7 09:49:02 gorets vmware_exporter[806568]:     results, labels = yield parallelize(
Sep  7 09:49:02 gorets vmware_exporter[806568]:   File "/usr/local/lib/python3.8/dist-packages/vmware_exporter/defer.py", line 100, in parallelize
Sep  7 09:49:02 gorets vmware_exporter[806568]:     results = yield defer.DeferredList(args, fireOnOneErrback=True)
Sep  7 09:49:02 gorets vmware_exporter[806568]: twisted.internet.defer.FirstError: FirstError[#1, [Failure instance: Traceback: <class 'IndexError'>: string index out of range
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:460:callback
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:568:_startRunCallbacks
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:654:_runCallbacks
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:1475:gotResult
Sep  7 09:49:02 gorets vmware_exporter[806568]: --- <exception caught here> ---
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/twisted/internet/defer.py:1418:_inlineCallbacks
Sep  7 09:49:02 gorets vmware_exporter[806568]: /usr/local/lib/python3.8/dist-packages/vmware_exporter/vmware_exporter.py:1097:vm_labels
Sep  7 09:49:02 gorets vmware_exporter[806568]: ]]
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,878 INFO:Fetched vim.Datastore inventory (0:00:00.526709)
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,893 INFO:Fetched vim.VirtualMachine inventory (0:00:00.547540)
Sep  7 09:49:02 gorets vmware_exporter[806568]: 2021-09-07 09:49:02,969 INFO:Fetched vim.HostSystem inventory (0:00:00.616206)
Sep  7 09:49:03 gorets vmware_exporter[806568]: 2021-09-07 09:49:03,092 INFO:FIN: _vmware_get_host_perf_manager_metrics
Sep  7 09:49:03 gorets vmware_exporter[806568]: 2021-09-07 09:49:03,147 INFO:FIN: _vmware_get_vm_perf_manager_metrics

The VM is powered on, cloned to the same host and datastore

[tainguyenbp]

Yeah, me too, I seen this bug when I cloned VM

[thuvh]

does this PR can help you?

[MVKozlov]

Yes, seems bug fixed with it

[kbrowder]

Had this same issue, any chance of merging https://github.com/pryorda/vmware_exporter/pull/294 and releasing it?

[tamilsaran]

yes me to fasing above issue 2022-09-21 11:22:18,358 INFO:Finished vm metrics collection Unhandled error in Deferred:

Traceback (most recent call last): File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 501, in errback self._startRunCallbacks(fail) File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 568, in _startRunCallbacks self._runCallbacks() File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 654, in _runCallbacks current.result = callback(current.result, *args, **kw) File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1475, in gotResult _inlineCallbacks(r, g, status) --- --- File "/usr/local/lib/python3.7/site-packages/twisted/internet/defer.py", line 1416, in _inlineCallbacks result = result.throwExceptionIntoGenerator(g) File "/usr/local/lib/python3.7/site-packages/twisted/python/failure.py", line 512, in throwExceptionIntoGenerator return g.throw(self.type, self.value, self.tb) File "/usr/local/lib/python3.7/site-packages/vmware_exporter/vmware_exporter.py", line 1845, in _async_render_GET request.finish() File "/usr/local/lib/python3.7/site-packages/twisted/web/server.py", line 286, in finish return http.Request.finish(self) File "/usr/local/lib/python3.7/site-packages/twisted/web/http.py", line 1080, in finish "Request.finish called on a request after its connection was lost; " builtins.RuntimeError: Request.finish called on a request after its connection was lost; use Request.notifyFinish to keep track of this.