838264 – subscription-manager feedback has changed during negative proxy testing

Bug 838264 - subscription-manager feedback has changed during negative proxy testing

Summary: subscription-manager feedback has changed during negative proxy testing

Keywords:
Status:	CLOSED DEFERRED
Alias:	None
Product:	Red Hat Enterprise Linux 5
Classification:	Red Hat
Component:	subscription-manager
Sub Component:
Version:	5.9
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	high
Target Milestone:	rc
Target Release:	---
Assignee:	Adrian Likins
QA Contact:	Entitlement Bugs
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:	771748
TreeView+	depends on / blocked

Reported:	2012-07-08 04:36 UTC by John Sefler
Modified:	2012-10-22 21:27 UTC (History)
CC List:	3 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2012-10-22 21:27:31 UTC
Target Upstream Version:
Embargoed:
Dependent Products:

Attachments	(Terms of Use)

Description John Sefler 2012-07-08 04:36:44 UTC

Description of problem:
I'm not sure whether to consider this change in behavior acceptable or not, but it has changed from rhel63 behavior and many automated proxy tests are catching this change/regression.  See an example in the re-create steps below...

Version-Release number of selected component (if applicable):
[root@jsefler-59server ~]# rpm -q subscription-manager python-rhsm
subscription-manager-1.0.8-1.git.14.dfc8438.el5
python-rhsm-1.0.3-1.git.0.583d26c.el5


How reproducible:


Steps to Reproduce:
[root@jsefler-59server ~]# subscription-manager list --avail --proxy=auto-services.usersys.redhat.com:3129 | head -3
+-------------------------------------------+
    Available Subscriptions
+-------------------------------------------+
[Errno 32] Broken pipe

^^^^^ THAT IS CORRECT

[root@jsefler-59server ~]# subscription-manager list --avail --proxy=BAD.com:3129 | head -3
Error updating system data, see /var/log/rhsm/rhsm.log for more details.

^^^^^ DID NOT EXPECT THIS ERROR. INSTEAD, A "Networking Error" WAS EXPECTED AS DEMONSTRATED HERE ON A RHEL63 SYSTEM.

[root@jsefler-63server ~]# subscription-manager list --avail --proxy=BAD.com:3129 | head -3
Network error, unable to connect to server.
Please see /var/log/rhsm/rhsm.log for more information.

^^^^^^ THAT FEEDBACK ON A RHEL63 SYSTEM IS CORRECT AND INFORMATIVE.  UNFORTUNATELY THIS FEEDBACK HAS CHANGED ON THE RHEL59 SYSTEM. 

  
Actual results:


Expected results:


