Actions
Issue #3918
closed
DeclarativeVersion cannot sync longer than 5 minutes or a timeout error is raised
Start date:
Due date:
Estimated time:
Severity:
3. High
Version:
Platform Release:
OS:
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
Sprint:
Sprint 41
Quarter:
Description
Syncing all of Django, Numpy, and Scipy packages
pjournal output:
Aug 14 16:03:53 pulp3.dev rq[31185]: pulp: rq.worker:INFO: Cleaning registries for queue: resource_manager
Aug 14 16:06:26 pulp3.dev rq[31185]: pulp: rq.worker:INFO: resource_manager: pulpcore.tasking.tasks._queue_reserved_task(<function sync at 0x7f547e45f730>, '862b2d0c-6534-4345-976d-7ce7abfc2ed4', ['/pulp/api/v3/
remotes/python/1/', '/pulp/api/v3/repositories/1/'], (), {'remote_pk': 1, 'repository_pk': 1}, {}) (6caed28b-4980-46cc-83ee-24384627b2e1)
Aug 14 16:06:26 pulp3.dev rq[31179]: pulp: rq.worker:INFO: reserved_resource_worker_1@pulp3.dev: pulp_python.app.tasks.sync.sync(remote_pk=1, repository_pk=1) (862b2d0c-6534-4345-976d-7ce7abfc2ed4)
Aug 14 16:06:26 pulp3.dev rq[31185]: pulp: rq.worker:INFO: resource_manager: Job OK (6caed28b-4980-46cc-83ee-24384627b2e1)
Aug 14 16:14:20 pulp3.dev rq[31179]: pulp: rq.worker:ERROR: concurrent.futures._base.TimeoutError
Aug 14 16:14:20 pulp3.dev rq[31179]: Traceback (most recent call last):
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/worker.py", line 793, in perform_job
Aug 14 16:14:20 pulp3.dev rq[31179]: rv = job.perform()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/job.py", line 599, in perform
Aug 14 16:14:20 pulp3.dev rq[31179]: self._result = self._execute()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/job.py", line 605, in _execute
Aug 14 16:14:20 pulp3.dev rq[31179]: return self.func(*self.args, **self.kwargs)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp_python/pulp_python/app/tasks/sync.py", line 52, in sync
Aug 14 16:14:20 pulp3.dev rq[31179]: DeclarativeVersion(first_stage, repository).create()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/declarative_version.py", line 115, in create
Aug 14 16:14:20 pulp3.dev rq[31179]: loop.run_until_complete(pipeline)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/usr/lib64/python3.6/asyncio/base_events.py", line 468, in run_until_complete
Aug 14 16:14:20 pulp3.dev rq[31179]: return future.result()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/api.py", line 57, in create_pipeline
Aug 14 16:14:20 pulp3.dev rq[31179]: await asyncio.gather(*futures)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/artifact_stages.py", line 205, in __call__
Aug 14 16:14:20 pulp3.dev rq[31179]: results = gathered_downloaders.result()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/base.py", line 54, in wrapper
Aug 14 16:14:20 pulp3.dev rq[31179]: raise error
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/base.py", line 51, in wrapper
Aug 14 16:14:20 pulp3.dev rq[31179]: return await func(downloader)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/backoff/_async.py", line 132, in retry
Aug 14 16:14:20 pulp3.dev rq[31179]: ret = yield from target(*args, **kwargs)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/http.py", line 164, in run
Aug 14 16:14:20 pulp3.dev rq[31179]: to_return = await self._handle_response(response)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/http.py", line 142, in _handle_response
Aug 14 16:14:20 pulp3.dev rq[31179]: chunk = await response.content.read(1024 * 1024)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/streams.py", line 319, in read
Aug 14 16:14:20 pulp3.dev rq[31179]: await self._wait('read')
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/streams.py", line 250, in _wait
Aug 14 16:14:20 pulp3.dev rq[31179]: await waiter
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/helpers.py", line 677, in __exit__
Aug 14 16:14:20 pulp3.dev rq[31179]: raise asyncio.TimeoutError from None
Aug 14 16:14:20 pulp3.dev rq[31179]: concurrent.futures._base.TimeoutError
Aug 14 16:14:20 pulp3.dev rq[31179]: Traceback (most recent call last):
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/worker.py", line 793, in perform_job
Aug 14 16:14:20 pulp3.dev rq[31179]: rv = job.perform()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/job.py", line 599, in perform
Aug 14 16:14:20 pulp3.dev rq[31179]: self._result = self._execute()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/job.py", line 605, in _execute
Aug 14 16:14:20 pulp3.dev rq[31179]: return self.func(*self.args, **self.kwargs)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp_python/pulp_python/app/tasks/sync.py", line 52, in sync
Aug 14 16:14:20 pulp3.dev rq[31179]: DeclarativeVersion(first_stage, repository).create()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/declarative_version.py", line 115, in create
Aug 14 16:14:20 pulp3.dev rq[31179]: loop.run_until_complete(pipeline)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/usr/lib64/python3.6/asyncio/base_events.py", line 468, in run_until_complete
Aug 14 16:14:20 pulp3.dev rq[31179]: return future.result()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/api.py", line 57, in create_pipeline
Aug 14 16:14:20 pulp3.dev rq[31179]: await asyncio.gather(*futures)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/artifact_stages.py", line 205, in __call__
Aug 14 16:14:20 pulp3.dev rq[31179]: results = gathered_downloaders.result()
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/base.py", line 54, in wrapper
Aug 14 16:14:20 pulp3.dev rq[31179]: raise error
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/base.py", line 51, in wrapper
Aug 14 16:14:20 pulp3.dev rq[31179]: return await func(downloader)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/backoff/_async.py", line 132, in retry
Aug 14 16:14:20 pulp3.dev rq[31179]: ret = yield from target(*args, **kwargs)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/http.py", line 164, in run
Aug 14 16:14:20 pulp3.dev rq[31179]: to_return = await self._handle_response(response)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/http.py", line 142, in _handle_response
Aug 14 16:14:20 pulp3.dev rq[31179]: chunk = await response.content.read(1024 * 1024)
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/streams.py", line 319, in read
Aug 14 16:14:20 pulp3.dev rq[31179]: await self._wait('read')
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/streams.py", line 250, in _wait
Aug 14 16:14:20 pulp3.dev rq[31179]: await waiter
Aug 14 16:14:20 pulp3.dev rq[31179]: File "/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/helpers.py", line 677, in __exit__
Aug 14 16:14:20 pulp3.dev rq[31179]: raise asyncio.TimeoutError from None
Aug 14 16:14:20 pulp3.dev rq[31179]: concurrent.futures._base.TimeoutError
Aug 14 16:14:20 pulp3.dev rq[31179]: pulp: rq.worker:WARNING: Moving job to 'failed' queue
Aug 14 16:14:20 pulp3.dev rq[31179]: pulp: rq.worker:INFO: reserved_resource_worker_1@pulp3.dev: pulpcore.tasking.tasks._release_resources('862b2d0c-6534-4345-976d-7ce7abfc2ed4') (f8e55eea-a164-4e63-a554-6bc9c5f7c6d8)
task result:
{
"id":"862b2d0c-6534-4345-976d-7ce7abfc2ed4",
"_href":"http://localhost:8000/pulp/api/v3/tasks/862b2d0c-6534-4345-976d-7ce7abfc2ed4/",
"created":"2018-08-14T16:06:26.838562Z",
"state":"failed",
"started_at":"2018-08-14T16:06:26.942774Z",
"finished_at":"2018-08-14T16:14:20.708025Z",
"non_fatal_errors":[
],
"error":{
"code":null,
"description":"",
"traceback":" File \"/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/worker.py\", line 793, in perform_job\n rv = job.perform()\n File \"/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/job.py\", line 599, in perform\n self._result = self._execute()\n File \"/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/rq/job.py\", line 605, in _execute\n return self.func(*self.args, **self.kwargs)\n File \"/home/vagrant/devel/pulp_python/pulp_python/app/tasks/sync.py\", line 52, in sync\n DeclarativeVersion(first_stage, repository).create()\n File \"/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/declarative_version.py\", line 115, in create\n loop.run_until_complete(pipeline)\n File \"/usr/lib64/python3.6/asyncio/base_events.py\", line 468, in run_until_complete\n return future.result()\n File \"/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/api.py\", line 57, in create_pipeline\n await asyncio.gather(*futures)\n File \"/home/vagrant/devel/pulp/plugin/pulpcore/plugin/stages/artifact_stages.py\", line 205, in __call__\n results = gathered_downloaders.result()\n File \"/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/base.py\", line 54, in wrapper\n raise error\n File \"/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/base.py\", line 51, in wrapper\n return await func(downloader)\n File \"/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/backoff/_async.py\", line 132, in retry\n ret = yield from target(*args, **kwargs)\n File \"/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/http.py\", line 164, in run\n to_return = await self._handle_response(response)\n File \"/home/vagrant/devel/pulp/plugin/pulpcore/plugin/download/http.py\", line 142, in _handle_response\n chunk = await response.content.read(1024 * 1024)\n File \"/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/streams.py\", line 319, in read\n await self._wait('read')\n File \"/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/streams.py\", line 250, in _wait\n await waiter\n File \"/home/vagrant/.virtualenvs/pulp/lib64/python3.6/site-packages/aiohttp/helpers.py\", line 677, in __exit__\n raise asyncio.TimeoutError from None\n"
},
"worker":"http://localhost:8000/pulp/api/v3/workers/1/",
"parent":null,
"spawned_tasks":[
],
"progress_reports":[
{
"message":"Un-Associating Content",
"state":"running",
"total":null,
"done":0,
"suffix":"",
"task":"http://localhost:8000/pulp/api/v3/tasks/862b2d0c-6534-4345-976d-7ce7abfc2ed4/"
},
{
"message":"Fetching Project Metadata",
"state":"completed",
"total":3,
"done":3,
"suffix":"",
"task":"http://localhost:8000/pulp/api/v3/tasks/862b2d0c-6534-4345-976d-7ce7abfc2ed4/"
},
{
"message":"Associating Content",
"state":"running",
"total":null,
"done":318,
"suffix":"",
"task":"http://localhost:8000/pulp/api/v3/tasks/862b2d0c-6534-4345-976d-7ce7abfc2ed4/"
},
{
"message":"Downloading Artifacts",
"state":"failed",
"total":319,
"done":319,
"suffix":"",
"task":"http://localhost:8000/pulp/api/v3/tasks/862b2d0c-6534-4345-976d-7ce7abfc2ed4/"
}
],
"created_resources":[
]
}
Related issues
Updated by bmbouter over 6 years ago
Can the traceback itself be included. Also how can this be reproduced (with commands or tests)?
Updated by dalley over 6 years ago
Follow the instructions here except change the remote to include the Django, Numpy, and Scipy projects (and any others, more is probably better) with empty version specifiers.
http://pulp-python.readthedocs.io/en/3.0-dev/workflows/sync/
Updated by bmbouter over 6 years ago
The default timeout for aiohttp is 5 minutes https://aiohttp.readthedocs.io/en/stable/client_quickstart.html#timeouts
The default can also be disabled.
Pulp currently does not specify any type of timeout. It does instantiate ClientSession in multiple places though which is where it needs to be specified, so introducing any changes need to happen in a few places.
One place is here in the dowloaders: https://github.com/pulp/pulp/blob/master/plugin/pulpcore/plugin/download/http.py#L120
Another is in the DownloaderFactory here: https://github.com/pulp/pulp/blob/master/plugin/pulpcore/plugin/download/factory.py#L92
FYI, this issue seems related: https://pulp.plan.io/issues/3149
Updated by bmbouter over 6 years ago
- Related to Issue #3149: pulpcore.plugin.download.asyncio has surprising timeout handling added
Updated by bmbouter over 6 years ago
I believe a 5 min total timeout won't work at all for us. aiohttp reuses connections so that timeout is for the entire life of the connection, which is "all the downloads" of the sync. This could sometimes take hours, or even days. Syncing over slow WAN links from remote places (we have users who do this).
I think the best thing we could do is to have the Downloaders and the Factory places disable all aiohttp timeouts. What do you all think?
Updated by bmbouter over 6 years ago
- Subject changed from TimeoutError w/ medium sized sync (Python plugin) inside Downloader Stages to DeclarativeVersion cannot sync longer than 5 minutes or a timeout error is raised
Updated by bmbouter over 6 years ago
- Sprint set to Sprint 41
Adding to sprint because we just missed triage and this is high-prio Pulp3 work.
Updated by dalley over 6 years ago
- Status changed from NEW to POST
- Assignee set to dalley
- Triaged changed from No to Yes
Added by dalley over 6 years ago
Added by dalley over 6 years ago
Revision 42eaeb97 | View on GitHub
Fix DeclarativeVersion timeout error
Fixes an issue where syncs > 5 minutes long would time out and fail
Updated by dalley over 6 years ago
- Status changed from POST to MODIFIED
Applied in changeset pulp|42eaeb971c9c5e18dfdc89aa89a2239afa738f2d.
Updated by bmbouter almost 5 years ago
- Status changed from MODIFIED to CLOSED - CURRENTRELEASE
Actions
.
Fix DeclarativeVersion timeout error
Fixes an issue where syncs > 5 minutes long would time out and fail
closes #3918 https://pulp.plan.io/issues/3918