Bug 1216278

Summary:	"Error in communication with subscription manager as BadStatusLine" when unregister system
Product:	Red Hat Enterprise Linux 6	Reporter:	Liushihui <shihliu>
Component:	virt-who	Assignee:	Radek Novacek <rnovacek>
Status:	CLOSED ERRATA	QA Contact:	xingge <gxing>
Severity:	medium	Docs Contact:
Priority:	unspecified
Version:	6.7	CC:	gxing, hsun, ldai, lmiksik, ovasik, rbalakri, sgao
Target Milestone:	rc
Target Release:	---
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:	virt-who-0.16-1.el6	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-05-10 23:55:01 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:

Description Liushihui 2015-04-29 02:03:21 UTC

Description of problem:
During register system, virt-who will show error info when communication with subscription manager 

Version-Release number of selected component (if applicable):
subscription-manager-1.14.5-1.el6.x86_64
python-rhsm-1.14.2-1.el6.x86_64
virt-who-0.12-5.el6.noarch
candlepin-0.9.48-1.el7.noarch
katello-2.2.0.8-1.el7sat.noarch
foreman-1.7.2.17-1.el7sat.noarch
Satellite-6.1.0-20150424.0

How reproducible:
80%

Steps to Reproduce:
1.Register system to Satellite 
2.Configure virt-who run at libvirt mode and restart virt-who service
# vim /etc/sysconfig/virt-who
VIRTWHO_BACKGROUND=1
VIRTWHO_DEBUG=1
VIRTWHO_INTERVAL=5
[root@hp-z220-04 ~]# service virt-who restart
Stopping virt-who:                                         [  OK  ]
Starting virt-who:                                         [  OK  ]
3.Unreigster system and check the virt-who's log
[root@hp-z220-04 ~]# subscription-manager unregister
[root@hp-z220-04 ~]# tail -f /var/log/rhsm/rhsm.log
2015-04-29 09:42:19,521 [DEBUG] subscription-manager:16602 @utils.py:284 - Restarted virt-who
2015-04-29 09:42:19,521 [WARNING]  @virtwho.py:202 - virt-who reload
2015-04-29 09:42:19,522 [ERROR]  @virtwho.py:111 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 102, in send
    self._sendGuestList(report)
  File "/usr/share/virt-who/virtwho.py", line 117, in _sendGuestList
    manager.sendVirtGuests(report.guests)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 120, in sendVirtGuests
    self.connection.updateConsumer(self.uuid(), guest_uuids=domains)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 839, in updateConsumer
    params['guestIds'] = self.sanitizeGuestIds(guest_uuids)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 883, in sanitizeGuestIds
    return [self.sanitizeGuestId(guestId) for guestId in guestIds or []]
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 889, in sanitizeGuestId
    if self.supports_resource('guestids'):
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 753, in supports_resource
    self._load_supported_resources()
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 740, in _load_supported_resources
    resources_list = self.conn.request_get("/")
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 602, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 512, in _request
    response = conn.getresponse()
  File "/usr/lib64/python2.6/httplib.py", line 1012, in getresponse
    response.begin()
  File "/usr/lib64/python2.6/httplib.py", line 404, in begin
    version, status, reason = self._read_status()
  File "/usr/lib64/python2.6/httplib.py", line 368, in _read_status
    raise BadStatusLine(line)
BadStatusLine

Actual results:
It will show some error log when virt-who communicate with subscription-manager

Expected results:
It should communicate with subscription-manager normally, it shouldn't show any error info.

Additional info:
It is easier to reproduce this problem after setting VIRTWHO_INTERVAL to a small value

Comment 2 Liushihui 2015-05-04 03:43:43 UTC