Additional info:
tail from rhsm.log on the rhel59 system...
2012-07-08 00:24:39,029 [INFO]  @connection.py:483 - Using certificate authentication: key = /etc/pki/consumer/key.pem, cert = /etc/pki/consumer/cert.pem, ca = /etc/rhsm/ca/, insecure = False
2012-07-08 00:24:39,029 [INFO]  @connection.py:496 - Connection Built: host: jsefler-f14-candlepin.usersys.redhat.com, port: 8443, handler: /candlepin
2012-07-08 00:24:39,030 [DEBUG]  @profile.py:95 - Loading current RPM profile.
2012-07-08 00:24:39,217 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-07-08 00:24:39,218 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-07-08 00:24:39,218 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-07-08 00:24:39,219 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-07-08 00:24:39,219 [DEBUG]  @connection.py:314 - Using proxy: BAD.com:3129
2012-07-08 00:24:39,220 [DEBUG]  @connection.py:329 - Making request: GET https://jsefler-f14-candlepin.usersys.redhat.com:8443/candlepin/
2012-07-08 00:24:39,788 [DEBUG]  @managercli.py:396 - Versions: {'subscription manager': '1.0.8-1.git.14.dfc8438.el5', 'server-type': 'subscription management service', 'python-rhsm': '1.0.3-1.git.0.583d26c.el5', 'candlepin': 'Unknown'} 
2012-07-08 00:24:39,791 [INFO]  @cache.py:160 - Checking current system info against cache: /var/lib/rhsm/facts/facts.json
2012-07-08 00:24:39,892 [DEBUG]  @cert_sorter.py:106 - Sorting product and entitlement cert status for: 2012-07-08 04:24:39.891988+00:00
2012-07-08 00:24:39,962 [DEBUG]  @cert_sorter.py:160 - Installed product IDs: ['100000000000060', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '99000', '27060', '69', '917571', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000006', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000008', '100000000000009', '100000000000022', '88888', '37090', '37070']
2012-07-08 00:24:39,963 [DEBUG]  @cert_sorter.py:113 - valid entitled products: []
2012-07-08 00:24:39,964 [DEBUG]  @cert_sorter.py:114 - expired entitled products: []
2012-07-08 00:24:39,964 [DEBUG]  @cert_sorter.py:115 - partially entitled products: []
2012-07-08 00:24:39,964 [DEBUG]  @cert_sorter.py:116 - unentitled products: ['100000000000006', '1000000000000023', '1144', '100000000000011', '100000000000010', '100000000000013', '100000000000012', '100000000000015', '99000', '27060', '69', '37090', '1', '37069', '37068', '37080', '37065', '37067', '37060', '37062', '100000000000060', '100000000000007', '100000000000004', '100000000000005', '100000000000002', '100000000000003', '100000000000000', '100000000000001', '100000000000020', '100000000000008', '100000000000009', '100000000000022', '88888', '917571', '37070']
2012-07-08 00:24:39,964 [DEBUG]  @cert_sorter.py:117 - future products: []
2012-07-08 00:24:39,965 [DEBUG]  @cert_sorter.py:118 - partial stacks: []
2012-07-08 00:24:39,965 [DEBUG]  @cert_sorter.py:119 - valid stacks: []
2012-07-08 00:24:39,968 [INFO]  @cache.py:162 - System data has changed, updating server.
2012-07-08 00:24:39,970 [DEBUG]  @facts.py:139 - Updating facts on server
2012-07-08 00:24:39,973 [DEBUG]  @connection.py:308 - Loading CA PEM certificates from: /etc/rhsm/ca/
2012-07-08 00:24:39,974 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/candlepin-stage.pem'
2012-07-08 00:24:39,974 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/jsefler-f14-candlepin.pem'
2012-07-08 00:24:39,975 [DEBUG]  @connection.py:290 - Loading CA certificate: '/etc/rhsm/ca/redhat-uep.pem'
2012-07-08 00:24:39,976 [DEBUG]  @connection.py:314 - Using proxy: BAD.com:3129
2012-07-08 00:24:39,976 [DEBUG]  @connection.py:329 - Making request: PUT https://jsefler-f14-candlepin.usersys.redhat.com:8443/candlepin/consumers/9a53c860-b55a-488a-bb29-f7e1dc5aac89
2012-07-08 00:24:40,146 [ERROR]  @cache.py:170 - Error updating system data
2012-07-08 00:24:40,147 [ERROR]  @cache.py:171 - (111, 'Connection refused')
Traceback (most recent call last):
  File "/usr/share/rhsm/subscription_manager/cache.py", line 164, in update_check
    self._update_server(uep, consumer_uuid)
  File "/usr/share/rhsm/subscription_manager/facts.py", line 140, in _update_server
    uep.updateConsumer(consumer_uuid, facts=self.get_facts())
  File "/usr/lib/python2.4/site-packages/rhsm/connection.py", line 611, in updateConsumer
    ret = self.conn.request_put(method, params)
  File "/usr/lib/python2.4/site-packages/rhsm/connection.py", line 394, in request_put
    return self._request("PUT", method, params)
  File "/usr/lib/python2.4/site-packages/rhsm/connection.py", line 335, in _request
    conn.request(request_type, handler, body=body, headers=headers)
  File "/usr/lib64/python2.4/httplib.py", line 810, in request
    self._send_request(method, url, body, headers)
  File "/usr/lib64/python2.4/httplib.py", line 833, in _send_request
    self.endheaders()
  File "/usr/lib/python2.4/site-packages/rhsm/connection.py", line 124, in endheaders
    httpslib.HTTPSConnection.endheaders(self)
  File "/usr/lib64/python2.4/httplib.py", line 804, in endheaders
    self._send_output()
  File "/usr/lib64/python2.4/httplib.py", line 685, in _send_output
    self.send(msg)
  File "/usr/lib64/python2.4/httplib.py", line 652, in send
    self.connect()
  File "/usr/lib64/python2.4/site-packages/M2Crypto/httpslib.py", line 175, in connect
    HTTPConnection.connect(self)
  File "/usr/lib64/python2.4/httplib.py", line 636, in connect
    raise socket.error, msg
