Actions
Issue #5163
closed
400+ errors don't show the URL it is failing on
Status:
CLOSED - CURRENTRELEASE
Priority:
Normal
Assignee:
Category:
-
Sprint/Milestone:
Start date:
Due date:
Estimated time:
Severity:
2. Medium
Version:
Platform Release:
OS:
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
Sprint:
Sprint 58
Quarter:
Description
A user contacted me with the logs below. The issue was that neither of us could see the actual url that was 404-ing so that we could verify the content was there or this was a Pulp bug.
Note that logging this information is not a good enough solution (I think) because we can't assume the log administrator is the user, and the end-user needs this info also.
This applies to any 400+ errors as raised by the response.raise_for_status() line here
ul 18 06:52:10 gprfc075.sbu.lab.eng.bos.redhat.com gunicorn[28351]: 127.0.0.1 - admin [18/Jul/2019:10:52:10 +0000] "GET /pulp/api/v3/tasks/01f034b0-a419-403a-88e8-b337a54c533a/ HTTP/1.1" 200 801 "-" "HTTPie/0.9.4"
Jul 18 06:52:11 gprfc075.sbu.lab.eng.bos.redhat.com gunicorn[28351]: 127.0.0.1 - admin [18/Jul/2019:10:52:11 +0000] "GET /pulp/api/v3/tasks/01f034b0-a419-403a-88e8-b337a54c533a/ HTTP/1.1" 200 801 "-" "HTTPie/0.9.4"
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: backoff:ERROR: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: backoff:ERROR: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: backoff:ERROR: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: backoff:ERROR: Giving up _run(...) after 1 tries (aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found')
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: rq.worker:ERROR: aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found'
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: Traceback (most recent call last):
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/rq/worker.py", line 812, in perform_job
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: rv = job.perform()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/rq/job.py", line 588, in perform
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: self._result = self._execute()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/rq/job.py", line 594, in _execute
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: return self.func(*self.args, **self.kwargs)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulp_file/app/tasks/synchronizing.py", line 45, in synchronize
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: dv.create()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/declarative_version.py", line 169, in create
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: loop.run_until_complete(pipeline)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/lib64/python3.6/asyncio/base_events.py", line 484, in run_until_complete
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: return future.result()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 209, in create_pipeline
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: await asyncio.gather(*futures)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 43, in __call__
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: await self.run()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 132, in run
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pb.done += task.result() # download_count
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 155, in _handle_content_unit
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: await asyncio.gather(*downloaders_for_content)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/models.py", line 78, in download
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: download_result = await downloader.run(extra_data=self.extra_data)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/download/base.py", line 212, in run
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: return await self._run(extra_data=extra_data)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/backoff/_async.py", line 131, in retry
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: ret = await target(*args, **kwargs)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/download/http.py", line 183, in _run
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: response.raise_for_status()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/aiohttp/client_reqrep.py", line 942, in raise_for_status
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: headers=self.headers)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found'
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: Traceback (most recent call last):
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/rq/worker.py", line 812, in perform_job
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: rv = job.perform()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/rq/job.py", line 588, in perform
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: self._result = self._execute()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/rq/job.py", line 594, in _execute
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: return self.func(*self.args, **self.kwargs)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulp_file/app/tasks/synchronizing.py", line 45, in synchronize
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: dv.create()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/declarative_version.py", line 169, in create
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: loop.run_until_complete(pipeline)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/lib64/python3.6/asyncio/base_events.py", line 484, in run_until_complete
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: return future.result()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 209, in create_pipeline
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: await asyncio.gather(*futures)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/api.py", line 43, in __call__
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: await self.run()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 132, in run
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pb.done += task.result() # download_count
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/artifact_stages.py", line 155, in _handle_content_unit
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: await asyncio.gather(*downloaders_for_content)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/stages/models.py", line 78, in download
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: download_result = await downloader.run(extra_data=self.extra_data)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/download/base.py", line 212, in run
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: return await self._run(extra_data=extra_data)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/backoff/_async.py", line 131, in retry
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: ret = await target(*args, **kwargs)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/pulpcore/plugin/download/http.py", line 183, in _run
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: response.raise_for_status()
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: File "/usr/local/lib/pulp/lib64/python3.6/site-packages/aiohttp/client_reqrep.py", line 942, in raise_for_status
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: headers=self.headers)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: aiohttp.client_exceptions.ClientResponseError: 404, message='Not Found'
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: rq.worker:INFO: Cleaning registries for queue: reserved-resource-worker-2@gprfc075.sbu.lab.eng.bos.redhat.com
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: rq.worker:INFO: reserved-resource-worker-2@gprfc075.sbu.lab.eng.bos.redhat.com: pulpcore.tasking.tasks._release_resources('01f034b0-a419-403a-88e8-b337a54c533a') (0c83745a-1f05-43e0-831e-d8e6e4a9fd18)
Jul 18 06:52:12 gprfc075.sbu.lab.eng.bos.redhat.com rq[3935]: pulp: rq.worker:INFO: reserved-resource-worker-2@gprfc075.sbu.lab.eng.bos.redhat.com: Job OK (0c83745a-1f05-43e0-831e-d8e6e4a9fd18)
Jul 18 06:52:13 gprfc075.sbu.lab.eng.bos.redhat.com gunicorn[28351]: 127.0.0.1 - admin [18/Jul/2019:10:52:13 +0000] "GET /pulp/api/v3/tasks/01f034b0-a419-403a-88e8-b337a54c533a/ HTTP/1.1" 200 3155 "-" "HTTPie/0.9.4"
Updated by amacdona@redhat.com over 5 years ago
- Triaged changed from No to Yes
- Sprint set to Sprint 56
Updated by dkliban@redhat.com over 5 years ago
- Status changed from NEW to ASSIGNED
- Assignee set to dkliban@redhat.com
I filed an issue[0] with aiohttp. I will also make a PR to fix it.
Updated by dkliban@redhat.com over 5 years ago
The only thing we can do is catch the ClientResponseError and re-raise the exception with a different message string that contains the URL.
Updated by bmbouter over 5 years ago
I agree, maybe we can add a workaround comment w/ a link to the upstream issue we are waiting on also.
Updated by dkliban@redhat.com over 5 years ago
The upstream PR has been merged. However, I am not sure when we are going to have a release.
Updated by dkliban@redhat.com over 5 years ago
- Status changed from ASSIGNED to MODIFIED
aiohttp 3.6.0 has been released. The issue should be resolved.
Updated by bmbouter about 5 years ago
- Status changed from MODIFIED to CLOSED - CURRENTRELEASE
Actions
.