Bug 1248167

Summary: [RHCI] Connection aborted BadStatusLIne during rhci synchronizing content
Product: Red Hat Satellite Reporter: Thom Carlin <tcarlin>
Component: PulpAssignee: satellite6-bugs <satellite6-bugs>
Status: CLOSED WONTFIX QA Contact: jcallaha
Severity: medium Docs Contact:
Priority: unspecified    
Version: 6.1.0CC: bbuckingham, bkearney, bmbouter, chrobert, cwelton, daviddavis, dkliban, ggainey, ipanova, jcallaha, jcline, jeremy, jhutar, jmatthew, juwu, ktordeur, mhrivnak, mmccune, pcreech, rchan, thomas.betrancourt, ttereshc
Target Milestone: UnspecifiedKeywords: Reopened
Target Release: Unused   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-03-27 16:13:42 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: 1212602    
Attachments:
Description Flags
A backported patch from upstream's fix
none
RHEL7 Hotfix RPM
none
RHEL6 Hotfix RPM none

Description Thom Carlin 2015-07-29 18:44:42 UTC
Description of problem:

During RHCI Content sync, package(s) fail to download

Version-Release number of selected component (if applicable):

6.1 beta

How reproducible:

Intermittent

Steps to Reproduce:
1. RHCI Install, syncing content
2.
3.

Actual results:

Pulp errors in /var/log/messages

Expected results:

No errors

Additional info:

messages excerpt:
ul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400) ('Connection aborted.', BadStatusLine("''",))
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400) Traceback (most recent call last):
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)   File "/usr/lib/python2.7/site-packages/nectar/downloaders/threaded.py", line 190, in _fetch
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)     response = session.get(request.url, headers=headers)
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)   File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 469, in get
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)     return self.request('GET', url, **kwargs)
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)   File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 457, in request
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)     resp = self.send(prep, **send_kwargs)
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)   File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 569, in send
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)     r = adapter.send(request, **kwargs)
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)   File "/usr/lib/python2.7/site-packages/requests/adapters.py", line 407, in send
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400)     raise ConnectionError(err, request=request)
Jul 29 14:11:04 <hostname> pulp: nectar.downloaders.threaded:ERROR: (20768-86400) ConnectionError: ('Connection aborted.', BadStatusLine("''",))

Comment 1 Thom Carlin 2015-07-29 18:46:13 UTC
Checking Sync Status: Red Hat Enterprise Linux 6 Server RPMs x86_64 6Server has "New packages: 13034/15973 (22.1 GB/27 GB). Failed to download 1 package."

Workaround is to manually sync the repo?

Comment 3 John Matthews 2015-07-29 18:51:57 UTC
I've seen this several times in past ~2 weeks.

