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
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