Project

Profile

Help

Issue #3918

closed

DeclarativeVersion cannot sync longer than 5 minutes or a timeout error is raised

Added by dalley over 5 years ago. Updated over 4 years ago.

Status:
CLOSED - CURRENTRELEASE
Priority:
Normal
Assignee:
Category:
-
Sprint/Milestone:
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

Related to Pulp - Issue #3149: pulpcore.plugin.download.asyncio has surprising timeout handlingCLOSED - WONTFIXActions
Actions #1

Updated by bmbouter over 5 years ago

Can the traceback itself be included. Also how can this be reproduced (with commands or tests)?

Actions #2

Updated by dalley over 5 years ago

  • Description updated (diff)
Actions #3

Updated by dalley over 5 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/

Actions #4

Updated by bmbouter over 5 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

Actions #5

Updated by bmbouter over 5 years ago

  • Related to Issue #3149: pulpcore.plugin.download.asyncio has surprising timeout handling added
Actions #6

Updated by bmbouter over 5 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?

Actions #7

Updated by bmbouter over 5 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
Actions #8

Updated by bmbouter over 5 years ago

  • Sprint set to Sprint 41

Adding to sprint because we just missed triage and this is high-prio Pulp3 work.

Actions #9

Updated by dalley over 5 years ago

  • Status changed from NEW to POST
  • Assignee set to dalley
  • Triaged changed from No to Yes

Added by dalley over 5 years ago

Revision 42eaeb97 | View on GitHub

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

Added by dalley over 5 years ago

Revision 42eaeb97 | View on GitHub

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

Actions #10

Updated by dalley over 5 years ago

  • Status changed from POST to MODIFIED
Actions #11

Updated by daviddavis almost 5 years ago

  • Sprint/Milestone set to 3.0.0
Actions #12

Updated by bmbouter almost 5 years ago

  • Tags deleted (Pulp 3)
Actions #13

Updated by bmbouter over 4 years ago

  • Status changed from MODIFIED to CLOSED - CURRENTRELEASE

Also available in: Atom PDF