Issue #4958: queue_download_deferred raises a duplicate key error - Pulp

Actions

Send by e-mail Copy link

Issue #4958

closed

queue_download_deferred raises a duplicate key error

Added by amacdona@redhat.com over 5 years ago. Updated over 5 years ago.

Status:

CLOSED - DUPLICATE

Priority:

Normal

Assignee:

Category:

Sprint/Milestone:

Start date:

Due date:

Estimated time:

Severity:

2. Medium

Version:

Platform Release:

OS:

Triaged:

Yes

Groomed:

Sprint Candidate:

Tags:

Pulp 2

Sprint:

Sprint 56

Quarter:

Description

I wasn't able to replicate this personally, but a user reported this error while doing a docker sync from https://registry.hub.docker.com gitlab/gitlab-ee


Jun 11 01:01:58 00000000000000 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[20e513fd-be55-4269-a64b-4cc020ed9869]
Jun 11 01:01:58 00000000000000 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[e473501d-0d86-4171-8cd3-99fa1dae7f20]
Jun 11 01:01:58 00000000000000 pulp: celery.app.trace:INFO: [20e513fd] Task pulp.server.controllers.repository.queue_download_deferred[20e513fd-be55-4269-a64b-4cc020ed9869] succeeded in 0.0474473450013s: None
Jun 11 01:01:59 00000000000000 pulp: celery.app.trace:INFO: [e473501d] Task pulp.server.controllers.repository.download_deferred[e473501d-0d86-4171-8cd3-99fa1dae7f20] succeeded in 1.01020334501s: None
Jun 11 01:06:47 00000000000000 puppet-agent[45956]: Applied catalog in 0.39 seconds
Jun 11 01:11:58 00000000000000 pulp: celery.beat:INFO: Scheduler: Sending due task download_deferred_content (pulp.server.controllers.repository.queue_download_deferred)
Jun 11 01:11:58 00000000000000 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[d7752d41-29df-4f50-9aca-5552fba961e3]
Jun 11 01:11:58 00000000000000 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[b5f5c1ec-6b62-4eef-b788-2787d8ea6878]
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320) Task pulp.server.controllers.repository.queue_download_deferred[d7752d41-29df-4f50-9aca-5552fba961e3] raised unexpected: DuplicateKeyError(u'E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "b5f5c1ec-6b62-4eef-b788-2787d8ea6878" }',)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320) Traceback (most recent call last):
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 367, in trace_task
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     R = retval = fun(*args, **kwargs)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 107, in __call__
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     return super(PulpTask, self).__call__(*args, **kwargs)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 622, in __protected_call__
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     return self.run(*args, **kwargs)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib/python2.7/site-packages/pulp/server/controllers/repository.py", line 1362, in queue_download_deferred
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     download_deferred.apply_async(tags=task_tags)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 491, in apply_async
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     'spawned_tasks', 'traceback'])
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib/python2.7/site-packages/pulp/server/db/model/__init__.py", line 566, in save_with_set_on_insert
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     check_keys, multi, manipulate, write_concern)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     _check_write_command_response([(0, result)])
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)   File "/usr/lib64/python2.7/site-packages/pymongo/helpers.py", line 300, in _check_write_command_response
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320)     raise DuplicateKeyError(error.get("errmsg"), 11000, error)
Jun 11 01:11:58 00000000000000 pulp: celery.app.trace:ERROR: [d7752d41] (13092-20320) DuplicateKeyError: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "b5f5c1ec-6b62-4eef-b788-2787d8ea6878" }
Jun 11 01:11:59 00000000000000 pulp: celery.app.trace:INFO: [b5f5c1ec] Task pulp.server.controllers.repository.download_deferred[b5f5c1ec-6b62-4eef-b788-2787d8ea6878] succeeded in 1.011006154s: None
Jun 11 01:21:58 00000000000000 pulp: celery.beat:INFO: Scheduler: Sending due task download_deferred_content (pulp.server.controllers.repository.queue_download_deferred)
Jun 11 01:21:58 00000000000000 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[021ed3ae-efe9-49ea-83e7-6761d96b6af0]

I assume there isn't a problem other than the alarming logging, it looks like the same task was queued twice and one of them failed, one of them succeeded (both with same ID)

Related issues

Actions

Copy link

Updated by amacdona@redhat.com over 5 years ago

Description updated (diff)
Tags Pulp 2 added

Actions

Copy link

Updated by ttereshc over 5 years ago

What do you mean "both with the same ID"? I don't see two tasks with the same id.

Actions

Copy link

Updated by daviddavis over 5 years ago

I think we experienced the same problem in #4428. I think the collision happens between the initial task insert and the task upsert (after the task is done)[0]. To fix #4428, we added sleep statements to tasks which is an ugly hack. We made this choice because we thought it was only happening in 1-2 places and rewriting the task code would be painful (see https://pulp.plan.io/issues/4428#note-10). Since this seems be happening throughout our code though, it might be worth finding a better solution adding sleep statements.

[0] https://github.com/pulp/pulp/blob/2-master/server/pulp/server/async/tasks.py#L415-L422

Actions

Copy link