Comment 4 Thom Carlin 2015-07-29 19:08:44 UTC
Jul 29 14:59:39 <hostname> pulp: pulp.server.event.http:INFO: (20768-49984) {'call_report': {u'exception': None, u'task_type': u'pulp.server.managers.repo.sync.sync', u'task_id': u'c4ea113a-4f7a-4f01-a4b5-8e77469fed7d', u'tags': [u'pulp:repository:Default_Organization-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_6Server', u'pulp:action:sync'], u'finish_time': None, u'_ns': u'task_status', u'start_time': u'2015-07-29T16:03:39Z', u'traceback': None, u'spawned_tasks': [], u'progress_report': {u'yum_importer': {u'content': {u'size_total': 28990245476L, u'items_left': 0, u'items_total': 15973, u'state': u'FINISHED', u'size_left': 0, u'details': {u'rpm_total': 15973, u'rpm_done': 15973, u'drpm_total': 0, u'drpm_done': 0}, u'error_details': [{u'url': u'https://cdn.redhat.com/content/dist/rhel/server/6/6Server/x86_64/os/Packages/kernel-2.6.32-220.2.1.el6.x86_64.rpm', u'errors': [u'(\'Connection aborted.\', BadStatusLine("\'\'",))']}]}, u'comps': {u'state': u'FINISHED'}, u'distribution': {u'items_total': 0, u'state': u'FINISHED', u'error_details': [], u'items_left': 0}, u'errata': {u'state': u'FINISHED'}, u'metadata': {u'state': u'FINISHED'}}}, u'state': u'running', u'worker_name': u'reserved_resource_worker-6@<hostname>', u'result': None, u'error': None, u'_id': ObjectId('55b8f95b55dd531d05d07076'), u'id': u'55b8f95b908ef2512845c6db'}, 'event_type': 'repo.sync.finish', 'payload': {'importer_id': u'yum_importer', 'exception': None, 'repo_id': u'Default_Organization-Red_Hat_Enterprise_Linux_Server-Red_Hat_Enterprise_Linux_6_Server_RPMs_x86_64_6Server', 'traceback': None, 'started': '2015-07-29T16:03:39Z', '_ns': u'repo_sync_results', 'completed': '2015-07-29T18:59:39Z', 'importer_type_id': u'yum_importer', 'error_message': None, 'summary': {'content': {'state': 'FINISHED'}, 'comps': {'state': 'FINISHED'}, 'distribution': {'state': 'FINISHED'}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}, 'added_count': 19359, 'result': 'success', 'updated_count': 11, 'de
Jul 29 14:59:39 <hostname> pulp: pulp.server.event.http:INFO: (20768-49984) tails': {'content': {'size_total': 28990245476, 'items_left': 0, 'items_total': 15973, 'state': 'FINISHED', 'size_left': 0, 'details': {'rpm_total': 15973, 'rpm_done': 15973, 'drpm_total': 0, 'drpm_done': 0}, 'error_details': [{'url': u'https://cdn.redhat.com/content/dist/rhel/server/6/6Server/x86_64/os/Packages/kernel-2.6.32-220.2.1.el6.x86_64.rpm', 'errors': ['(\'Connection aborted.\', BadStatusLine("\'\'",))']}]}, 'comps': {'state': 'FINISHED'}, 'distribution': {'items_total': 0, 'state': 'FINISHED', 'error_details': [], 'items_left': 0}, 'errata': {'state': 'FINISHED'}, 'metadata': {'state': 'FINISHED'}}, 'id': '55b9229b908ef25120062adb', 'removed_count': 0}}

Comment 5 John Matthews 2015-07-29 23:14:28 UTC
Saw again (we've moved to snap14 of sat 6.1.0).

# rpm -qa | grep pulp

python-pulp-puppet-common-2.6.0.14-1.el7sat.noarch
pulp-katello-0.5-1.el7sat.noarch
python-kombu-3.0.24-9.pulp.el7sat.noarch
python-isodate-0.5.0-4.pulp.el7sat.noarch
pulp-rpm-plugins-2.6.0.14-1.el7sat.noarch
pulp-nodes-common-2.6.0.14-1.el7sat.noarch
python-pulp-common-2.6.0.14-1.el7sat.noarch
python-pulp-bindings-2.6.0.14-1.el7sat.noarch
pulp-selinux-2.6.0.14-1.el7sat.noarch
pulp-puppet-plugins-2.6.0.14-1.el7sat.noarch
rubygem-smart_proxy_pulp-1.0.1.2-1.el7sat.noarch
pulp-nodes-parent-2.6.0.14-1.el7sat.noarch
pulp-puppet-tools-2.6.0.14-1.el7sat.noarch
pulp-docker-plugins-0.2.5-1.el7sat.noarch
python-pulp-rpm-common-2.6.0.14-1.el7sat.noarch
pulp-server-2.6.0.14-1.el7sat.noarch
python-pulp-docker-common-0.2.5-1.el7sat.noarch

# rpm -qa | grep nectar
python-nectar-1.3.1-2.el7sat.noarch


Jul 29 19:10:08 localhost pulp: pulp_rpm.plugins.importers.yum.sync:INFO: Determining which units need to be downloaded.
Jul 29 19:10:08 localhost pulp: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading 108 RPMs.
Jul 29 19:10:08 localhost pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): cdn.redhat.com
Jul 29 19:10:08 localhost pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): cdn.redhat.com
Jul 29 19:10:08 localhost pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): cdn.redhat.com
Jul 29 19:10:08 localhost pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): cdn.redhat.com
Jul 29 19:10:08 localhost pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): cdn.redhat.com
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320) ('Connection aborted.', BadStatusLine("''",))
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320) Traceback (most recent call last):
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)   File "/usr/lib/python2.7/site-packages/nectar/downloaders/threaded.py", line 190, in _fetch
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)     response = session.get(request.url, headers=headers)
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)   File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 476, in get
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)     return self.request('GET', url, **kwargs)
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)   File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 464, in request
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)     resp = self.send(prep, **send_kwargs)
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)   File "/usr/lib/python2.7/site-packages/requests/sessions.py", line 576, in send
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)     r = adapter.send(request, **kwargs)
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)   File "/usr/lib/python2.7/site-packages/requests/adapters.py", line 415, in send
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320)     raise ConnectionError(err, request=request)
Jul 29 19:10:13 localhost pulp: nectar.downloaders.threaded:ERROR: (6999-16320) ConnectionError: ('Connection aborted.', BadStatusLine("''",))
Jul 29 19:10:13 localhost pulp: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (2): cdn.redhat.com

