Bug 1248167 - [RHCI] Connection aborted BadStatusLIne during rhci synchronizing content
[RHCI] Connection aborted BadStatusLIne during rhci synchronizing content
Status: CLOSED WONTFIX
Product: Red Hat Satellite 6
Classification: Red Hat
Component: Pulp (Show other bugs)
6.1.0
Unspecified Unspecified
unspecified Severity medium (vote)
: Unspecified
: --
Assigned To: satellite6-bugs
jcallaha
: Reopened
Depends On:
Blocks: rhci-common-installer
  Show dependency treegraph
 
Reported: 2015-07-29 14:44 EDT by Thom Carlin
Modified: 2017-07-26 15:38 EDT (History)
17 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2017-03-27 12:13:42 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
A backported patch from upstream's fix (6.34 KB, patch)
2016-03-03 08:56 EST, Jeremy Cline
no flags Details | Diff
RHEL7 Hotfix RPM (44.15 KB, application/x-rpm)
2016-05-12 19:22 EDT, Mike McCune
no flags Details
RHEL6 Hotfix RPM (44.27 KB, application/x-rpm)
2016-05-12 19:23 EDT, Mike McCune
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
Pulp Redmine 1210 High CLOSED - CURRENTRELEASE ConnectionError - BadStatusLine during repo sync 2016-05-24 15:31 EDT

  None (edit)
Description Thom Carlin 2015-07-29 14:44:42 EDT
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 14:46:13 EDT
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 14:51:57 EDT
I've seen this several times in past ~2 weeks.
Comment 4 Thom Carlin 2015-07-29 15:08:44 EDT
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 19:14:28 EDT
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 07:30:23 EDT
I opened a pulp upstream bug to track this issue down https://pulp.plan.io/issues/1210
Comment 8 jcallaha 2015-08-24 09:55:12 EDT
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 09:30:13 EDT
The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug.
Comment 10 pulp-infra@redhat.com 2015-09-01 09:30:15 EDT
The Pulp upstream bug priority is at High. Updating the external tracker on this bug.
Comment 14 jcallaha 2015-10-13 23:09:04 EDT
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 14:20:28 EDT
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 15:00:47 EST
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 09:20:03 EST
The Pulp upstream bug status is at NEW. Updating the external tracker on this bug.
Comment 19 pulp-infra@redhat.com 2016-02-26 11:00:39 EST
The Pulp upstream bug status is at ASSIGNED. Updating the external tracker on this bug.
Comment 20 Jeremy Cline 2016-02-29 09:03:53 EST
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 10:30:46 EST
The Pulp upstream bug status is at POST. Updating the external tracker on this bug.
Comment 22 pulp-infra@redhat.com 2016-03-01 08:30:43 EST
The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug.
Comment 23 Jeremy Cline 2016-03-03 08:56 EST
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 08:00:40 EST
The Pulp upstream bug status is at ON_QA. Updating the external tracker on this bug.
Comment 25 Kenny Tordeurs 2016-03-07 02:26:14 EST
FYI

Customer applied patch and all syncs are working fine now.
Comment 26 Thomas Bétrancourt 2016-03-09 05:39:13 EST
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 08:42:55 EST
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 11:46:47 EST
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 19:32:32 EDT
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune@redhat.com with any questions
Comment 32 Mike McCune 2016-05-12 19:22:03 EDT
= 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 19:22 EDT
Created attachment 1156938 [details]
RHEL7 Hotfix RPM
Comment 34 Mike McCune 2016-05-12 19:23 EDT
Created attachment 1156939 [details]
RHEL6 Hotfix RPM
Comment 35 pulp-infra@redhat.com 2016-05-24 15:31:16 EDT
The Pulp upstream bug status is at CLOSED - CURRENTRELEASE. Updating the external tracker on this bug.
Comment 36 Michael Hrivnak 2017-01-12 15:56:58 EST
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 12:13:42 EDT
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.

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