Project

Profile

Help

Actions
Send by e-mail Copy link

Issue #5163

closed

400+ errors don't show the URL it is failing on

Added by bmbouter over 5 years ago. Updated almost 5 years ago.

Status:
CLOSED - CURRENTRELEASE
Priority:
Normal
Assignee:
dkliban@redhat.com
Category:
-
Sprint/Milestone:
3.0.0
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"
Actions
Copy link
 #1

Updated by amacdona@redhat.com over 5 years ago

  • Triaged changed from No to Yes
  • Sprint set to Sprint 56
Actions
Copy link
 #2

Updated by rchan over 5 years ago

  • Sprint changed from Sprint 56 to Sprint 57
Actions
Copy link
 #3

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.

[0] https://github.com/aio-libs/aiohttp/issues/3959

Actions
Copy link
 #4

Updated by bmbouter over 5 years ago

How should we fix this in the middle term?

Actions
Copy link
 #5

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.

Actions
Copy link
 #6

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.

Actions
Copy link
 #7

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.

Actions
Copy link
 #8

Updated by rchan about 5 years ago

  • Sprint changed from Sprint 57 to Sprint 58
Actions
Copy link
 #9

Updated by dkliban@redhat.com about 5 years ago

  • Status changed from ASSIGNED to MODIFIED

aiohttp 3.6.0 has been released. The issue should be resolved.

Actions
Copy link
 #10

Updated by bmbouter almost 5 years ago

  • Sprint/Milestone set to 3.0.0
Actions
Copy link
 #11

Updated by bmbouter almost 5 years ago

  • Status changed from MODIFIED to CLOSED - CURRENTRELEASE
Actions
Send by e-mail Copy link

Also available in: Atom PDF