Comment 7 Ina Panova 2015-08-24 11:30:23 UTC
I opened a pulp upstream bug to track this issue down https://pulp.plan.io/issues/1210

Comment 8 jcallaha 2015-08-24 13:55:12 UTC
Might be the same issue that i'm seeing here. http://pastebin.test.redhat.com/307533

Comment 9 pulp-infra@redhat.com 2015-09-01 13:30:13 UTC
The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug.

Comment 10 pulp-infra@redhat.com 2015-09-01 13:30:15 UTC
The Pulp upstream bug priority is at High. Updating the external tracker on this bug.

Comment 14 jcallaha 2015-10-14 03:09:04 UTC
Verified in Satellite-6.1.0-RHEL-7-20151012.0 compose. 

I tested the sync of approximately 12 repos with between 15G and 28G of content per repo. The only time I encountered an issue was with a control system using an older version of Satellite.

Comment 16 errata-xmlrpc 2015-10-15 18:20:28 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://access.redhat.com/errata/RHBA-2015:1911

Comment 17 pulp-infra@redhat.com 2016-02-11 20:00:47 UTC
The Pulp upstream bug status is at CLOSED - CURRENTRELEASE. Updating the external tracker on this bug.

Comment 18 pulp-infra@redhat.com 2016-02-24 14:20:03 UTC
The Pulp upstream bug status is at NEW. Updating the external tracker on this bug.

Comment 19 pulp-infra@redhat.com 2016-02-26 16:00:39 UTC
The Pulp upstream bug status is at ASSIGNED. Updating the external tracker on this bug.

Comment 20 Jeremy Cline 2016-02-29 14:03:53 UTC
I'm untriaging this and marking it as NEW since this appears to still occur in upstream, although the exception is being swallowed. The only symptom beyond a generic 'Download failed' message is that all packages after it occurs are skipped.

This error occurs when the upstream server returns an HTTP status line (e.g. 'HTTP/1.1 200 OK') that can't be parsed by Python's httplib. In the case of the initial bug report, it seems that the server it's syncing from is returning a blank line ("''") rather than a status line.

Comment 21 pulp-infra@redhat.com 2016-02-29 15:30:46 UTC
The Pulp upstream bug status is at POST. Updating the external tracker on this bug.

Comment 22 pulp-infra@redhat.com 2016-03-01 13:30:43 UTC
The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug.

