Bug 1339863

Summary: Failed to communicate with subscription-manager as "Interrupted system call"
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.3CC: hsun, ldai, ovasik, rbalakri, rnovacek, sgao, shihliu
Target Milestone: rc   
Target Release: ---   
Hardware: x86_64   
OS: Linux   
Whiteboard:
Fixed In Version: virt-who-0.17-10.el7 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: 1323020 Environment:
Last Closed: 2016-11-04 05:09:16 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: 1323020    
Bug Blocks:    
Attachments:
Description Flags
rhsm.log none

Description Liushihui 2016-05-26 02:04:49 UTC 
As it also exist on RHEL-7.3-20160518.n.0, track it on rhel7.3

Version-Release number of selected component (if applicable):
Satellite-6.2.0-RHEL-7-20160518.1
virt-who-0.17-1.el7.noarch
subscription-manager-1.17.6-1.el7.x86_64
python-rhsm-1.17.2-1.el7.x86_64

+++ This bug was initially created as a clone of Bug #1323020 +++

Description of problem:
If host/guest mapping info updated, restart virt-who service will result in failed to communicate with subscription-manager.

Version-Release number of selected component (if applicable):
virt-who-0.16-7.el6.noarch
subscription-manager-1.16.8-8.el6.x86_64
python-rhsm-1.16.6-1.el6.x86_64
Satellite-6.1.0-RHEL-6-20160321

How reproducible:
20%

Steps to Reproduce:
1. Register system to satellite6.1
2. Configure virt-who run at rhevm mode and restart virt-who service
[root@hp-dl360g6-01 ~]# cat /etc/sysconfig/virt-who  | grep -v ^# | grep -v ^$
VIRTWHO_DEBUG=1
VIRTWHO_RHEVM=1
VIRTWHO_RHEVM_OWNER=ACME_Corporation
VIRTWHO_RHEVM_ENV=Library
VIRTWHO_RHEVM_SERVER=https://dell-pe1955-01.rhts.eng.bos.redhat.com:443
VIRTWHO_RHEVM_USERNAME=admin@internal
VIRTWHO_RHEVM_PASSWORD=redhat
[root@hp-dl360g6-01 ~]# service virt-who restart
3. In the rhevm webUI,stop vm, then remove host, restart virt-who service and check virt-who's log.
[root@hp-dl360g6-01 ~]# tail -f /var/log/rhsm/rhsm.log
2016-03-31 05:34:27,114 [virtwho.main DEBUG] MainProcess(8258):MainThread @virtwho.py:terminate:359 - virt-who is shutting down
2016-03-31 05:34:27,552 [virtwho.env_cmdline DEBUG] RhevM-1(8265):MainThread @virt.py:run:381 - Virt backend 'env/cmdline' terminated
2016-03-31 05:34:28,117 [virtwho.main ERROR] MainProcess(8258):MainThread @virtwho.py:send:216 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 199, in send
    self._sendGuestAssociation(report)
  File "/usr/share/virt-who/virtwho.py", line 226, in _sendGuestAssociation
    manager.hypervisorCheckIn(report, self.options)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 163, in hypervisorCheckIn
    is_async = hasattr(self.connection, 'has_capability') and self.connection.has_capability('hypervisors_async')
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 868, in has_capability
    self.capabilities = self._load_manager_capabilities()
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 850, in _load_manager_capabilities
    status = self.getStatus()
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 1335, in getStatus
    return self.conn.request_get(method)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 681, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 571, in _request
    conn.request(request_type, handler, body=body, headers=headers)
  File "/usr/lib64/python2.6/httplib.py", line 936, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib64/python2.6/httplib.py", line 973, in _send_request
    self.endheaders()
  File "/usr/lib64/python2.6/httplib.py", line 930, in endheaders
    self._send_output()
  File "/usr/lib64/python2.6/httplib.py", line 802, in _send_output
    self.send(msg)
  File "/usr/lib64/python2.6/httplib.py", line 761, in send
    self.connect()
  File "/usr/lib64/python2.6/site-packages/M2Crypto/httpslib.py", line 73, in connect
    raise error
error: [Errno 4] Interrupted system call
2016-03-31 05:34:28,128 [virtwho.main DEBUG] MainProcess(8258):MainThread @virtwho.py:send_report:168 - Report from "env/cmdline" failed to sent
2016-03-31 05:34:28,130 [virtwho.main DEBUG] MainProcess(8258):MainThread @virtwho.py:<module>:824 - virt-who terminated

Actual results:
Failed to communicate with subscription-manager when stop virt-who service as "Interrupted system call"

Expected results:
It shouldn't show error info when stop virt-who service

