Bug 1265582

Summary: virt-who generate too many timeout info when it can't reach the vcenter
Product: Red Hat Enterprise Linux 7 Reporter: Liushihui <shihliu>
Component: virt-whoAssignee: Radek Novacek <rnovacek>
Status: CLOSED ERRATA QA Contact: Eko <hsun>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 7.2CC: hsun, ovasik, owwang, sgao
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: virt-who-0.17-1.el7 Doc Type: No Doc Update
Doc Text:
undefined
Story Points: ---
Clone Of:
: 1315604 (view as bug list) Environment:
Last Closed: 2016-11-04 05:06:03 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1315604    

Description Liushihui 2015-09-23 09:47:11 UTC
Description of problem:
When virt-who connect to vcenter through proxy, virt-who will generate too many info of "Wait for ESX event finished, timeout"

Version-Release number of selected component (if applicable):
virt-who-0.14-8.el7.noarch
subscription-manager-1.15.9-10.el7.x86_64
python-rhsm-1.15.4-5.el7.x86_64

How reproducible:
Always

Steps to Reproduce:
1. Register system to SAM
2. Configure virt-who run at esx mode and make virt-who connect vcenter through proxy. then restart virt-who service.
3. Restart squid on proxy
[root@samdns ~]# service squid restart
4. Before squid is restarted, check the virt-who's log 

Actual results:
It will generate over 100 times "Wait for ESX event finished, timeout" info every one minute. 
2015-09-23 17:13:56,001 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,005 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,008 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,011 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,015 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,019 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,022 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,025 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,029 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,032 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,036 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,039 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,042 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,046 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,049 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,052 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,056 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
2015-09-23 17:13:56,059 [DEBUG]  @esx.py:105 - Wait for ESX event finished, timeout
............

Expected results:
Virt-who shouldn't generate too many redundant timeout info in the log.

Additional info:
After squid is restarted ,virt-who can resend h/g mapping to server

Comment 1 Radek Novacek 2016-05-03 12:52:18 UTC
This bug is fixed upstream (or at least I can't reproduce it):

2016-05-03 14:49:43,468 ERROR: Virt backend 'env/cmdline' fails with exception:
ConnectionError: ('Connection aborted.', BadStatusLine("''",))
2016-05-03 14:49:43,469 INFO: Waiting 60 seconds before retrying backend 'env/cmdline'
2016-05-03 14:50:43,896 INFO: Report for config "env/cmdline" hasn't changed, not sending

Comment 2 Radek Novacek 2016-05-17 13:02:38 UTC
Fixed in virt-who-0.17-1.el7.

Comment 4 Liushihui 2016-06-02 07:15:15 UTC
Verified it on virt-who-0.17-2.el7.noarch since virt-who won't generate too many redundant info and throw error info when can't connect proxy. After proxy can be connect, virt-who still work normally. Therefore, verify it.

Verified version:
subscription-manager-1.17.6-1.el7.x86_64
python-rhsm-1.17.2-1.el7.x86_64
python-rhsm-1.17.2-1.el7.x86_64

Verified process:
1. Register system to Satellite6.2
2. Configure virt-who run at esx mode and make virt-who connect vcenter through proxy. then restart virt-who service.
3. Restart squid on proxy
[root@samdns ~]# service squid restart
4. Before squid is restarted, check the virt-who's log 
2016-06-02 03:09:56,001 [virtwho.test-esx1 ERROR] Esx-1(11146):MainThread @virt.py:run:377 - Virt backend 'test-esx1' fails with exception:
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/virtwho/virt/virt.py", line 372, in run
    self._run()
  File "/usr/lib/python2.7/site-packages/virtwho/virt/esx/esx.py", line 174, in _run
    options=options)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 542, in __call__
    return client.invoke(args, kwargs)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 602, in invoke
    result = self.send(soapenv)
  File "/usr/lib/python2.7/site-packages/suds/client.py", line 641, in send
    reply = transport.send(request)
  File "/usr/lib/python2.7/site-packages/virtwho/virt/esx/esx.py", line 95, in send
    verify=False
  File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 507, in post
    return self.request('POST', url, data=data, json=json, **kwargs)
  File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 464, in request
    resp = self.send(prep, **send_kwargs)
  File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 576, in send
    r = adapter.send(request, **kwargs)
  File "/usr/lib/python2.7/site-packages/requests/adapters.py", line 415, in send
    raise ConnectionError(err, request=request)
ConnectionError: ('Connection aborted.', BadStatusLine("''",))
2016-06-02 03:09:56,002 [virtwho.test-esx1 INFO] Esx-1(11146):MainThread @virt.py:run:390 - Waiting 60 seconds before retrying backend 'test-esx1'
2016-06-02 03:10:56,065 [virtwho.test-esx1 DEBUG] Esx-1(11146):MainThread @esx.py:_prepare:127 - Log into ESX
2016-06-02 03:10:56,291 [virtwho.test-esx1 DEBUG] Esx-1(11146):MainThread @esx.py:_prepare:130 - Creating ESX event filter
2016-06-02 03:10:56,412 [virtwho.test-esx1 DEBUG] Esx-1(11146):MainThread @virt.py:enqueue:357 - Report for config "test-esx1" gathered, putting to queue for sending
2016-06-02 03:10:56,414 [virtwho.main INFO] MainProcess(11139):MainThread @executor.py:run:250 - Report for config "test-esx1" hasn't changed, not sending

Result:
virt-who won't generate too many redundant info and throw error info when can't connect proxy. After proxy restart successfully, virt-who still work normally.

Comment 7 errata-xmlrpc 2016-11-04 05:06:03 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2016-2387.html