Comment 23 Jeremy Cline 2016-03-03 13:56:33 UTC
Created attachment 1132797 [details]
A backported patch from upstream's fix

I've attached a patch I backported from nectar-1.5 as a user offered to test the change. I myself have not tested the backport.

Comment 24 pulp-infra@redhat.com 2016-03-05 13:00:40 UTC
The Pulp upstream bug status is at ON_QA. Updating the external tracker on this bug.

Comment 25 Kenny Tordeurs 2016-03-07 07:26:14 UTC
FYI

Customer applied patch and all syncs are working fine now.

Comment 26 Thomas Bétrancourt 2016-03-09 10:39:13 UTC
Hello,

I have applied this patch. Since, i don't had any sync problem. Today, we have some sync problems with a repository because of AV check.

I have the following line in logs, which tell that the patch is working fine:

requests.packages.urllib3.connectionpool:WARNING: Retrying (Retry(total=2, connect=5, read=2, redirect=None)) after connection broken by 'ReadTimeoutError("HTTPConnectionPool(host=u'bluecoat', port=8080): Read timed out. (read timeout=27)",)': http://download.virtualbox.org/virtualbox/rpm/el/7/x86_64/VirtualBox-5.0-5.0.14_105127_el7-1.x86_64.rpm

Regression: while using a proxy, requests.packages.urllib3.connectionpool:INFO: Starting new HTTP connection (18): bluecoat displays proxy hostname instead of target hostname.

Expected log in this case:
requests.packages.urllib3.connectionpool:INFO: Starting new HTTP connection (18): download.virtualbox.org

I hope this can help you

Comment 27 Jeremy Cline 2016-03-09 13:42:55 UTC
Hello Thomas,

I'm glad to hear things are working, thanks so much for testing the patch!

I am hesitant to change the hostname in the log message  from requests.packages.urllib3.connectionpool to the final destination's hostname rather than the proxy hostname. Personally, I would find it confusing since it would lead me to believe that Pulp is not using the proxy at all. However, I am quite close to the problem so my perspective could very well be skewed. 

Could you perhaps expand on why it would be more helpful to have urllib3 log the target hostname? The logging has historically been quite confusing/unhelpful and I definitely want to change that.

Comment 28 Thomas Bétrancourt 2016-03-09 16:46:47 UTC
Your welcome!

About logs, I said only that the behavior has changed when your patch is applied. 

Maybe when we are synchronizing several repositories in a same time, this can be helpful to identify which one is encountering network problems.

If it is possible, something like "<proxy> -> <target>" could be fine, to show that we are using a proxy to sync this repository?

Comment 31 Mike McCune 2016-03-28 23:32:32 UTC
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions

Comment 32 Mike McCune 2016-05-12 23:22:03 UTC
= HOTFIX PACKAGES FOR SATELLITE 6.1 =

* Download python-nectar-1.3.5-1 packages attached to this bugzilla for your appropriate version of RHEL
* rpm -Uvh python-nectar-1.3.5-1..
* katello-service restart

Comment 33 Mike McCune 2016-05-12 23:22:43 UTC
Created attachment 1156938 [details]
RHEL7 Hotfix RPM

Comment 34 Mike McCune 2016-05-12 23:23:22 UTC
Created attachment 1156939 [details]
RHEL6 Hotfix RPM

Comment 35 pulp-infra@redhat.com 2016-05-24 19:31:16 UTC
The Pulp upstream bug status is at CLOSED - CURRENTRELEASE. Updating the external tracker on this bug.

Comment 36 Michael Hrivnak 2017-01-12 20:56:58 UTC
This was released with Pulp 2.8 upstream, and it appears to already be part of Satellite 6.2.

The fix is specifically in python-nectar 1.5.1

Comment 37 Bryan Kearney 2017-03-27 16:13:42 UTC
We do not plan on fixing this for Satellite 6.1. I am closing this out as WONTFIX. If you feel this was done in error, please feel free to re-open with additional information.