Additional info:
Comment 1 Radek Novacek 2016-05-26 07:15:03 UTC 
It seems that the backtrace here is from an older version of virt-who (RHEL-6 perhaps). Can you please reproduce it with virt-who-0.17-1.el7.noarch so I can see correct backtrace?

Thank you.
Comment 2 Liushihui 2016-05-31 03:44:20 UTC 
I haven't reproduce it on virt-who-0.17-1.el7.noarch in recently test. I plan to  track it on the following two virt-who version, if it can't reproduce, I will close it. what's your opinion? Thanks.
Comment 3 Radek Novacek 2016-05-31 05:49:39 UTC 
I agree, if we can't reproduce in the next version of virt-who, please close this bug.
Comment 4 Liushihui 2016-06-02 06:54:30 UTC 
In virt-who-0.17-2.el7.noarch. It will show "Unable to send data: Communication with subscription manager interrupted", please see detail info in attachment.

Reproduced version:
virt-who-0.17-2.el7.noarch
subscription-manager-1.17.6-1.el7.x86_64

Reproduced process:
1. Configure virt-who run at esx mode and just configure /etc/virt-who.d/XX
[root@localhost ~]# cat /etc/virt-who.d/virt 
[test-esx1]
type=esx
server=10.73.2.95
username=Administrator
#encrypted_password=07928b0a0b0caa7c6e3b5915466210bd
password=Welcome1!
owner=ACME_Corporation
env=Library

2. Restart virt-who and check virt-who's log,virt-who send correct h/g mapping info to satellite and no debug info in log.
2016-06-02 02:37:29,795 [INFO] @main.py:157 - Using configuration "test-esx1" ("esx" mode)
2016-06-02 02:37:29,796 [INFO] @main.py:159 - Using reporter_id='localhost.localdomain-d4f30f62b62f4854af348120066d195d'
2016-06-02 02:37:30,831 [INFO] @subscriptionmanager.py:194 - Sending update in hosts-to-guests mapping for config "test-esx1": 2 hypervisors and 1 guests found
2016-06-02 02:38:30,218 [INFO] @executor.py:250 - Report for config "test-esx1" hasn't changed, not sending
2016-06-02 02:39:30,222 [INFO] @executor.py:250 - Report for config "test-esx1" hasn't changed, not sending
2016-06-02 02:40:30,226 [INFO] @executor.py:250 - Report for config "test-esx1" hasn't changed, not sending

3. Modify configure file /etc/sysconfig/virt-who as the following:
[root@localhost ~]# cat /etc/sysconfig/virt-who  | grep -v ^# | grep -v ^$
VIRTWHO_DEBUG=1
https_proxy=https://10.73.2.81:3128

4. Restart virt-who and check virt-who's log.
2016-06-02 02:41:28,108 [virtwho.init INFO] MainProcess(11092):MainThread @main.py:main:157 - Using configuration "test-esx1" ("esx" mode)
2016-06-02 02:41:28,108 [virtwho.init INFO] MainProcess(11092):MainThread @main.py:main:159 - Using reporter_id='localhost.localdomain-d4f30f62b62f4854af348120066d195d'
2016-06-02 02:41:28,110 [virtwho.main DEBUG] MainProcess(11092):MainThread @executor.py:run:171 - Starting infinite loop with 60 seconds interval
2016-06-02 02:41:28,138 [virtwho.test-esx1 DEBUG] Esx-1(11099):MainThread @virt.py:run:364 - Virt backend 'test-esx1' started
2016-06-02 02:41:28,139 [virtwho.test-esx1 DEBUG] Esx-1(11099):MainThread @esx.py:_prepare:127 - Log into ESX
2016-06-02 02:41:28,381 [virtwho.test-esx1 DEBUG] Esx-1(11099):MainThread @esx.py:_prepare:130 - Creating ESX event filter
2016-06-02 02:41:28,475 [virtwho.test-esx1 DEBUG] Esx-1(11099):MainThread @virt.py:enqueue:357 - Report for config "test-esx1" gathered, putting to queue for sending
2016-06-02 02:41:28,487 [virtwho.main DEBUG] MainProcess(11092):MainThread @subscriptionmanager.py:_connect:123 - Authenticating with certificate: /etc/pki/consumer/cert.pem
2016-06-02 02:42:28,065 [virtwho.main ERROR] MainProcess(11092):MainThread @executor.py:send:143 - Unable to send data: Communication with subscription manager interrupted
2016-06-02 02:42:28,065 [virtwho.main DEBUG] MainProcess(11092):MainThread @executor.py:send_report:108 - Report from "test-esx1" failed to sent
2016-06-02 02:42:28,476 [virtwho.test-esx1 DEBUG] Esx-1(11099):MainThread @virt.py:enqueue:357 - Report for config "test-esx1" gathered, putting to queue for sending

