Issue #2363: Pulp acts like all is well when a sync completely fails - RPM Support - Pulp

Actions

Send by e-mail Copy link

Issue #2363

closed

Pulp acts like all is well when a sync completely fails

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

Status:

CLOSED - CURRENTRELEASE

Priority:

Urgent

Assignee:

ttereshc

Sprint/Milestone:

Start date:

Due date:

Estimated time:

Severity:

3. High

Version:

Platform Release:

2.11.0

OS:

Triaged:

Yes

Groomed:

Sprint Candidate:

Tags:

Pulp 2

Sprint:

Sprint 10

Quarter:

Description

Let's say you create an RPM repository and sync it, like so:

#!/usr/bin/env bash

pulp-admin rpm repo create --repo-id foo --feed 'https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-mirrorlist-bad'
pulp-admin rpm repo sync run --repo-id foo

On Pulp 2.11, this script succeeds. Absolutely no errors are reported. This is a problem, because the given feed has no valid mirrorlist entries. Here's a copy-paste of its current contents:

https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/

Indeed, one can use this URL directly in a test script:

#!/usr/bin/env bash

pulp-admin rpm repo create --repo-id foo --feed 'https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/'
pulp-admin rpm repo sync run --repo-id foo

This script also succeeds on Pulp 2.11. Absolutely no errors are reported.

This doesn't seem right. In my opinion, a failed sync should be reported to the user.

Here's what's logged into journalctl when the first script runs. Notice the "WARNING" line.

