Issue #2272
closedDownloading on_demand repositories silently fails
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:
- http://docs.pulpproject.org/dev-guide/integration/rest-api/repo/sync.html?highlight=verify_all_units#download-a-repository
- http://docs.pulpproject.org/user-guide/deferred-download.html?highlight=verify_all_units#re-using-files-on-disk-when-db-is-lost
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
Starts pulp_streamer with other pulp services
This is so plugins are loaded into the streamer.
closes #2272 https://pulp.plan.io/issues/2272