Result:
It will show error info "Unable to send data: Communication with subscription manager interrupted" in log.
Comment 5 Liushihui 2016-06-02 06:55:40 UTC 
Created attachment 1163915 [details]
rhsm.log
Comment 6 Radek Novacek 2016-06-09 11:13:50 UTC 
It seems to be a problem with the proxy. Make sure it can connect to the satellite, or set no_proxy=<satellite_address> var in the /etc/sysconfig/virt-who.
Comment 7 Liushihui 2016-06-21 03:37:12 UTC 
When use virt-who-0.17-2.el7.noarch connect hyperv2016, it also produced this issue:

[root@intel-wildcatpass-01 virt-who.d]# cat /etc/sysconfig/virt-who  | grep -v ^# | grep -v ^$
VIRTWHO_DEBUG=1
VIRTWHO_HYPERV=1
VIRTWHO_HYPERV_OWNER=ACME_Corporation
VIRTWHO_HYPERV_ENV=Library
VIRTWHO_HYPERV_SERVER=10.73.5.240
VIRTWHO_HYPERV_USERNAME=administrator
VIRTWHO_HYPERV_PASSWORD=Welcome1

[root@intel-wildcatpass-01 virt-who.d]# service virt-who restart
Redirecting to /bin/systemctl restart  virt-who.service

[root@intel-wildcatpass-01 virt-who.d]# tail -f /var/log/rhsm/rhsm.log
2016-06-20 23:29:53,221 [virtwho.main DEBUG] MainProcess(30537):MainThread @executor.py:terminate:303 - virt-who is shutting down
2016-06-20 23:29:53,221 [virtwho.env_cmdline ERROR] HyperV-1(30544):MainThread @virt.py:run:374 - Virt backend 'env/cmdline' fails with error: Unable to connect to Hyper-V server: ('Connection aborted.', error(4, 'Interrupted system call'))
2016-06-20 23:29:53,221 [virtwho.env_cmdline DEBUG] HyperV-1(30544):MainThread @virt.py:run:387 - Virt backend 'env/cmdline' terminated
Comment 8 Liushihui 2016-06-21 06:10:15 UTC 
It usually occur "Interrupted system call" when stop virt-who service before virt-who get response from hyperv.
Comment 9 Radek Novacek 2016-06-30 09:03:05 UTC 
I was not able to reproduce it with latest version of virt-who.

Can you try to reproduce it with virt-who-0.17-5.el7 and provide the environment to me if you are able to reproduce it.
Comment 10 Liushihui 2016-07-20 01:40:34 UTC 
It still exist on virt-who-0.17-6.el7.noarch. Please do the following steps to reproduced this issue

Env:
dell-t320-01.khw.lab.eng.bos.redhat.com  username/passwd: root/red2015

Steps:
1. Register system to satellite
2. Config virt-who run at hyperv mode and make hyperv server can't reach.
[root@dell-t320-01 ~]# cat /etc/sysconfig/virt-who  | grep -v ^# | grep -v ^$
VIRTWHO_DEBUG=1
VIRTWHO_HYPERV=1
VIRTWHO_HYPERV_OWNER=ACME_Corporation
VIRTWHO_HYPERV_ENV=Library
VIRTWHO_HYPERV_SERVER=10.73.5.22    ========>It is not reachable
VIRTWHO_HYPERV_USERNAME=administrator
VIRTWHO_HYPERV_PASSWORD=Welcome1
3. Restart virt-who service
[root@dell-t320-01 ~]# service virt-who restart
Redirecting to /bin/systemctl restart  virt-who.service
4. Stop virt-who service
[root@dell-t320-01 ~]# service virt-who stop
Redirecting to /bin/systemctl stop  virt-who.service
5. Check virt-who's log
[root@dell-t320-01 ~]# tail -f /var/log/rhsm/rhsm.log
2016-07-19 21:34:30,105 [virtwho.env_cmdline DEBUG] HyperV-1(46537):MainThread @virt.py:run:364 - Virt backend 'env/cmdline' started
2016-07-19 21:34:36,396 [virtwho.main DEBUG] MainProcess(46530):MainThread @executor.py:terminate:303 - virt-who is shutting down
2016-07-19 21:34:36,396 [virtwho.env_cmdline ERROR] HyperV-1(46537):MainThread @virt.py:run:374 - Virt backend 'env/cmdline' fails with error: Unable to connect to Hyper-V server: ('Connection aborted.', error(4, 'Interrupted system call'))
2016-07-19 21:34:36,396 [virtwho.env_cmdline DEBUG] HyperV-1(46537):MainThread @virt.py:run:387 - Virt backend 'env/cmdline' terminated
2016-07-19 21:34:37,398 [virtwho.main DEBUG] MainProcess(46530):MainThread @__main__.py:main:19 - virt-who terminated
Comment 11 Liushihui 2016-07-22 01:57:06 UTC 
Radek, I'm sorry that machine has been taken by other people. please use this  machine(hp-dl2x170g6-01.rhts.eng.bos.redhat.com  root/red2015) to check it. 
I think the key point of this problem is virt-who hasn't get any response from unreachable hyperv when stop virt-who service. Thanks.
Comment 12 Radek Novacek 2016-07-26 14:42:19 UTC 
This issue is now addressed upstream.

