Bug 1248167
Summary: | [RHCI] Connection aborted BadStatusLIne during rhci synchronizing content | ||||||||||
---|---|---|---|---|---|---|---|---|---|---|---|
Product: | Red Hat Satellite | Reporter: | Thom Carlin <tcarlin> | ||||||||
Component: | Pulp | Assignee: | satellite6-bugs <satellite6-bugs> | ||||||||
Status: | CLOSED WONTFIX | QA Contact: | jcallaha | ||||||||
Severity: | medium | Docs Contact: | |||||||||
Priority: | unspecified | ||||||||||
Version: | 6.1.0 | CC: | 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: | Unspecified | Keywords: | 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
Thom Carlin
2015-07-29 18:44:42 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? I've seen this several times in past ~2 weeks. 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}} 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 I opened a pulp upstream bug to track this issue down https://pulp.plan.io/issues/1210 Might be the same issue that i'm seeing here. http://pastebin.test.redhat.com/307533 The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug. The Pulp upstream bug priority is at High. Updating the external tracker on this bug. 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. 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 The Pulp upstream bug status is at CLOSED - CURRENTRELEASE. Updating the external tracker on this bug. The Pulp upstream bug status is at NEW. Updating the external tracker on this bug. The Pulp upstream bug status is at ASSIGNED. Updating the external tracker on this bug. 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. The Pulp upstream bug status is at POST. Updating the external tracker on this bug. The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug. 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.
The Pulp upstream bug status is at ON_QA. Updating the external tracker on this bug. FYI Customer applied patch and all syncs are working fine now. 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 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. 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? This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune with any questions = 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 Created attachment 1156938 [details]
RHEL7 Hotfix RPM
Created attachment 1156939 [details]
RHEL6 Hotfix RPM
The Pulp upstream bug status is at CLOSED - CURRENTRELEASE. Updating the external tracker on this bug. 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 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. |