Red Hat Satellite engineering is moving the tracking of its product development work on Satellite to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "Satellite project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs will be migrated starting at the end of May. If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "Satellite project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/SAT-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 2047485 - syncing repo using proxy can generate misleading log entries when proxy deny access to the url requested
Summary: syncing repo using proxy can generate misleading log entries when proxy deny ...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Satellite
Classification: Red Hat
Component: Pulp
Version: 6.10.1
Hardware: Unspecified
OS: Unspecified
unspecified
high
Target Milestone: 6.11.0
Assignee: satellite6-bugs
QA Contact: Lai
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2022-01-27 22:05 UTC by Joniel Pasqualetto
Modified: 2022-07-05 14:32 UTC (History)
6 users (show)

Fixed In Version: pulpcore-3.16.8
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2022-07-05 14:32:26 UTC
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Github pulp pulpcore issues 2654 0 None closed Improve proxy connection failure error message 2022-05-06 12:28:01 UTC
Red Hat Product Errata RHSA-2022:5498 0 None None None 2022-07-05 14:32:41 UTC

Description Joniel Pasqualetto 2022-01-27 22:05:09 UTC 
Description of problem:

The error message returned by pulp when a proxy used to sync returns a 403 is not clear and very misleading.

Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: pulp [7b674fa5-dac2-4ca1-ac25-891cfe108f56]: backoff:ERROR: Giving up download_wrapper(...) after 1 tries (aiohttp.client_exceptions.ClientHttpProxyError: 403, message='Forbidden', url=URL('http://127.0.0.1:3128'))

The URL shows the proxy address instead of the actual URL trying to be synced.

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


How reproducible:


Steps to Reproduce:
1. Configure the repository to use a proxy
2. Ensure the proxy won't allow pulp to access the URL and will return a 403
3. Launch the sync

Actual results:

Sync fails, with misleading error messages:

~~~
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: Giving up download_wrapper(...) after 1 tries (aiohttp.client_exceptions.ClientHttpProxyError: 403, message='Forbidden', url=URL('http://127.0.0.1:3128'))
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: pulp [7b674fa5-dac2-4ca1-ac25-891cfe108f56]: backoff:ERROR: Giving up download_wrapper(...) after 1 tries (aiohttp.client_exceptions.ClientHttpProxyError: 403, message='Forbidden', url=URL('http://127.0.0.1:3128'))
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: pulp [7b674fa5-dac2-4ca1-ac25-891cfe108f56]: pulp_rpm.app.tasks.synchronizing:INFO: Attempting to resolve a true url from potential mirrolist url 'https://cdn.redhat.com/content/dist/rhel/server/7/7Server/x86_64/sat-tools/6.10/os'
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: Giving up download_wrapper(...) after 1 tries (aiohttp.client_exceptions.ClientHttpProxyError: 403, message='Forbidden', url=URL('http://127.0.0.1:3128'))
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: pulp [7b674fa5-dac2-4ca1-ac25-891cfe108f56]: backoff:ERROR: Giving up download_wrapper(...) after 1 tries (aiohttp.client_exceptions.ClientHttpProxyError: 403, message='Forbidden', url=URL('http://127.0.0.1:3128'))
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: pulp [7b674fa5-dac2-4ca1-ac25-891cfe108f56]: pulpcore.tasking.pulpcore_worker:INFO: Task bd7efea8-e60a-4b4a-8f6c-b82e44dbc579 failed (403, message='Forbidden', url=URL('http://127.0.0.1:3128'))
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: pulp [7b674fa5-dac2-4ca1-ac25-891cfe108f56]: pulpcore.tasking.pulpcore_worker:INFO:   File "/usr/lib/python3.6/site-packages/pulpcore/tasking/pulpcore_worker.py", line 317, in _perform_task
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: result = func(*args, **kwargs)
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/pulp_rpm/app/tasks/synchronizing.py", line 425, in synchronize
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: remote_url = fetch_remote_url(remote)
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/pulp_rpm/app/tasks/synchronizing.py", line 289, in fetch_remote_url
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: remote_url = fetch_mirror(remote)
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/pulp_rpm/app/tasks/synchronizing.py", line 247, in fetch_mirror
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: result = downloader.fetch()
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/pulpcore/download/base.py", line 177, in fetch
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: return done.pop().result()
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/pulpcore/download/http.py", line 264, in run
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: return await download_wrapper()
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/backoff/_async.py", line 133, in retry
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: ret = await target(*args, **kwargs)
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/pulpcore/download/http.py", line 260, in download_wrapper
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: return await self._run(extra_data=extra_data)
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib/python3.6/site-packages/pulp_rpm/app/downloaders.py", line 105, in _run
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: self.url, proxy=self.proxy, proxy_auth=self.proxy_auth, auth=self.auth
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib64/python3.6/site-packages/aiohttp/client.py", line 1117, in __aenter__
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: self._resp = await self._coro
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib64/python3.6/site-packages/aiohttp/client.py", line 521, in _request
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: req, traces=traces, timeout=real_timeout
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib64/python3.6/site-packages/aiohttp/connector.py", line 535, in connect
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: proto = await self._create_connection(req, traces, timeout)
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib64/python3.6/site-packages/aiohttp/connector.py", line 890, in _create_connection
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: _, proto = await self._create_proxy_connection(req, traces, timeout)
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: File "/usr/lib64/python3.6/site-packages/aiohttp/connector.py", line 1129, in _create_proxy_connection
Jan 27 16:47:29 import-export-sat.usersys.redhat.com pulpcore-worker-2[16394]: headers=resp.headers,
~~~