Oct 19 14:13:25 pulp.example.com pulp[7629]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Oct 19 14:13:25 pulp.example.com pulp[7647]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[aa0eb0a1-d12c-4f57-a8c5-e091f564c7ea]
Oct 19 14:13:25 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.sync.sync[7a269318-8919-4b75-8f59-c17b35bcbe72]
Oct 19 14:13:25 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[44d40ab7-b66c-4e65-9238-1e0ccf5a0093]
Oct 19 14:13:25 pulp.example.com pulp[7647]: celery.worker.job:INFO: Task pulp.server.async.tasks._queue_reserved_task[aa0eb0a1-d12c-4f57-a8c5-e091f564c7ea] succeeded in 0.0655890779999s: None
Oct 19 14:13:25 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-mirrorlist-bad/.
Oct 19 14:13:25 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:13:26 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:13:26 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-mirrorlist-bad/.
Oct 19 14:13:26 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:13:27 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:13:27 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/.
Oct 19 14:13:27 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:13:28 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading additional units.
Oct 19 14:13:28 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:13:29 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:13:30 pulp.example.com pulp[7834]: pulp.server.controllers.repository:WARNING: Plugin type [yum_importer] on repo [foo] did not return a valid sync report
Oct 19 14:13:30 pulp.example.com pulp[7834]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Oct 19 14:13:30 pulp.example.com pulp[7647]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[2071e91a-be26-4c6f-b5e2-46d8ddd313ce]
Oct 19 14:13:30 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.publish.publish[22b135fe-0a93-4610-bb5e-de942d0392e5]
Oct 19 14:13:30 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.managers.repo.sync.sync[7a269318-8919-4b75-8f59-c17b35bcbe72] succeeded in 5.731223118s: <pulp.server.async.tasks.TaskResult object at 0x7f3c70b97f90>
Oct 19 14:13:30 pulp.example.com pulp[7647]: celery.worker.job:INFO: Task pulp.server.async.tasks._queue_reserved_task[2071e91a-be26-4c6f-b5e2-46d8ddd313ce] succeeded in 0.0782126609993s: None
Oct 19 14:13:30 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[44d40ab7-b66c-4e65-9238-1e0ccf5a0093] succeeded in 0.0319390320001s: None
Oct 19 14:13:30 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[e4b4d812-6b2a-4eb2-8816-866d86c1d440]
Oct 19 14:13:31 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.managers.repo.publish.publish[22b135fe-0a93-4610-bb5e-de942d0392e5] succeeded in 0.302907476s: {'exception': None, 'repo_id': u'foo', 'traceback': None, 'started': '2016-10-19T18:13:30Z', '_ns': u'repo_publish_results',...
Oct 19 14:13:31 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[e4b4d812-6b2a-4eb2-8816-866d86c1d440] succeeded in 0.012067054s: None

Here's what's logged into the log when the second script runs. Again, notice the "WARNING" line.

Oct 19 14:18:32 pulp.example.com pulp[7647]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[d3fd26ed-b4aa-4cf1-8892-9c7f70bf2ea5]
Oct 19 14:18:32 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.sync.sync[360b72f7-82b4-45d5-8e7b-c11364996123]
Oct 19 14:18:32 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[e70e2e5f-93c5-46ad-8df2-746f81789b5e]
Oct 19 14:18:32 pulp.example.com pulp[7647]: celery.worker.job:INFO: Task pulp.server.async.tasks._queue_reserved_task[d3fd26ed-b4aa-4cf1-8892-9c7f70bf2ea5] succeeded in 0.0647222320003s: None
Oct 19 14:18:32 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/.
Oct 19 14:18:32 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:18:33 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:18:33 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/.
Oct 19 14:18:33 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:18:34 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:18:35 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/.
Oct 19 14:18:35 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:18:36 pulp.example.com pulp[7834]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading additional units.
Oct 19 14:18:36 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:18:37 pulp.example.com pulp[7834]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:18:38 pulp.example.com pulp[7834]: pulp.server.controllers.repository:WARNING: Plugin type [yum_importer] on repo [foo] did not return a valid sync report
Oct 19 14:18:38 pulp.example.com pulp[7647]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[d4078d8d-92ee-4b66-94b0-3507a93912cb]
Oct 19 14:18:38 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.publish.publish[14072bf0-4007-4175-a9f3-d66059b323d0]
Oct 19 14:18:38 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.managers.repo.sync.sync[360b72f7-82b4-45d5-8e7b-c11364996123] succeeded in 5.645285756s: <pulp.server.async.tasks.TaskResult object at 0x7f3c70b97610>
Oct 19 14:18:38 pulp.example.com pulp[7647]: celery.worker.job:INFO: Task pulp.server.async.tasks._queue_reserved_task[d4078d8d-92ee-4b66-94b0-3507a93912cb] succeeded in 0.0789843820003s: None
Oct 19 14:18:38 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[e70e2e5f-93c5-46ad-8df2-746f81789b5e] succeeded in 0.0312013190014s: None
Oct 19 14:18:38 pulp.example.com pulp[7600]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[32b75879-8374-4584-a6e2-dd725b8064aa]
Oct 19 14:18:38 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.managers.repo.publish.publish[14072bf0-4007-4175-a9f3-d66059b323d0] succeeded in 0.313760993s: {'exception': None, 'repo_id': u'foo', 'traceback': None, 'started': '2016-10-19T18:18:38Z', '_ns': u'repo_publish_results',...
Oct 19 14:18:38 pulp.example.com pulp[7600]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[32b75879-8374-4584-a6e2-dd725b8064aa] succeeded in 0.0135559279988s: None

In contrast, a Pulp 2.10 system will correctly report an error when the following script is executed:

#!/usr/bin/env bash

pulp-admin rpm repo create --repo-id foo --feed 'https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/'
pulp-admin rpm repo sync run --repo-id foo

And here's an example of what a Pulp 2.10 system logs. Notice the lack of a warning related to an invalid sync report.

Oct 19 14:26:27 localhost.localdomain pulp[9511]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Oct 19 14:26:27 localhost.localdomain pulp[9490]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._queue_reserved_task[13606902-a6e4-4429-bea1-19c05e51e918]
Oct 19 14:26:27 localhost.localdomain pulp[9758]: py.warnings:WARNING: (9758-19104) /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>
Oct 19 14:26:27 localhost.localdomain pulp[9758]: py.warnings:WARNING: (9758-19104)   "MongoClient opened before fork. Create MongoClient "
Oct 19 14:26:27 localhost.localdomain pulp[9758]: py.warnings:WARNING: (9758-19104)
Oct 19 14:26:27 localhost.localdomain pulp[9758]: kombu.transport.qpid:INFO: Connected to qpid with SASL mechanism ANONYMOUS
Oct 19 14:26:27 localhost.localdomain pulp[9591]: celery.worker.strategy:INFO: Received task: pulp.server.managers.repo.sync.sync[2b9598ef-ee65-4768-8f9f-a84d63b24596]
Oct 19 14:26:27 localhost.localdomain pulp[9771]: py.warnings:WARNING: (9771-97728) /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>
Oct 19 14:26:27 localhost.localdomain pulp[9771]: py.warnings:WARNING: (9771-97728)   "MongoClient opened before fork. Create MongoClient "
Oct 19 14:26:27 localhost.localdomain pulp[9771]: py.warnings:WARNING: (9771-97728)
Oct 19 14:26:27 localhost.localdomain pulp[9591]: celery.worker.strategy:INFO: Received task: pulp.server.async.tasks._release_resource[cf3d7ee3-3f26-411a-b47e-80036d03e80b]
Oct 19 14:26:27 localhost.localdomain pulp[9490]: celery.worker.job:INFO: Task pulp.server.async.tasks._queue_reserved_task[13606902-a6e4-4429-bea1-19c05e51e918] succeeded in 0.116481841s: None
Oct 19 14:26:27 localhost.localdomain pulp[9771]: pulp_rpm.plugins.importers.yum.sync:INFO: Downloading metadata from https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-unsignedd/.
Oct 19 14:26:27 localhost.localdomain pulp[9771]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:26:28 localhost.localdomain pulp[9771]: requests.packages.urllib3.connectionpool:INFO: Starting new HTTPS connection (1): repos.fedorapeople.org
Oct 19 14:26:29 localhost.localdomain pulp[9771]: pulp.server.async.tasks:INFO: Task failed : [2b9598ef-ee65-4768-8f9f-a84d63b24596] : Error retrieving metadata: Not found
Oct 19 14:26:29 localhost.localdomain pulp[9591]: celery.worker.job:INFO: Task pulp.server.managers.repo.sync.sync[2b9598ef-ee65-4768-8f9f-a84d63b24596] raised expected: PulpCodedException()
Oct 19 14:26:29 localhost.localdomain pulp[9591]: celery.worker.job:INFO: Task pulp.server.async.tasks._release_resource[cf3d7ee3-3f26-411a-b47e-80036d03e80b] succeeded in 0.0233983580001s: None

Actions

Copy link

Updated by amacdona@redhat.com over 7 years ago

Priority changed from Normal to Urgent
Severity changed from 2. Medium to 3. High
Triaged changed from No to Yes

Added by ttereshc over 7 years ago

Revision 41b02d94 | View on GitHub

Show error on sync failure if the was no metadata or treeinfo found

closes #2363 https://pulp.plan.io/issues/2363

Actions

Copy link

Updated by ttereshc over 7 years ago

Status changed from NEW to POST
Assignee set to ttereshc

https://github.com/pulp/pulp_rpm/pull/997

Actions

Copy link

Updated by ttereshc over 7 years ago

Status changed from POST to MODIFIED

Applied in changeset 41b02d944fd698ea702a0f45933769d08bad40e9.

Actions

Copy link

Updated by semyers over 7 years ago

Platform Release set to 2.11.0

Actions

Copy link

Updated by ttereshc over 7 years ago

Sprint/Milestone set to 28

Actions

Copy link

Updated by semyers over 7 years ago

Status changed from MODIFIED to 5

Actions

Copy link

Updated by pthomas@redhat.com over 7 years ago

Status changed from 5 to 6

verified


[root@cloud-qe-22 ~]# pulp-admin rpm repo create --repo-id foo --feed 'https://repos.fedorapeople.org/pulp/pulp/fixtures/rpm-mirrorlist-bad'
Successfully created repository [foo]

[root@cloud-qe-22 ~]# pulp-admin rpm repo sync run --repo-id foo
+----------------------------------------------------------------------+
                     Synchronizing Repository [foo]
+----------------------------------------------------------------------+

This command may be exited via ctrl+c without affecting the request.

Downloading metadata...
[\]
... completed

Downloading repository content...
[-]
[==================================================] 100%
RPMs:       0/0 items
Delta RPMs: 0/0 items

... completed

Downloading distribution files...
[==================================================] 100%
Distributions: 0/0 items

Task Failed

Error retrieving metadata: Not Found

Actions

Copy link