Project

Profile

Help

Actions
Send by e-mail Copy link

Issue #2272

closed

Downloading on_demand repositories silently fails

Added by Ichimonji10 over 7 years ago. Updated about 5 years ago.

Status:
CLOSED - CURRENTRELEASE
Priority:
Normal
Assignee:
bizhang
Sprint/Milestone:
-
Start date:
Due date:
Estimated time:
Severity:
3. High
Version:
Platform Release:
OS:
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
Pulp 2
Sprint:
Sprint 9
Quarter:

Description

Let's say I execute the following commands:

pulp-admin rpm repo create \
    --repo-id ichi \
    --feed 'https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm/' \
    --download-policy on_demand
pulp-admin -vv rpm repo sync run --repo-id ichi
pulp-admin -vv repo download --repo-id ichi

Importantly, the repository has an on_demand download policy. As a result, the repo sync run command doesn't download any content units from the remote repository onto disk. The third command forces content units to be downloaded onto disk. (Adding --verify-all has no effect.)

For more information on this feature, see:

Well, that's what's supposed to happen. In reality, Pulp never downloads any content units onto disk. This especially apparent if one resets Pulp directly before executing the script above: no /var/lib/pulp/content directory is created.

The system logs show no indication that anything has gone wrong:

Sep 20 17:14:09 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Parsing metadata.
Sep 20 17:14:09 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm/.
Sep 20 17:14:09 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Sep 20 17:14:10 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Parsing metadata.
Sep 20 17:14:10 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm/.
Sep 20 17:14:10 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Sep 20 17:14:11 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Parsing metadata.
Sep 20 17:14:11 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata files.
Sep 20 17:14:11 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (2): repos.fedorapeople.org
Sep 20 17:14:11 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (3): repos.fedorapeople.org
Sep 20 17:14:11 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (4): repos.fedorapeople.org
Sep 20 17:14:11 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (5): repos.fedorapeople.org
Sep 20 17:14:12 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Generating metadata databases.
Sep 20 17:14:12 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Determining which units need to be downloaded.
Sep 20 17:14:13 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading additional units.
Sep 20 17:14:13 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Sep 20 17:14:14 example.com pulp[19129]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Sep 20 17:14:15 example.com pulp[19129]: pulp_rpm.plugins.importers.yum.sync:INFO: Sync complete.
Sep 20 17:14:15 example.com pulp[19129]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Sep 20 17:14:15 example.com pulp[18665]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[89880999-403a-4082-87b3-0755bec46e31]
Sep 20 17:14:15 example.com pulp[19060]: celery.worker.job:INFO: Task pulp.server.managers.repo.sync.sync[a56c5125-0061-4812-8be4-c7800ee25ac3] succeeded in 6.763268247s: <pulp.server.async.tasks.TaskResult object at 0x7fd1d404bcd0>
Sep 20 17:14:15 example.com pulp[19060]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[d6ad75e6-0796-43e2-a7df-1f58cbdf719f] succeeded in 0.00523663999957s: None
Sep 20 17:14:15 example.com pulp[19060]: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.publish.publish[b076362f-2c4b-49c0-be65-446efe878050]
Sep 20 17:14:15 example.com pulp[19060]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[7d2436ee-10c2-4af6-97be-baece2cf2dff]
Sep 20 17:14:15 example.com pulp[18665]: celery.worker.job:INFO: Task pulp.server.async.tasks._queue_reserved_task[89880999-403a-4082-87b3-0755bec46e31] succeeded in 0.0365141399998s: None
Sep 20 17:14:15 example.com pulp[19060]: celery.worker.job:INFO: Task pulp.server.managers.repo.publish.publish[b076362f-2c4b-49c0-be65-446efe878050] succeeded in 0.550737492s: {'exception': None, 'repo_id': u'cd95133a-af28-4ad7-b2fb-ab91102344ad', 'traceback': None, 'started': '2016-09-20T21:14:15Z',...
Sep 20 17:14:15 example.com pulp[19060]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[7d2436ee-10c2-4af6-97be-baece2cf2dff] succeeded in 0.00386058500044s: None
Sep 20 17:14:22 example.com pulp[19056]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_repo[1ec5ace1-3b7e-473b-9f13-2b78bd2f9cc1]
Sep 20 17:14:22 example.com pulp[19126]: py.warnings:WARNING: (19126-06368) /usr/lib64/python2.7/site-packages/pymongo/topology.py:74: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: http://api.mongodb.org/python/current/faq.html#using-pymongo-with-multiprocessing>
Sep 20 17:14:22 example.com pulp[19126]: py.warnings:WARNING: (19126-06368)   "MongoClient opened before fork. Create MongoClient "
Sep 20 17:14:22 example.com pulp[19126]: py.warnings:WARNING: (19126-06368)
Sep 20 17:14:23 example.com pulp[19126]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): example.com
Sep 20 17:14:23 example.com pulp[19126]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (2): example.com
Sep 20 17:14:23 example.com pulp[19126]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (3): example.com
Sep 20 17:14:23 example.com pulp[19126]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (4): example.com
Sep 20 17:14:23 example.com pulp[19126]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (5): example.com
Sep 20 17:14:24 example.com pulp[19056]: celery.worker.job:INFO: Task pulp.server.controllers.repository.download_repo[1ec5ace1-3b7e-473b-9f13-2b78bd2f9cc1] succeeded in 1.167712049s: None