https://github.com/virt-who/virt-who/commit/38a96bcad56cbb6b4ecc7b5ad4d2c9a07ec970fb
Comment 14 Liushihui 2016-08-02 03:50:00 UTC 
Verified it on virt-who-0.17-7.el7.noarch since virt-who can stop normally and it wasn't any error info in the log. Therefore, verified it.

Verified version
virt-who-0.17-7.el7.noarch
subscription-manager-1.17.9-1.el7.x86_64
python-rhsm-1.17.5-1.el7.x86_64

Verified process:
1. Register system to satellite
2. Config virt-who run at hyperv mode and make hyperv server can't reach.
[root@dell-t320-01 ~]# cat /etc/sysconfig/virt-who  | grep -v ^# | grep -v ^$
VIRTWHO_DEBUG=1
VIRTWHO_HYPERV=1
VIRTWHO_HYPERV_OWNER=ACME_Corporation
VIRTWHO_HYPERV_ENV=Library
VIRTWHO_HYPERV_SERVER=10.73.5.22    ========>It is not reachable
VIRTWHO_HYPERV_USERNAME=administrator
VIRTWHO_HYPERV_PASSWORD=Welcome1
3. Restart virt-who service
[root@dell-t320-01 ~]# service virt-who restart
Redirecting to /bin/systemctl restart  virt-who.service
4. Stop virt-who service
[root@dell-t320-01 ~]# service virt-who stop
Redirecting to /bin/systemctl stop  virt-who.service
5. Check virt-who's log
[root@dell-t320-01 ~]# tail -f /var/log/rhsm/rhsm.log
==========================Start virt-who===========================
2016-08-01 23:45:23,238 [virtwho.main DEBUG] MainProcess(109604):MainThread @executor.py:terminate:303 - virt-who is shutting down
2016-08-01 23:45:23,239 [virtwho.hyperv DEBUG] HyperV-1(109611):MainThread @virt.py:run:389 - Virt backend 'hyperv' terminated
2016-08-01 23:45:24,241 [virtwho.main DEBUG] MainProcess(109604):MainThread @__main__.py:main:19 - virt-who terminated
2016-08-01 23:45:37,021 [virtwho.init DEBUG] MainProcess(109673):MainThread @executor.py:__init__:65 - Using config named 'hyperv'
2016-08-01 23:45:37,021 [virtwho.init INFO] MainProcess(109673):MainThread @main.py:main:160 - Using configuration "hyperv" ("hyperv" mode)
2016-08-01 23:45:37,022 [virtwho.init INFO] MainProcess(109673):MainThread @main.py:main:162 - Using reporter_id='hp-dl560egen8-01.khw.lab.eng.bos.redhat.com-802e3ee1794e4d728db29e3f9fbae108'
2016-08-01 23:45:37,024 [virtwho.main DEBUG] MainProcess(109673):MainThread @executor.py:run:171 - Starting infinite loop with 60 seconds interval
2016-08-01 23:45:37,064 [virtwho.hyperv DEBUG] MainProcess(109673):MainThread @hyperv.py:__init__:472 - Hyper-V url: http://10.73.5.21:5985/wsman
2016-08-01 23:45:37,067 [virtwho.hyperv DEBUG] HyperV-1(109680):MainThread @virt.py:run:364 - Virt backend 'hyperv' started

==========================Stop virt-who===========================

2016-08-01 23:45:51,591 [virtwho.main DEBUG] MainProcess(109673):MainThread @executor.py:terminate:303 - virt-who is shutting down
2016-08-01 23:45:51,591 [virtwho.hyperv DEBUG] HyperV-1(109680):MainThread @virt.py:run:389 - Virt backend 'hyperv' terminated
2016-08-01 23:45:52,594 [virtwho.main DEBUG] MainProcess(109673):MainThread @__main__.py:main:19 - virt-who terminated