Expected results:
Better handling of the error and clear error message indicating that the proxy returned an <HTTP ERRORCODE> when <REPO URL> was requested.

Additional info:
Comment 3 Daniel Alley 2022-04-29 20:50:28 UTC 
It's not really misleading.  The part that fails is the HTTP "CONNECT" call which initializes the proxy tunnel, and this is indeed the URL that the "CONNECT" call is sent to. The remote URL is completely irrelevant to the error itself because no requests have been sent there yet.

Changing the URL would make it misleading in the opposite direction because it's really the proxy which is the issue, not the remote url.  It might be reasonable to give the user more awareness of which Remote is involved so that they could possibly turn off the proxy, but even then it's a minor misdirection because any Remote using that proxy will likely fail in the same way.

Passing this back to you Joniel, not sure what the best action to take is here.
Comment 4 Joniel Pasqualetto 2022-04-29 21:14:16 UTC 
Hello dalley

When a CONNECT is sent, it goes with a destination host (the relative path we're going to fetch is not part of it, but the host is). 

For example, curl does it like this:

~~~
# curl -v https://cdn.redhat.com -k
* About to connect() to proxy squid.redhat.com port 3128 (#0)
*   Trying 10.5.30.88...
* Connected to squid.redhat.com (10.5.30.88) port 3128 (#0)
* Establish HTTP proxy tunnel to cdn.redhat.com:443
> CONNECT cdn.redhat.com:443 HTTP/1.1    <==================== destination is part of the connect request
> Host: cdn.redhat.com:443
> User-Agent: curl/7.29.0
> Proxy-Connection: Keep-Alive
> 
< HTTP/1.0 200 Connection established
< 
~~~

Not knowing what was the complete request that was blocked complicates the troubleshooting process. Also, when talking about a URL for a user perspective, the proxy is not part of it.

What about we get a log that says something like "error trying to connect to <remote host from remote URL> via <proxy URL>. That'd be super clear!
Comment 18 errata-xmlrpc 2022-07-05 14:32:26 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 (Moderate: Satellite 6.11 Release), 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/RHSA-2022:5498
Note You need to log in before you can comment on or make changes to this bug.