The best clue I have as to what's wrong are the task reports. Here's an example of what pulp-admin writes to console during the execution of the third script command, above:

Download Repository Content
[=                                                 ] 3%
1 of 32 items
... failed
2016-09-20 19:46:39,862 - DEBUG - sending GET request to /pulp/api/v2/tasks/173b6fac-98d2-4faf-8e87-9f9be41e4011/
2016-09-20 19:46:39,888 - INFO - GET request to /pulp/api/v2/tasks/173b6fac-98d2-4faf-8e87-9f9be41e4011/ with parameters None
2016-09-20 19:46:39,888 - INFO - Response status : 200 

2016-09-20 19:46:39,888 - INFO - Response body :
 {
  "exception": null, 
  "task_type": "pulp.server.controllers.repository.download_repo", 
  "_href": "/pulp/api/v2/tasks/173b6fac-98d2-4faf-8e87-9f9be41e4011/", 
  "task_id": "173b6fac-98d2-4faf-8e87-9f9be41e4011", 
  "tags": [
    "pulp:repository:ichi", 
    "pulp:action:download"
  ], 
  "finish_time": "2016-09-20T23:46:38Z", 
  "_ns": "task_status", 
  "start_time": "2016-09-20T23:46:37Z", 
  "traceback": null, 
  "spawned_tasks": [], 
  "progress_report": {
    "background_download": [
      {
        "num_success": 0, 
        "description": "Download Repository Content", 
        "step_type": "background_download", 
        "items_total": 32, 
        "state": "FAILED", 
        "error_details": [], 
        "details": "", 
        "num_failures": 1, 
        "step_id": "ac523705-9187-49a4-b3b7-4bbdc75b716d", 
        "num_processed": 1
      }
    ]
  }, 
  "queue": "celery.dq", 
  "state": "finished", 
  "worker_name": "celery", 
  "result": null, 
  "error": null, 
  "_id": {
    "$oid": "57e1ca5dcf39b1f2105dc504"
  }, 
  "id": "57e1ca5dcf39b1f2105dc504"
}

Task Succeeded

Notice the ... failed?

Here's an example of the task reports generated by a POST call to /pulp/api/v2/repositories/<repo_id>/actions/download/:

({'_href': '/pulp/api/v2/tasks/1ec5ace1-3b7e-473b-9f13-2b78bd2f9cc1/',
  '_id': {'$oid': '57e1a6aecf39b1f2105dc41e'},
  '_ns': 'task_status',
  'error': None,
  'exception': None,
  'finish_time': '2016-09-20T21:14:24Z',
  'id': '57e1a6aecf39b1f2105dc41e',
  'progress_report': {'background_download': [{'description': 'Download '
                                                              'Repository '
                                                              'Content',
                                               'details': '',
                                               'error_details': [],
                                               'items_total': 32,
                                               'num_failures': 1,
                                               'num_processed': 1,
                                               'num_success': 0,
                                               'state': 'FAILED',
                                               'step_id': '9cf8c6a6-e1a5-40f9-a8da-7415924f3892',
                                               'step_type': 'background_download'}]},
  'queue': 'celery.dq',
  'result': None,
  'spawned_tasks': [],
  'start_time': '2016-09-20T21:14:22Z',
  'state': 'finished',
  'tags': ['pulp:repository:cd95133a-af28-4ad7-b2fb-ab91102344ad',
           'pulp:action:download'],
  'task_id': '1ec5ace1-3b7e-473b-9f13-2b78bd2f9cc1',
  'task_type': 'pulp.server.controllers.repository.download_repo',
  'traceback': None,
  'worker_name': 'celery'},)

