Bug 1401078

Summary: unrepeatable "BadStatusLine" tracebacks are silently encountered when stage testing
Product: Red Hat Enterprise Linux 6 Reporter: John Sefler <jsefler>
Component: subscription-managerAssignee: Kevin Howell <khowell>
Status: CLOSED ERRATA QA Contact: John Sefler <jsefler>
Severity: high Docs Contact:
Priority: high    
Version: 6.9CC: csnyder, khowell, redakkan, skallesh, vrjain
Target Milestone: rcKeywords: Triaged
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-03-21 10:57:48 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 John Sefler 2016-12-02 18:06:37 UTC
Description of problem:
Automated test runs are occasionally hitting failing subscription-manager command line calls with an unexpected exit code and a traceback in the rhsm.log that raises a BadStatusLine.  Here's an example...

Notice the time stamp difference in the log between the POST and the WARNING. That's over two minutes.  Maybe something is really timing out?  and if so, why?  But first, can sub-man handle the failure better?


Last request from /var/log/rhsm/rhsm.log:
2016-12-01 22:12:52,968 [DEBUG] subscription-manager:12469:MainThread @connection.py:490 - Making request: POST /subscription/consumers/8c99e4a4-2e74-4af4-b6d5-197160624e3e/entitlements
2016-12-01 22:15:20,488 [WARNING] subscription-manager:12469:MainThread @managercli.py:204 - Error during auto-attach.
2016-12-01 22:15:20,488 [ERROR] subscription-manager:12469:MainThread @managercli.py:205 - 
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/subscription_manager/managercli.py", line 200, in autosubscribe
ents = cp.bind(consumer_uuid) # new style
File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 1123, in bind
return self.conn.request_post(method)
File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 626, in request_post
return self._request("POST", method, params)
File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 512, in _request
response = conn.getresponse()
File "/usr/lib/python2.6/site-packages/rhsm/m2cryptohttp.py", line 166, in getresponse
return self._connection.getresponse(*args, **kwargs)
File "/usr/lib/python2.6/httplib.py", line 1049, in getresponse
response.begin()
File "/usr/lib/python2.6/httplib.py", line 433, in begin
version, status, reason = self._read_status()
File "/usr/lib/python2.6/httplib.py", line 397, in _read_status
raise BadStatusLine(line)
BadStatusLine
2016-12-01 22:15:20,504 [ERROR] subscription-manager:12469:MainThread @managercli.py:177 - Unable to attach: 
2016-12-01 22:15:20,504 [ERROR] subscription-manager:12469:MainThread @managercli.py:178 - 
Traceback (most recent call last):
File "/usr/lib/python2.6/site-packages/subscription_manager/managercli.py", line 1621, in _do_command
service_level=self.options.service_level)
File "/usr/lib/python2.6/site-packages/subscription_manager/managercli.py", line 200, in autosubscribe
ents = cp.bind(consumer_uuid) # new style
File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 1123, in bind
return self.conn.request_post(method)
File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 626, in request_post
return self._request("POST", method, params)
File "/usr/lib/python2.6/site-packages/rhsm/connection.py", line 512, in _request
response = conn.getresponse()
File "/usr/lib/python2.6/site-packages/rhsm/m2cryptohttp.py", line 166, in getresponse
return self._connection.getresponse(*args, **kwargs)
File "/usr/lib/python2.6/httplib.py", line 1049, in getresponse
response.begin()
File "/usr/lib/python2.6/httplib.py", line 433, in begin
version, status, reason = self._read_status()
File "/usr/lib/python2.6/httplib.py", line 397, in _read_status
raise BadStatusLine(line)
BadStatusLine


Version-Release number of selected component (if applicable):
Installed versions...
Client1 'kvm-guest-05.rhts.eng.bos.redhat.com' is running version: 
subscription-manager-firstboot-1.18.5-1.el6.i686
subscription-manager-gui-1.18.5-1.el6.i686
subscription-manager-1.18.5-1.el6.i686
subscription-manager-migration-1.18.5-1.el6.i686
subscription-manager-migration-data-2.0.32-1.el6.noarch
python-rhsm-certificates-1.18.5-1.el6.i686
python-rhsm-1.18.5-1.el6.i686

How reproducible:


Steps to Reproduce:
The traceback above came from an automated test that was doing this on the command line...
ssh root.eng.bos.redhat.com subscription-manager subscribe --auto --servicelevel=SeLf-supPOrt
Stdout: 

Service level set to: SeLf-supPOrt
Stderr: 
ExitCode: 70



Actual results:
 above

Expected results:
  did not expect an exit code of 70  The problem has nothing to do with the --servicelevel=SeLf-supPOrt.  That just happened to be the automated test case that hit this BadStatusLine response from the server.  

Additional info:

Comment 3 Chris Snyder 2016-12-05 16:29:46 UTC
The expected behaviour is to print out (to stderr) something to the effect "problem communicating with subscription management service, please try again later.". We likely already have a string that is suitable for this purpose. If not this needs to be fixed before string freeze.

Comment 4 Chris Snyder 2016-12-08 21:04:57 UTC
The fix for this bug (in the attached external tracker) has been merged upstream.
As such I'm moving this bug to POST.

Comment 6 John Sefler 2017-01-05 23:32:38 UTC
As indicated in the bug description, the offending "BadStatusLine" was unrepeatedly encountered by automated testruns.  Hence I have no way to reliably verify a fix manually.  However, automated testruns since the fix was integrated into subscription-manager-1.18.6-1, have no longer encountered a "BadStatusLine".  If I interpreted the developer's committed fix correctly, the offending situation should now give rise to a "Remote server error. Please check the connection details, or see /var/log/rhsm/rhsm.log for more information." which is a satisfactory way for subscription-manager to handle this issue.

For now I will mark this bug as VERIFIED and continue monitoring automated testruns.  If the "BadStatusLine" reoccurs, I will re-open this bug.

Reference sub-man commit bc6c652c005b28b3b4cf9272e961465877edcad5 1401078: "Remote server error" on BadStatusLine

Comment 8 errata-xmlrpc 2017-03-21 10:57:48 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/RHSA-2017-0698.html