Description of problem: On my setup I can see this error from time to time to appear in the journal. Not sure if it causes any actual harm. Version-Release number of selected component (if applicable): satellite-6.4.0-9.beta.el7sat.noarch pulp-server-2.16.0-2.el7sat.noarch How reproducible: every few hours on my setup Steps to Reproduce: 1. I have a Snap5 and synced PuppetForge to it and some more Puppet modules 2. I have published bunch of content views with 35 puppet modules - was OK 3. Then I have added all the modules into the CV and attempted to republish Actual results: Error: PLP0034: The distributor 1-CV5-Library-puppet-3865773e-af53-432a-92c7-ce8566c0833c indicated a failed response when publishing repository 1-CV5-Library-puppet-3865773e-af53-432a-92c7-ce8566c0833c. Expected results: Should work Additional info: Jun 02 04:40:11 sat640snap5.example.com pulp[14007]: celery.beat:INFO: Scheduler: Sending due task download_deferred_content (pulp.server.controllers.repository.queue_download_deferred) Jun 02 04:40:11 sat640snap5.example.com pulp[13813]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[904367c8-8c66-4d5f-9a58-4a7b7e0b77ff] Jun 02 04:40:11 sat640snap5.example.com pulp[13733]: qpid.messaging:WARNING: [904367c8] process forked, child must not use parent qpid.messaging Jun 02 04:40:11 sat640snap5.example.com pulp[13733]: kombu.transport.qpid:INFO: [904367c8] Connected to qpid with SASL mechanism ANONYMOUS Jun 02 04:40:11 sat640snap5.example.com pulp[13816]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[65862e33-0ec0-469e-a159-c61083ca6708] Jun 02 04:40:11 sat640snap5.example.com pulp[13733]: py.warnings:WARNING: [904367c8] (13733-29088) /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> Jun 02 04:40:11 sat640snap5.example.com pulp[13733]: py.warnings:WARNING: [904367c8] (13733-29088) "MongoClient opened before fork. Create MongoClient " Jun 02 04:40:11 sat640snap5.example.com pulp[13733]: py.warnings:WARNING: [904367c8] (13733-29088) Jun 02 04:40:11 sat640snap5.example.com pulp[13733]: celery.app.trace:INFO: [904367c8] Task pulp.server.controllers.repository.queue_download_deferred[904367c8-8c66-4d5f-9a58-4a7b7e0b77ff] succeeded in 0.0518634849977s: None Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: pulp.server.async.tasks:INFO: [65862e33] Task failed : [65862e33-0ec0-469e-a159-c61083ca6708] Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) Task pulp.server.controllers.repository.download_deferred[65862e33-0ec0-469e-a159-c61083ca6708] raised unexpected: NotUniqueError(u'Update failed (E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "65862e33-0ec0-469e-a159-c61083ca6708" })',) Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) Traceback (most recent call last): Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 367, in trace_task Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) R = retval = fun(*args, **kwargs) Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 521, in __call__ Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) upsert=True) Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) File "/usr/lib/python2.7/site-packages/mongoengine/queryset/base.py", line 516, in update_one Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) upsert=upsert, multi=False, write_concern=write_concern, **update) Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) File "/usr/lib/python2.7/site-packages/pulp/server/db/querysets.py", line 100, in update Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) super(CriteriaQuerySet, self).update(*args, **kwargs) Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) File "/usr/lib/python2.7/site-packages/mongoengine/queryset/base.py", line 467, in update Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) raise NotUniqueError(u'Update failed (%s)' % unicode(err)) Jun 02 04:40:11 sat640snap5.example.com pulp[12455]: celery.app.trace:ERROR: [65862e33] (12455-88544) NotUniqueError: Update failed (E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "65862e33-0ec0-469e-a159-c61083ca6708" }) Jun 02 04:40:12 sat640snap5.example.com pulp[15288]: pulp.server.db.connection:INFO: Attempting to connect to localhost:27017 Jun 02 04:40:12 sat640snap5.example.com pulp[15288]: pulp.server.db.connection:INFO: Attempting to connect to localhost:27017 Jun 02 04:40:12 sat640snap5.example.com pulp[15288]: pulp.server.db.connection:INFO: Write concern for Mongo connection: {} Jun 02 04:50:11 sat640snap5.example.com pulp[14007]: celery.beat:INFO: Scheduler: Sending due task download_deferred_content (pulp.server.controllers.repository.queue_download_deferred) Jun 02 04:50:11 sat640snap5.example.com pulp[13813]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.queue_download_deferred[f601cbdd-79dc-4842-9597-b415642819fc] Jun 02 04:50:11 sat640snap5.example.com pulp[13816]: celery.worker.strategy:INFO: Received task: pulp.server.controllers.repository.download_deferred[04777184-3cb3-4fb2-ae66-69878c2033fd] Jun 02 04:50:11 sat640snap5.example.com pulp[13733]: celery.app.trace:INFO: [f601cbdd] Task pulp.server.controllers.repository.queue_download_deferred[f601cbdd-79dc-4842-9597-b415642819fc] succeeded in 0.00575933399887s: None Jun 02 04:50:11 sat640snap5.example.com pulp[15288]: py.warnings:WARNING: [04777184] (15288-88544) /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> Jun 02 04:50:11 sat640snap5.example.com pulp[15288]: py.warnings:WARNING: [04777184] (15288-88544) "MongoClient opened before fork. Create MongoClient " Jun 02 04:50:11 sat640snap5.example.com pulp[15288]: py.warnings:WARNING: [04777184] (15288-88544) Jun 02 04:50:11 sat640snap5.example.com pulp[15288]: celery.app.trace:INFO: [04777184] Task pulp.server.controllers.repository.download_deferred[04777184-3cb3-4fb2-ae66-69878c2033fd] succeeded in 0.0205771690016s: None Jun 02 04:50:12 sat640snap5.example.com pulp[16385]: pulp.server.db.connection:INFO: Attempting to connect to localhost:27017 Jun 02 04:50:12 sat640snap5.example.com pulp[16385]: pulp.server.db.connection:INFO: Attempting to connect to localhost:27017 Jun 02 04:50:12 sat640snap5.example.com pulp[16385]: pulp.server.db.connection:INFO: Write concern for Mongo connection: {}
Note that when updating the CV, I have hit bug 1585408
Created attachment 1447030 [details] "Errors" tab of the failed publish task
Created attachment 1447031 [details] From DynFlow - with failed step unfolded
Jan, What version of mongoengine are you using? $ rpm -qa mongoengine Just in case it was installed via pip: $ pip freeze | grep mongoengine
python-mongoengine-0.10.5-2.el7sat.noarch
I am re-opening this bz as I have a customer who is seeing similar errors on his 6.4 beta. I will attach the whole messages logs from the foreman-debug. Let me know if you need anything else to move this bz forward
The Pulp upstream bug status is at NEW. Updating the external tracker on this bug.
The Pulp upstream bug priority is at Normal. Updating the external tracker on this bug.
I'm seeing this on 6.5 Snap 26 too. Two occurrences on my box today: May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) Task pulp.server.managers.consumer.applicability.batch_regenerate_applicability[b7326b64-9271-4545-9c5c-080d89a9715c] raised unexpected: NotUniqueError(u'Update failed (E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "b7326b64-9271-4545-9c5c-080d89a9715c" })',) May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) Traceback (most recent call last): May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 367, in trace_task May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) R = retval = fun(*args, **kwargs) May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 521, in __call__ May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) upsert=True) May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) File "/usr/lib/python2.7/site-packages/mongoengine/queryset/base.py", line 516, in update_one May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) upsert=upsert, multi=False, write_concern=write_concern, **update) May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) File "/usr/lib/python2.7/site-packages/pulp/server/db/querysets.py", line 100, in update May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) super(CriteriaQuerySet, self).update(*args, **kwargs) May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) File "/usr/lib/python2.7/site-packages/mongoengine/queryset/base.py", line 467, in update May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) raise NotUniqueError(u'Update failed (%s)' % unicode(err)) May 09 04:50:49 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[8182]: celery.app.trace:ERROR: [b7326b64] (8182-42944) NotUniqueError: Update failed (E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "b7326b64-9271-4545-9c5c-080d89a9715c" }) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: Unhandled Exception May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) Traceback (most recent call last): May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) response = wrapped_callback(request, *callback_args, **callback_kwargs) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return self.dispatch(request, *args, **kwargs) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return handler(request, *args, **kwargs) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return _verify_auth(self, operation, super_user_only, method, *args, **kwargs) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) value = method(self, *args, **kwargs) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) return func(*args, **kwargs) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) queue_regenerate_applicability_for_repos(repo_criteria.as_dict()) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) (profiles_to_process,), **{'group_id': task_group_id}) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) 'spawned_tasks', 'traceback']) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) TaskStatus._get_collection().update({'task_id': task_id}, update, upsert=True) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 2232, in update May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) check_keys, multi, manipulate, write_concern) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) File "/usr/lib64/python2.7/site-packages/pymongo/collection.py", line 710, in _update May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) _check_write_command_response([(0, result)]) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: pulp.server.webservices.middleware.exception:ERROR: (21288-55232) raise DuplicateKeyError(error.get("errmsg"), 11000, error) May 09 08:33:16 dhcp-8-29-228.lab.eng.rdu2.redhat.com pulp[21288]: 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" } On both cases I was syncing multiple repos (of one product) at the same time.
The Pulp upstream bug status is at ASSIGNED. Updating the external tracker on this bug.
The Pulp upstream bug status is at MODIFIED. Updating the external tracker on this bug.
All upstream Pulp bugs are at MODIFIED+. Moving this bug to POST.
The Pulp upstream bug status is at POST. Updating the external tracker on this bug.
The Pulp upstream bug status is at CLOSED - CURRENTRELEASE. Updating the external tracker on this bug.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHSA-2019:3172