I've observed this issue on Pulp 2.10.1 and 2.11.0 systems provisioned this morning, on Fedora 24 and 23, respectively. Here's the exact packages on the test Fedora 24 system:

$ grep PRETTY /etc/os-release 
PRETTY_NAME="Fedora 24 (Twenty Four)"
$ rpm -qa | sort | grep -i pulp
pulp-admin-client-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
pulp-docker-admin-extensions-2.1.1-0.1.alpha.git.25.0292bec.fc24.noarch
pulp-docker-plugins-2.1.1-0.1.alpha.git.25.0292bec.fc24.noarch
pulp-puppet-admin-extensions-2.10.1-0.1.alpha.git.40.b5a745b.fc24.noarch
pulp-puppet-plugins-2.10.1-0.1.alpha.git.40.b5a745b.fc24.noarch
pulp-python-admin-extensions-1.1.2-1.fc24.noarch
pulp-python-plugins-1.1.2-1.fc24.noarch
pulp-rpm-admin-extensions-2.10.1-0.1.alpha.git.46.9669d43.fc24.noarch
pulp-rpm-plugins-2.10.1-0.1.alpha.git.46.9669d43.fc24.noarch
pulp-selinux-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
pulp-server-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
python-kombu-3.0.33-6.pulp.fc24.noarch
python-pulp-bindings-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
python-pulp-client-lib-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
python-pulp-common-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
python-pulp-docker-common-2.1.1-0.1.alpha.git.25.0292bec.fc24.noarch
python-pulp-oid_validation-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
python-pulp-puppet-common-2.10.1-0.1.alpha.git.40.b5a745b.fc24.noarch
python-pulp-python-common-1.1.2-1.fc24.noarch
python-pulp-repoauth-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch
python-pulp-rpm-common-2.10.1-0.1.alpha.git.46.9669d43.fc24.noarch
python-pulp-streamer-2.10.1-0.1.alpha.git.27.5ceb370.fc24.noarch

Here's the exact packages on the test Fedora 23 system:

$ grep PRETTY /etc/os-release 
PRETTY_NAME="Fedora 23 (Twenty Three)"
$ rpm -qa | sort | grep -i pulp
pulp-admin-client-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
pulp-docker-admin-extensions-2.2.0-0.1.alpha.git.201.dcabfb1.fc23.noarch
pulp-docker-plugins-2.2.0-0.1.alpha.git.201.dcabfb1.fc23.noarch
pulp-ostree-admin-extensions-1.2.0-0.1.alpha.git.104.777be19.fc23.noarch
pulp-ostree-plugins-1.2.0-0.1.alpha.git.104.777be19.fc23.noarch
pulp-puppet-admin-extensions-2.11.0-0.1.alpha.git.187.e97c179.fc23.noarch
pulp-puppet-plugins-2.11.0-0.1.alpha.git.187.e97c179.fc23.noarch
pulp-python-admin-extensions-1.2.0-0.1.alpha.git.108.e1444cf.fc23.noarch
pulp-python-plugins-1.2.0-0.1.alpha.git.108.e1444cf.fc23.noarch
pulp-rpm-admin-extensions-2.11.0-0.1.alpha.git.525.4e07924.fc23.noarch
pulp-rpm-plugins-2.11.0-0.1.alpha.git.525.4e07924.fc23.noarch
pulp-selinux-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
pulp-server-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
python-kombu-3.0.33-6.pulp.fc23.noarch
python-pulp-bindings-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
python-pulp-client-lib-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
python-pulp-common-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
python-pulp-docker-common-2.2.0-0.1.alpha.git.201.dcabfb1.fc23.noarch
python-pulp-oid_validation-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
python-pulp-ostree-common-1.2.0-0.1.alpha.git.104.777be19.fc23.noarch
python-pulp-puppet-common-2.11.0-0.1.alpha.git.187.e97c179.fc23.noarch
python-pulp-python-common-1.2.0-0.1.alpha.git.108.e1444cf.fc23.noarch
python-pulp-repoauth-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
python-pulp-rpm-common-2.11.0-0.1.alpha.git.525.4e07924.fc23.noarch
python-pulp-streamer-2.11.0-0.1.alpha.git.692.ab3aa93.fc23.noarch
Actions
Send by e-mail Copy link

Also available in: Atom PDF