Actions
Issue #4428
closed
Upsert query raises NotUniqueError
Added by daviddavis about 5 years ago. Updated over 4 years ago.
Start date:
Due date:
Estimated time:
Severity:
2. Medium
Version:
Platform Release:
2.21.0
OS:
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
Pulp 2
Sprint:
Sprint 56
Quarter:
Description
Feb 15 16:16:52 xxxx mongod.27017[25694]: [conn57] command pulp_database.$cmd command: update { update: "task_status", ordered: true, updates: [ { q: { task_id: "7a256849-5184-4393-98fe-05a66ba0681b" }, u: { $set: { start_time: "2019-02-15T21:16:52Z", worker_name: "reserved_resource_worker-0@xxxx", state: "running" } }, multi: false, upsert: true } ] } numYields:0 reslen:255 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 130ms
Feb 15 16:16:52 xxxx pulp: pulp.server.async.tasks:INFO: [7a256849] Task failed : [7a256849-5184-4393-98fe-05a66ba0681b]
Feb 15 16:16:52 xxxx pulp: celery.app.trace:ERROR: [7a256849] (26802-76000) Task pulp.server.controllers.repository.download_deferred[7a256849-5184-4393-98fe-05a66ba0681b] raised unexpected: NotUniqueError(u'Update failed (E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "7a256849-5184-4393-98fe-05a66ba0681b" })',)
Feb 15 16:16:52 xxxx pulp: celery.app.trace:ERROR: [7a256849] (26802-76000) NotUniqueError: Update failed (E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "7a256849-5184-4393-98fe-05a66ba0681b" })
Looks like this is a known problem starting with MongoDB 3.0 and the wiredtiger engine that is not being fixed until 4.2.
https://jira.mongodb.org/browse/SERVER-14322
The work around according to the jira is, "Currently clients can retry the update to get the same behavior which is expected from the server."
I'm concerned that other places which do upserts could hit this problem as well.
Related issues
Updated by CodeHeeler about 5 years ago
- Triaged changed from No to Yes
- Sprint set to Sprint 49
Updated by daviddavis about 5 years ago
- Priority changed from High to Normal
- Severity changed from 3. High to 2. Medium
Updated by daviddavis about 5 years ago
- Sprint deleted (
Sprint 49)
Removing from sprint until we can determine whether this is harmless or not. Sounds like it might not be.
Updated by daviddavis about 5 years ago
- Sprint set to Sprint 49
After talking with @dkliban, we decided to move this back onto the sprint. It sounds relatively harmless except it causes the deferred_download task to fail and the user sees an error in their logs.
Updated by daviddavis about 5 years ago
This might be the same or related to https://pulp.plan.io/issues/3358.
Updated by dalley about 5 years ago
- Related to Issue #3358: Very occasionally, a task will be processed and have a 'worker_name' of None added
Updated by dalley about 5 years ago
I'm a little concerned that fixing this issue would present higher risks than leaving it be, since fixing it would likely involve delving into tasking code. Having looked into this a year ago, I'm fairly certain the issue is somewhere in this block of code, which actually documents some race condition concerns.
https://github.com/pulp/pulp/blob/2-master/server/pulp/server/async/tasks.py#L416-L529
I believe this only happens when the deferred_download task does not actually do anything, and exits immediately. So the error message in the logs is scary - but does not influence Pulp operation at all, as far as I know.
Updated by daviddavis about 5 years ago
Would catching and silencing the exception be an option? I looked at a random Satellite machine and saw that the error was happening at a rate of about 2-3 per day. I guess we can remove this from the sprint and reevaluate if we get more user complaints.
Updated by dkliban@redhat.com about 5 years ago
The risks associated with making changes to fix this problem outweigh the benefits of the fix. We are not going to address this issue at this time.
Updated by dkliban@redhat.com almost 5 years ago
May 6 23:48:36 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.consumer.applicability.batch_regenerate_applicability[99de88d0-3a86-44ae-befe-af4430e0da4b]
May 6 23:48:36 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.consumer.applicability.batch_regenerate_applicability[f3f41c41-7f87-4399-99a6-a10e6567dee1]
May 6 23:48:36 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.consumer.applicability.batch_regenerate_applicability[ab8d40d2-c7a6-4dd7-99c1-ff844b585434]
May 6 23:48:36 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: Unhandled Exception
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "ab8d40d2-c7a6-4dd7-99c1-ff844b585434" }
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) Traceback (most recent call last):
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 185, in _get_response
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) response = wrapped_callback(request, *callback_args, **callback_kwargs)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 68, in view
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) return self.dispatch(request, *args, **kwargs)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 88, in dispatch
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) return handler(request, *args, **kwargs)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 241, in _auth_decorator
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) return _verify_auth(self, operation, super_user_only, method, *args, **kwargs)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 195, in _verify_auth
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) value = method(self, *args, **kwargs)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/util.py", line 130, in wrapper
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) return func(*args, **kwargs)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/repositories.py", line 913, in post
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) queue_regenerate_applicability_for_repos(repo_criteria.as_dict())
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/pulp/server/managers/consumer/applicability.py", line 156, in queue_regenerate_applicability_for_repos
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) (profiles_to_process,), **{'group_id': task_group_id})
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 491, in apply_async
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) 'spawned_tasks', 'traceback'])
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib/python2.7/site-packages/pulp/server/db/model/__init__.py", line 566, in save_with_set_on_insert
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) check_keys, multi, manipulate, write_concern)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) _check_write_command_response([(0, result)])
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) File "/usr/lib64/python2.7/site-packages/pymongo/helpers.py", line 300, in _check_write_command_response
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) raise DuplicateKeyError(error.get("errmsg"), 11000, error)
May 6 23:48:37 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21290-18752) DuplicateKeyError: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "ab8d40d2-c7a6-4dd7-99c1-ff844b585434" }
May 7 12:02:24 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[92d5d0d4-1ea9-4c8e-808a-5f6b0111067f]
May 7 12:02:24 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[89f52ddb-bc10-47ac-b7b6-13a93fa0bde8]
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) Task pulp.server.controllers.repository.queue_download_deferred[92d5d0d4-1ea9-4c8e-808a-5f6b0111067f] raised unexpected: DuplicateKeyError(u'E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "89f52ddb-bc10-47ac-b7b6-13a93fa0bde8" }',)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) Traceback (most recent call last):
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 367, in trace_task
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) R = retval = fun(*args, **kwargs)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 107, in __call__
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) return super(PulpTask, self).__call__(*args, **kwargs)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 622, in __protected_call__
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) return self.run(*args, **kwargs)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib/python2.7/site-packages/pulp/server/controllers/repository.py", line 1362, in queue_download_deferred
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) download_deferred.apply_async(tags=task_tags)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 491, in apply_async
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) 'spawned_tasks', 'traceback'])
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib/python2.7/site-packages/pulp/server/db/model/__init__.py", line 566, in save_with_set_on_insert
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) check_keys, multi, manipulate, write_concern)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) _check_write_command_response([(0, result)])
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) File "/usr/lib64/python2.7/site-packages/pymongo/helpers.py", line 300, in _check_write_command_response
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) raise DuplicateKeyError(error.get("errmsg"), 11000, error)
May 7 12:02:24 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [92d5d0d4] (8325-66560) DuplicateKeyError: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "89f52ddb-bc10-47ac-b7b6-13a93fa0bde8" }
May 7 16:03:50 dhcp-8-29-228 pulp: celery.app.trace:INFO: [f0b28914] Task pulp.server.async.tasks._release_resource[f0b28914-bbc9-4fbb-ac93-b3d2035d2ab5] succeeded in 0.00248535699211s: None
May 7 16:04:05 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.consumer.applicability.batch_regenerate_applicability[0fa996a0-cd8d-422b-ae4d-45c8acbfb13b]
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: Unhandled Exception
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "0fa996a0-cd8d-422b-ae4d-45c8acbfb13b" }
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) Traceback (most recent call last):
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 185, in _get_response
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) response = wrapped_callback(request, *callback_args, **callback_kwargs)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 68, in view
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) return self.dispatch(request, *args, **kwargs)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 88, in dispatch
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) return handler(request, *args, **kwargs)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 241, in _auth_decorator
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) return _verify_auth(self, operation, super_user_only, method, *args, **kwargs)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 195, in _verify_auth
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) value = method(self, *args, **kwargs)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/util.py", line 130, in wrapper
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) return func(*args, **kwargs)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/repositories.py", line 913, in post
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) queue_regenerate_applicability_for_repos(repo_criteria.as_dict())
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/pulp/server/managers/consumer/applicability.py", line 156, in queue_regenerate_applicability_for_repos
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) (profiles_to_process,), **{'group_id': task_group_id})
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 491, in apply_async
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) 'spawned_tasks', 'traceback'])
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib/python2.7/site-packages/pulp/server/db/model/__init__.py", line 566, in save_with_set_on_insert
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) check_keys, multi, manipulate, write_concern)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) _check_write_command_response([(0, result)])
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) File "/usr/lib64/python2.7/site-packages/pymongo/helpers.py", line 300, in _check_write_command_response
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) raise DuplicateKeyError(error.get("errmsg"), 11000, error)
May 7 16:04:05 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-01856) DuplicateKeyError: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "0fa996a0-cd8d-422b-ae4d-45c8acbfb13b" }
May 7 16:04:05 dhcp-8-29-228 pulp: celery.app.trace:INFO: [0fa996a0] Task pulp.server.managers.consumer.applicability.batch_regenerate_applicability[0fa996a0-cd8d-422b-ae4d-45c8acbfb13b] succeeded in 0.442111186916s: None
May 7 23:45:43 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.consumer.applicability.batch_regenerate_applicability[2aba41c6-6037-4255-8cd6-67e47377f8d3]
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: Unhandled Exception
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "2aba41c6-6037-4255-8cd6-67e47377f8d3" }
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) Traceback (most recent call last):
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 185, in _get_response
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) response = wrapped_callback(request, *callback_args, **callback_kwargs)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 68, in view
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return self.dispatch(request, *args, **kwargs)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 88, in dispatch
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return handler(request, *args, **kwargs)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 241, in _auth_decorator
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return _verify_auth(self, operation, super_user_only, method, *args, **kwargs)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 195, in _verify_auth
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) value = method(self, *args, **kwargs)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/util.py", line 130, in wrapper
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return func(*args, **kwargs)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/repositories.py", line 913, in post
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) queue_regenerate_applicability_for_repos(repo_criteria.as_dict())
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/managers/consumer/applicability.py", line 156, in queue_regenerate_applicability_for_repos
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) (profiles_to_process,), **{'group_id': task_group_id})
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 491, in apply_async
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) 'spawned_tasks', 'traceback'])
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/db/model/__init__.py", line 566, in save_with_set_on_insert
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) check_keys, multi, manipulate, write_concern)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) _check_write_command_response([(0, result)])
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/helpers.py", line 300, in _check_write_command_response
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) raise DuplicateKeyError(error.get("errmsg"), 11000, error)
May 7 23:45:43 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) DuplicateKeyError: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "2aba41c6-6037-4255-8cd6-67e47377f8d3" }
May 7 23:45:44 dhcp-8-29-228 pulp: celery.app.trace:INFO: [2aba41c6] Task pulp.server.managers.consumer.applicability.batch_regenerate_applicability[2aba41c6-6037-4255-8cd6-67e47377f8d3] succeeded in 0.450156594045s: None
May 8 16:32:30 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[399aacf5-3138-4df4-8830-a4142c88556a]
May 8 16:32:30 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[9763ab58-2400-4544-b3d6-33ee9ac6964b]
May 8 16:32:30 dhcp-8-29-228 pulp: celery.app.trace:INFO: [9763ab58] Task pulp.server.controllers.repository.download_deferred[9763ab58-2400-4544-b3d6-33ee9ac6964b] succeeded in 0.0918355770409s: None
May 8 16:32:31 dhcp-8-29-228 mongod.27017[6216]: [conn100] update pulp_database.task_status query: { task_id: "9763ab58-2400-4544-b3d6-33ee9ac6964b" } planSummary: IXSCAN { task_id: -1 } update: { $set: { exception: null, task_type: "pulp.server.controllers.repository.download_deferred", tags: [ "pulp:action:deferred_download" ], progress_report: {}, worker_name: null, group_id: null }, $setOnInsert: { finish_time: null, start_time: null, traceback: null, spawned_tasks: [], state: "waiting", result: null, error: null } } keysInserted:3 writeConflicts:1 exception: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "9763ab58-2400-4544-b3d6-33ee9ac6964b" } code:11000 numYields:0 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } 184ms
May 8 16:32:31 dhcp-8-29-228 mongod.27017[6216]: [conn100] command pulp_database.$cmd command: update { update: "task_status", ordered: true, updates: [ { q: { task_id: "9763ab58-2400-4544-b3d6-33ee9ac6964b" }, u: { $set: { exception: null, task_type: "pulp.server.controllers.repository.download_deferred", tags: [ "pulp:action:deferred_download" ], progress_report: {}, worker_name: null, group_id: null }, $setOnInsert: { finish_time: null, start_time: null, traceback: null, spawned_tasks: [], state: "waiting", result: null, error: null } }, multi: false, upsert: true } ] } numYields:0 reslen:255 locks:{ Global: { acquireCount: { r: 1, w: 1 } }, Database: { acquireCount: { w: 1 } }, Collection: { acquireCount: { w: 1 } } } protocol:op_query 215ms
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) Task pulp.server.controllers.repository.queue_download_deferred[399aacf5-3138-4df4-8830-a4142c88556a] raised unexpected: DuplicateKeyError(u'E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "9763ab58-2400-4544-b3d6-33ee9ac6964b" }',)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) Traceback (most recent call last):
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 367, in trace_task
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) R = retval = fun(*args, **kwargs)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 107, in __call__
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) return super(PulpTask, self).__call__(*args, **kwargs)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 622, in __protected_call__
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) return self.run(*args, **kwargs)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib/python2.7/site-packages/pulp/server/controllers/repository.py", line 1362, in queue_download_deferred
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) download_deferred.apply_async(tags=task_tags)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 491, in apply_async
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) 'spawned_tasks', 'traceback'])
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib/python2.7/site-packages/pulp/server/db/model/__init__.py", line 566, in save_with_set_on_insert
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) check_keys, multi, manipulate, write_concern)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) _check_write_command_response([(0, result)])
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) File "/usr/lib64/python2.7/site-packages/pymongo/helpers.py", line 300, in _check_write_command_response
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) raise DuplicateKeyError(error.get("errmsg"), 11000, error)
May 8 16:32:31 dhcp-8-29-228 pulp: celery.app.trace:ERROR: [399aacf5] (8183-29696) DuplicateKeyError: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "9763ab58-2400-4544-b3d6-33ee9ac6964b" }
May 9 08:33:02 dhcp-8-29-228 pulp: celery.app.trace:INFO: [8ad505c6] Task pulp.server.async.tasks._release_resource[8ad505c6-243e-4903-a96c-9807dcaacaee] succeeded in 0.00221286003944s: None
May 9 08:33:15 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.consumer.applicability.batch_regenerate_applicability[653e9ebb-84f7-403f-aa2c-be3e6ca4033d]
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: Unhandled Exception
May 9 08:33:16 dhcp-8-29-228 pulp: celery.app.trace:INFO: [653e9ebb] Task pulp.server.managers.consumer.applicability.batch_regenerate_applicability[653e9ebb-84f7-403f-aa2c-be3e6ca4033d] succeeded in 0.0793163949857s: None
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "653e9ebb-84f7-403f-aa2c-be3e6ca4033d" }
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) Traceback (most recent call last):
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/django/core/handlers/base.py", line 185, in _get_response
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) response = wrapped_callback(request, *callback_args, **callback_kwargs)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 68, in view
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return self.dispatch(request, *args, **kwargs)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/django/views/generic/base.py", line 88, in dispatch
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return handler(request, *args, **kwargs)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 241, in _auth_decorator
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return _verify_auth(self, operation, super_user_only, method, *args, **kwargs)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/decorators.py", line 195, in _verify_auth
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) value = method(self, *args, **kwargs)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/util.py", line 130, in wrapper
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return func(*args, **kwargs)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/webservices/views/repositories.py", line 913, in post
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) queue_regenerate_applicability_for_repos(repo_criteria.as_dict())
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/managers/consumer/applicability.py", line 162, in queue_regenerate_applicability_for_repos
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) (profiles_to_process,), **{'group_id': task_group_id})
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 491, in apply_async
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) 'spawned_tasks', 'traceback'])
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib/python2.7/site-packages/pulp/server/db/model/__init__.py", line 566, in save_with_set_on_insert
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) check_keys, multi, manipulate, write_concern)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) _check_write_command_response([(0, result)])
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/helpers.py", line 300, in _check_write_command_response
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) raise DuplicateKeyError(error.get("errmsg"), 11000, error)
May 9 08:33:16 dhcp-8-29-228 pulp: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) DuplicateKeyError: E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "653e9ebb-84f7-403f-aa2c-be3e6ca4033d" }
May 9 08:33:16 dhcp-8-29-228 pulp: celery.worker.strategy:INFO: Received task: pulp.server.managers.consumer.applicability.batch_regenerate_applicability[2398e34a-abf7-4242-aa85-27d8a80cdea1]
May 9 08:33:16 dhcp-8-29-228 pulp: celery.app.trace:INFO: [2398e34a] Task pulp.server.managers.consumer.applicability.batch_regenerate_applicability[2398e34a-abf7-4242-aa85-27d8a80cdea1] succeeded in 0.0221149789868s: None
Updated by dkliban@redhat.com almost 5 years ago
Katello always makes a request to regenerate applicability after each sync. When the generate applicability task fails, Katello reports this as a Warning on the sync.
Updated by rchan almost 5 years ago
From reading the comments, it looks like this issue will not be fixed?
Updated by bherring almost 5 years ago
- Related to Issue #4795: Pulp2 task details information returns incorrect values when polled too quickly added
Updated by daviddavis almost 5 years ago
Talked with @dkliban about trying to add a 0.5 sleep time to the deferred_download and batch_regenerate_applicability tasks to prevent this NotUniqueError.
Updated by daviddavis almost 5 years ago
- Status changed from NEW to ASSIGNED
- Assignee set to daviddavis
Updated by daviddavis almost 5 years ago
- Sprint set to Sprint 53
Assigning to sprint per our triage today.
Added by daviddavis almost 5 years ago
Updated by daviddavis almost 5 years ago
- Status changed from ASSIGNED to MODIFIED
Applied in changeset pulp|fb8a31f0876f7628d3a381226117fea26b93c312.
Updated by daviddavis almost 5 years ago
Updated by daviddavis almost 5 years ago
- Related to Issue #4958: queue_download_deferred raises a duplicate key error added
Updated by ttereshc almost 5 years ago
- Sprint/Milestone deleted (
2.20.0) - Platform Release deleted (
2.20.0)
Added by daviddavis almost 5 years ago
Revision f6c15ecd | View on GitHub
Revert "Add sleep calls to prevent task upsert errors"
After testing, this fix did not fix the issue. So we're removing it.
This reverts commit fb8a31f0876f7628d3a381226117fea26b93c312.
ref #4428
Added by daviddavis almost 5 years ago
Revision 62c96776 | View on GitHub
Revert "Add sleep calls to prevent task upsert errors"
After testing, this fix did not fix the issue. So we're removing it.
This reverts commit fb8a31f0876f7628d3a381226117fea26b93c312.
ref #4428
(cherry picked from commit f6c15ecd541810178b308444ffb6ab164ae58fc4)
Updated by daviddavis almost 5 years ago
- Related to deleted (Issue #4958: queue_download_deferred raises a duplicate key error)
Updated by daviddavis almost 5 years ago
- Status changed from MODIFIED to ASSIGNED
Updated by daviddavis almost 5 years ago
The patch we created didn't seem to solve the problem. We're investigating an alternative solution.
Updated by daviddavis almost 5 years ago
- Status changed from ASSIGNED to POST
Updated by daviddavis almost 5 years ago
- Sprint changed from Sprint 53 to Sprint 56
Updated by daviddavis over 4 years ago
- Has duplicate Issue #4958: queue_download_deferred raises a duplicate key error added
Added by daviddavis over 4 years ago
Revision 4443de2b | View on GitHub
Manually retry failing task upsert queries
Updated by daviddavis over 4 years ago
- Status changed from POST to MODIFIED
Applied in changeset pulp|4443de2baaad7b4b2d7d2984f1af9b2d3024c9b6.
Updated by dalley over 4 years ago
- Status changed from MODIFIED to CLOSED - CURRENTRELEASE
Actions
.
Add sleep calls to prevent task upsert errors
Adding a couple sleep calls to slow down tasks that finish too soon. This will hopefully prevent NotUniqueError we've seen.
fixes #4428 https://pulp.plan.io/issues/4428