error: (111, 'Connection refused')
2012-07-08 00:24:40,157 [ERROR]  @managercli.py:114 - exception caught in subscription-manager
2012-07-08 00:24:40,158 [ERROR]  @managercli.py:115 - Error updating system data, see /var/log/rhsm/rhsm.log for more details.
Traceback (most recent call last):
  File "/usr/sbin/subscription-manager", line 78, in ?
    sys.exit(abs(main() or 0))
  File "/usr/sbin/subscription-manager", line 69, in main
    return managercli.CLI().main()
  File "/usr/share/rhsm/subscription_manager/managercli.py", line 1963, in main
    return cmd.main()
  File "/usr/share/rhsm/subscription_manager/managercli.py", line 400, in main
    return_code = self._do_command()
  File "/usr/share/rhsm/subscription_manager/managercli.py", line 1729, in _do_command
    self.facts, self.options.all, on_date)
  File "/usr/share/rhsm/subscription_manager/managerlib.py", line 325, in getAvailableEntitlements
    dlist = list_pools(cpserver, consumer_uuid, facts, get_all, active_on)
  File "/usr/share/rhsm/subscription_manager/managerlib.py", line 297, in list_pools
    facts.update_check(uep, consumer_uuid)
  File "/usr/share/rhsm/subscription_manager/cache.py", line 172, in update_check
    raise Exception(_("Error updating system data, see /var/log/rhsm/rhsm.log "
Exception: Error updating system data, see /var/log/rhsm/rhsm.log for more details.

Comment 2 Adrian Likins 2012-08-01 16:59:09 UTC

Seems to be the same behaviour on RHEL63 and RHEL59, with the 5.9 code, so it doesn't seem to be release dependent.

Comment 3 Adrian Likins 2012-08-01 17:28:56 UTC

This is pretty ugly on closer inspection. The generic error message is coming from a generic exception handler deep down in the cache.py code. It really shouldn't be doing that, but to fix it means finding all the places that could get network errors and making sure they have handlers. Which is better, but because of the way the cache code is intertwingled everywhere, that is hard to figure out where exactly we can get network errors. 

Can the test code be setup to handle the more generic "Error updating system data" error? That's kind of ugly, but this might take a while to untangle nicely.

Comment 4 Adrian Likins 2012-10-22 14:18:05 UTC

I don't think this should be a RHEL blocker, as I think the current behaviour is ok. We could change the error to be more precise, but it's a bigger change that I would want to introduce at this point. 

I don't think this is a regression, but an intetional behaviour change thats part of the 5.9 rebase.

Comment 6 John Sefler 2012-10-22 21:27:31 UTC

Upon further review with alikins and some re-testing with newer packages than the original bug, the current behavior with subscription-manager-1.0.23-1.el5 has improved over the original bug report. We therefore decided to open a new bug 869046 with lower severity, and move this bug to CLOSED DEFERRED.

Note You need to log in before you can comment on or make changes to this bug.