Sometimes, it will show the following two kinds of error info:
2015-05-04 11:26:14,117 [DEBUG] subscription-manager:16376 @utils.py:284 - Restarted virt-who
2015-05-04 11:26:14,117 [WARNING]  @virtwho.py:202 - virt-who reload
2015-05-04 11:26:21,318 [ERROR]  @virtwho.py:111 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 104, in send
    self._sendGuestAssociation(report)
  File "/usr/share/virt-who/virtwho.py", line 121, in _sendGuestAssociation
    result = manager.hypervisorCheckIn(report.config, report.association, report.config.type)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 133, in hypervisorCheckIn
    return self.connection.hypervisorCheckIn(config.owner, config.env, mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 815, in hypervisorCheckIn
    return self.conn.request_post(url, host_guest_mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 605, in request_post
    return self._request("POST", method, params)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 530, in _request
    self.validateResponse(result, request_type, handler)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 572, in validateResponse
    raise RestlibException(response['status'], error_msg)
RestlibException: undefined method `admin?' for nil:NilClass


2015-05-04 11:30:11,304 [DEBUG] subscription-manager:16456 @utils.py:284 - Restarted virt-who
2015-05-04 11:30:11,304 [WARNING]  @virtwho.py:202 - virt-who reload
2015-05-04 11:30:11,307 [ERROR]  @virtwho.py:111 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 104, in send
    self._sendGuestAssociation(report)
  File "/usr/share/virt-who/virtwho.py", line 121, in _sendGuestAssociation
    result = manager.hypervisorCheckIn(report.config, report.association, report.config.type)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 133, in hypervisorCheckIn
    return self.connection.hypervisorCheckIn(config.owner, config.env, mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 815, in hypervisorCheckIn
    return self.conn.request_post(url, host_guest_mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 605, in request_post
    return self._request("POST", method, params)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 514, in _request
    "content": response.read(),
  File "/usr/lib64/python2.6/httplib.py", line 538, in read
    return self._read_chunked(amt)
  File "/usr/lib64/python2.6/httplib.py", line 587, in _read_chunked
    value.append(self._safe_read(chunk_left))
  File "/usr/lib64/python2.6/httplib.py", line 641, in _safe_read
    raise IncompleteRead(''.join(s), amt)
IncompleteRead: IncompleteRead(0 bytes read, 7351 more expected)

Comment 3 Radek Novacek 2015-05-05 15:38:36 UTC

There are some improvements of the unregistration handling in the virt-who-0.12-7.el6. Could you please retry it with that version of virt-who?

Comment 4 Liushihui 2015-05-11 09:15:36 UTC

In the virt-who-0.12-7.el6, Unregister system to Satellite6.1.0, it will generate "error: [Errno 4] Interrupted system call" when reload virt-who. Meanwhile, it will generate too many "Error in communication with subscription manager" messages at the same time.
[NOTE]: It has not this problem when virt-who unregister to SAM 1.4.1 

2015-05-11 17:07:08,882 [ERROR]  @virtwho.py:115 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 102, in send
    self._sendGuestList(report)
  File "/usr/share/virt-who/virtwho.py", line 121, in _sendGuestList
    manager.sendVirtGuests(report.guests)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 119, in sendVirtGuests
    self.connection.updateConsumer(self.uuid(), guest_uuids=domains)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 858, in updateConsumer
    ret = self.conn.request_put(method, params)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 611, in request_put
    return self._request("PUT", method, params)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 505, 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

Test version:
virt-who-0.12-7.el6.noarch
subscription-manager-1.14.6-1.el6.x86_64
python-rhsm-1.14.2-1.el6.x86_64
candlepin-0.9.49.0-1.el7.noarch
katello-2.2.0.8-1.el7sat.noarch
foreman-1.7.2.19-1.el7sat.noarch

Comment 5 Liushihui 2015-05-12 08:49:02 UTC

It is easier to reproduce it when virt-who refresh too frequently . For example. setting VIRTWHO_INTERVAL= 5 is easier to reproduce it than setting VIRTWHO_INTERVAL= 30

Comment 6 Radek Novacek 2015-05-14 08:57:55 UTC

I can't reproduce it, but I think I made a workaround (catching that exception - it only occurs when virt-who gets the SIGHUP signal from subscription-manager).

Comment 7 Radek Novacek 2015-05-14 12:34:11 UTC

Fixed in virt-who-0.12-8.el6.

Comment 9 Liushihui 2015-05-20 07:22:30 UTC

Verified it on virt-who-0.12-8.el6.noarch since it won't generate any error when virt-who communication with subscription manager.Therefore, verify it.

Comment 10 Liushihui 2015-06-04 07:30:36 UTC

The same problem has been reproduced on virt-who-0.12-9.el6.noarch, Therefore reopen it. 
When unregistering system, it will generate error info of "BadStatusLine" when communicate with subscription-manager, please see the detail log as the following:
2015-06-04 06:13:17,012 [WARNING]  @virtwho.py:242 - virt-who reload
2015-06-04 06:13:17,012 [ERROR]  @virtwho.py:123 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 105, in send
    self._sendGuestAssociation(report)
  File "/usr/share/virt-who/virtwho.py", line 134, in _sendGuestAssociation
    result = manager.hypervisorCheckIn(report.config, report.association, report.config.type)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 132, in hypervisorCheckIn
    return self.connection.hypervisorCheckIn(config.owner, config.env, mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 815, in hypervisorCheckIn
    return self.conn.request_post(url, host_guest_mapping)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 605, in request_post
    return self._request("POST", method, params)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 512, in _request
    response = conn.getresponse()
  File "/usr/lib64/python2.6/httplib.py", line 1012, in getresponse
    response.begin()
  File "/usr/lib64/python2.6/httplib.py", line 404, in begin
    version, status, reason = self._read_status()
  File "/usr/lib64/python2.6/httplib.py", line 368, in _read_status
    raise BadStatusLine(line)
BadStatusLine

Comment 11 Radek Novacek 2015-06-04 14:33:36 UTC

Fixed in virt-who-0.12-10.el6.

Comment 12 Liushihui 2015-06-11 08:51:55 UTC

Verified it on virt-who-0.12-10.el6 since it won't generate any error log when unregister to SAM-1.4.1-RHEL-6-20141113.0 or Satellite-6.1.0-RHEL-7-20150603.1. Therefore, verify it.

Verified version:
virt-who-0.12-10.el6.noarch
subscription-manager-1.14.10-1.el6.x86_64
python-rhsm-1.14.3-1.el6.x86_64

Comment 13 Liushihui 2015-06-16 02:16:31 UTC

It has been reproduced on  virt-who-0.12-10.el6 against Satellite-6.1.0-RHEL-7-20150612.0, Therefore, reopen it.

2015-06-16 10:14:06,704 [DEBUG] rhsmd:28107 @identity.py:143 - Reload of consumer identity cert /etc/pki/consumer/cert.pem raised an exception with msg: [Errno 2] No such file or directory: '/etc/pki/consumer/key.pem'
2015-06-16 10:14:06,704 [DEBUG] rhsmd:28107 @rhsmd:148 - D-Bus signal com.redhat.SubscriptionManager.EntitlementStatus.entitlement_status_changed emitted
2015-06-16 10:14:06,704 [DEBUG] subscription-manager:28096 @utils.py:284 - Restarted virt-who
2015-06-16 10:14:06,704 [WARNING]  @virtwho.py:242 - virt-who reload
2015-06-16 10:14:06,706 [ERROR]  @virtwho.py:123 - Error in communication with subscription manager:
Traceback (most recent call last):
  File "/usr/share/virt-who/virtwho.py", line 103, in send
    self._sendGuestList(report)
  File "/usr/share/virt-who/virtwho.py", line 129, in _sendGuestList
    manager.sendVirtGuests(report.guests)
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 105, in sendVirtGuests
    self._connect()
  File "/usr/share/virt-who/manager/subscriptionmanager/subscriptionmanager.py", line 83, in _connect
    if not self.connection.ping()['result']:
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 762, in ping
    return self.conn.request_get("/status/")
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 602, in request_get
    return self._request("GET", method)
  File "/usr/lib64/python2.6/site-packages/rhsm/connection.py", line 512, in _request
    response = conn.getresponse()
  File "/usr/lib64/python2.6/httplib.py", line 1012, in getresponse
    response.begin()
  File "/usr/lib64/python2.6/httplib.py", line 404, in begin
    version, status, reason = self._read_status()
  File "/usr/lib64/python2.6/httplib.py", line 368, in _read_status
    raise BadStatusLine(line)
BadStatusLine
2015-06-16 10:14:06,709 [INFO]  @virtwho.py:576 - Reloading
2015-06-16 10:14:06,709 [DEBUG]  @virtwho.py:151 - Starting infinite loop with 10 seconds interval

Comment 15 Radek Novacek 2015-06-18 14:15:58 UTC

The problem is very minor, it's just a harmless error message that happens only when the machine is unregistered. I'll move this bug to the next release.

Comment 17 Radek Novacek 2015-12-15 12:07:48 UTC

I can't reproduce this with current upstream version, so it seems to be resolved.

Comment 18 Radek Novacek 2015-12-17 12:30:28 UTC

Fixed by rebase to virt-who-0.16-1.el6.

Comment 20 Eko 2016-01-19 08:49:53 UTC

Verified, can't be duplicated on virt-who-0.16-1.el6

Comment 22 errata-xmlrpc 2016-05-10 23:55:01 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/RHEA-2016-0859.html