6 Check virt-who's thread
[root@hp-dl560egen8-01 sysconfig]# ps -ef|grep virt-who
root     109730  12254  0 23:45 pts/0    00:00:00 grep --color=auto virt-who

Result:
Virt-who can stop normally and it hasn't shown any error info in the log.
Comment 15 Liushihui 2016-08-16 08:29:41 UTC 
It reproduced on virt-who-0.17-8.el7.noarch when virt-who run at xen mode. It occurred when virt-who hasn't get any response from unreachable xen server before stop virt-who service. Therefore, reopen it.

Reproduced version:
virt-who-0.17-8.el7.noarch
subscription-manager-1.17.10-1.el7.x86_64
python-rhsm-1.17.6-1.el7.x86_64

Reproduced process:
1. Register system to satellite5.7
2. Config virt-who run at xen mode and make xen server can't reach.
[root@hp-z220-03 virt-who.d]# cat /etc/virt-who.d/xen 
[test-xen]
type=xen
server=10.73.130.246
username=root
encrypted_password=cf0fc8adf1684c50644300e7cbd6a113
owner=ACME_Corporation
env=Library
sat_server=10.73.3.169       ========>It is not reachable
sat_username=admin
sat_password=redhat
hypervisor_id=hwuuid
3. Restart virt-who service
[root@dell-t320-01 ~]# service virt-who restart
Redirecting to /bin/systemctl restart  virt-who.service
4. Stop virt-who service
[root@dell-t320-01 ~]# service virt-who stop
Redirecting to /bin/systemctl stop  virt-who.service
5. Check virt-who's log
[root@dell-t320-01 ~]# tail -f /var/log/rhsm/rhsm.log
2016-08-16 04:19:11,659 [virtwho.main DEBUG] MainProcess(24173):MainThread @executor.py:terminate:303 - virt-who is shutting down
2016-08-16 04:19:11,659 [virtwho.test-xen ERROR] Xen-1(24180):MainThread @xen.py:login:60 - Unable to login to XENserver https://10.73.130.246
Traceback (most recent call last):
  File "/usr/lib/python2.7/site-packages/virtwho/virt/xen/xen.py", line 51, in login
    self.session.xenapi.login_with_password(self.username, self.password)
  File "/usr/lib/python2.7/site-packages/virtwho/virt/xen/XenAPI.py", line 260, in __call__
    return self.__send(self.__name, args)
  File "/usr/lib/python2.7/site-packages/virtwho/virt/xen/XenAPI.py", line 152, in xenapi_request
    self._login(methodname, params)
  File "/usr/lib/python2.7/site-packages/virtwho/virt/xen/XenAPI.py", line 175, in _login
    result = _parse_result(getattr(self, 'session.%s' % method)(*params))
  File "/usr/lib64/python2.7/xmlrpclib.py", line 1233, in __call__
    return self.__send(self.__name, args)
  File "/usr/lib64/python2.7/xmlrpclib.py", line 1587, in __request
    verbose=self.__verbose
  File "/usr/lib/python2.7/site-packages/virtwho/util.py", line 39, in request
    resp = requests.post(self._url, data=request_body, headers=headers, verify=False)
  File "/usr/lib/python2.7/site-packages/requests/api.py", line 108, in post
    return request('post', url, data=data, json=json, **kwargs)
  File "/usr/lib/python2.7/site-packages/requests/api.py", line 50, in request
    response = session.request(method=method, url=url, **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.', error(4, 'Interrupted system call'))
2016-08-16 04:19:11,660 [virtwho.test-xen DEBUG] Xen-1(24180):MainThread @virt.py:run:389 - Virt backend 'test-xen' terminated
2016-08-16 04:19:12,661 [virtwho.main DEBUG] MainProcess(24173):MainThread @__main__.py:main:19 - virt-who terminated

Result:
It will show error info "ConnectionError: ('Connection aborted.', error(4, 'Interrupted system call'))" in log.
Comment 16 Radek Novacek 2016-08-16 12:37:22 UTC 
Resolved upstream:

https://github.com/virt-who/virt-who/commit/ff2419fd1abda3a5ca3328af88821e7f9b3ed544
Comment 17 Radek Novacek 2016-08-16 16:49:31 UTC 
Fixed in virt-who-0.17-10.el7.
Comment 19 Liushihui 2016-08-31 02:36:33 UTC 
Verified it on virt-who-0.17-10.el7 since Virt-who can stop normally and it hasn't shown any error info in the log. Therefore, verify it.
Comment 21 errata-xmlrpc 2016-11-04 05:09:16 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