Issue #3687
Updated by Ichimonji10 almost 6 years ago
To reproduce, simply install Pulp 2.16.1 (the most recent stable release) or Pulp 2 nightly on Fedora 27, and try to use it. You'll immediately encounter strange behaviour. A good Pulp Smash reproducer is <code>python -m unittest pulp_smash.tests.pulp2.docker.api_v2.test_copy</code>. (This is the first test that's typcially executed by Jenkins.) The test will immediately stall, as Pulp Smash polls an ongoing asynchronous Pulp task which never returns. Why is this happening? It's not because of failed services. Here's some output from one VM: <pre>[root@fedora-27-pulp-2-16-stable ~]# systemctl --state failed UNIT LOAD ACTIVE SUB DESCRIPTION ● mcelog.service loaded failed failed Machine Check Exception Logging Daemon LOAD = Reflects whether the unit definition was properly loaded. ACTIVE = The high-level unit activation state, i.e. generalization of SUB. SUB = The low-level unit activation state, values depend on unit type. 1 loaded units listed. Pass --all to see loaded but inactive units, too. To show all installed unit files use 'systemctl list-unit-files'. </pre> This failure is both benign and unrelated to pulp. The mcelog service checks for hardware errors in CPUs, and it doesn't work on some (all?) AMD processors, and it may not work on VMs anyway. Let's take a look at the logs on Fedora 26 and 27: <pre>[root@fedora-26-pulp-2-16-stable ~]# journalctl -p 0..4 --boot=-0 -- Logs begin at Mon 2018-05-21 09:57:57 EDT, end at Mon 2018-05-21 12:25:44 EDT. -- May 21 11:37:02 fedora-26 systemd[1]: /run/systemd/generator/dev-mapper-fedora\x2droot.device.d/timeout.conf:3: Unknown lvalue 'JobRunningTimeoutSec' in section 'Unit' May 21 11:37:03 fedora-26 systemd[1]: /run/systemd/generator/dev-mapper-fedora\x2droot.device.d/timeout.conf:3: Unknown lvalue 'JobRunningTimeoutSec' in section 'Unit' May 21 11:37:03 fedora-26 systemd[1]: /etc/systemd/system/dev-fedora-swap.device.d/timeout.conf:3: Unknown lvalue 'JobRunningTimeoutSec' in section 'Unit' May 21 11:37:03 fedora-26 systemd[1]: /etc/systemd/system/dev-fedora-root.device.d/timeout.conf:3: Unknown lvalue 'JobRunningTimeoutSec' in section 'Unit' May 21 11:37:04 fedora-26-pulp-2-16-stable kernel: systemd: 17 output lines suppressed due to ratelimiting May 21 11:37:04 fedora-26-pulp-2-16-stable kernel: Decoding supported only on Scalable MCA processors. May 21 11:37:04 fedora-26-pulp-2-16-stable kernel: Decoding supported only on Scalable MCA processors. May 21 11:37:05 fedora-26-pulp-2-16-stable systemd[1]: mcelog.service: Failed with result 'exit-code'. May 21 11:37:05 fedora-26-pulp-2-16-stable smartd[710]: DEVICESCAN failed: glob(3) aborted matching pattern /dev/discs/disc* May 21 11:37:05 fedora-26-pulp-2-16-stable smartd[710]: In the system's table of devices NO devices found to scan May 21 11:37:07 fedora-26-pulp-2-16-stable systemd[1]: iscsi.service: Unit cannot be reloaded because it is inactive. May 21 11:37:49 fedora-26-pulp-2-16-stable sshd[1383]: pam_lastlog(sshd:session): unable to open /var/log/lastlog: No such file or directory May 21 11:39:05 fedora-26-pulp-2-16-stable pulp[1134]: py.warnings:WARNING: [357b1e0a] (1134-59552) /usr/lib64/python2.7/site-packages/pymongo/topology.py:145: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: ht May 21 11:39:05 fedora-26-pulp-2-16-stable pulp[1134]: py.warnings:WARNING: [357b1e0a] (1134-59552) "MongoClient opened before fork. Create MongoClient " May 21 11:39:05 fedora-26-pulp-2-16-stable pulp[1134]: py.warnings:WARNING: [357b1e0a] (1134-59552) May 21 11:39:05 fedora-26-pulp-2-16-stable pulp[1149]: py.warnings:WARNING: [72cc7015] (1149-96352) /usr/lib64/python2.7/site-packages/pymongo/topology.py:145: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: ht May 21 11:39:05 fedora-26-pulp-2-16-stable pulp[1149]: py.warnings:WARNING: [72cc7015] (1149-96352) "MongoClient opened before fork. Create MongoClient " May 21 11:39:05 fedora-26-pulp-2-16-stable pulp[1149]: py.warnings:WARNING: [72cc7015] (1149-96352) May 21 12:07:09 fedora-26-pulp-2-16-stable pulp[1139]: py.warnings:WARNING: [d499acf9] (1139-96480) /usr/lib64/python2.7/site-packages/pymongo/topology.py:145: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: ht May 21 12:07:09 fedora-26-pulp-2-16-stable pulp[1139]: py.warnings:WARNING: [d499acf9] (1139-96480) "MongoClient opened before fork. Create MongoClient " May 21 12:07:09 fedora-26-pulp-2-16-stable pulp[1139]: py.warnings:WARNING: [d499acf9] (1139-96480) </pre> <pre>[root@fedora-27-pulp-2-16-stable ~]# journalctl --priority 0..4 --boot=-0 -- Logs begin at Mon 2018-05-21 09:57:58 EDT, end at Mon 2018-05-21 12:10:20 EDT. -- May 21 11:37:04 fedora-27-pulp-2-16-stable kernel: systemd: 18 output lines suppressed due to ratelimiting May 21 11:37:04 fedora-27-pulp-2-16-stable kernel: Decoding supported only on Scalable MCA processors. May 21 11:37:04 fedora-27-pulp-2-16-stable kernel: amd64_edac_mod: Unknown symbol amd_unregister_ecc_decoder (err -2) May 21 11:37:04 fedora-27-pulp-2-16-stable kernel: amd64_edac_mod: Unknown symbol amd_register_ecc_decoder (err -2) May 21 11:37:04 fedora-27-pulp-2-16-stable kernel: amd64_edac_mod: Unknown symbol amd_report_gart_errors (err -2) May 21 11:37:04 fedora-27-pulp-2-16-stable rsyslogd[699]: environment variable TZ is not set, auto correcting this to TZ=/etc/localtime [v8.34.0 try http://www.rsyslog.com/e/2442 ] May 21 11:37:04 fedora-27-pulp-2-16-stable smartd[709]: DEVICESCAN failed: glob(3) aborted matching pattern /dev/discs/disc* May 21 11:37:04 fedora-27-pulp-2-16-stable smartd[709]: In the system's table of devices NO devices found to scan May 21 11:37:04 fedora-27-pulp-2-16-stable systemd[1]: mcelog.service: Failed with result 'exit-code'. May 21 11:37:06 fedora-27-pulp-2-16-stable systemd[1]: iscsi.service: Unit cannot be reloaded because it is inactive. May 21 11:39:05 fedora-27-pulp-2-16-stable pulp[1310]: py.warnings:WARNING: [6aaee6d5] (1310-16320) /usr/lib64/python2.7/site-packages/pymongo/topology.py:145: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: ht May 21 11:39:05 fedora-27-pulp-2-16-stable pulp[1310]: py.warnings:WARNING: [6aaee6d5] (1310-16320) "MongoClient opened before fork. Create MongoClient " May 21 11:39:05 fedora-27-pulp-2-16-stable pulp[1310]: py.warnings:WARNING: [6aaee6d5] (1310-16320) May 21 11:39:05 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: [b1f6b58d] (1308-18464) /usr/lib64/python2.7/site-packages/pymongo/topology.py:145: UserWarning: MongoClient opened before fork. Create MongoClient with connect=False, or create client after forking. See PyMongo's documentation for details: ht May 21 11:39:05 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: [b1f6b58d] (1308-18464) "MongoClient opened before fork. Create MongoClient " May 21 11:39:05 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: [b1f6b58d] (1308-18464) May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) /usr/lib/python2.7/site-packages/celery/app/trace.py:542: RuntimeWarning: Exception raised outside body: NotUniqueError(u'Tried to save duplicate unique keys (E11000 duplicate key error collection: pulp_database.task_status index: May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) Traceback (most recent call last): May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) File "/usr/lib/python2.7/site-packages/celery/app/trace.py", line 435, in trace_task May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) task_on_success(retval, uuid, args, kwargs) May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) File "/usr/lib/python2.7/site-packages/pulp/server/async/tasks.py", line 577, in on_success May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) task_status.save() May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) File "/usr/lib/python2.7/site-packages/mongoengine/document.py", line 400, in save May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) raise NotUniqueError(message % six.text_type(err)) May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) NotUniqueError: Tried to save duplicate unique keys (E11000 duplicate key error collection: pulp_database.task_status index: task_id_-1 dup key: { : "b1f6b58d-1cec-41c6-86dd-ef0bbe5f1bf6" }) May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) exc, exc_info.traceback))) May 21 11:39:08 fedora-27-pulp-2-16-stable pulp[1308]: py.warnings:WARNING: (1308-18464) </pre> This is interesting: Pulp is encountering a duplicate key error in mongo. Even more interesting is that this error is reproductible. Duplicate key errors occur immediately whether Pulp 2.16 stable or Pulp 2.16 nightly is installed. What might explain this? It might be due to a Mongo-related upgrade. Here's some of the packages on Fedora 26 and 27: various hosts: <pre> [root@fedora-26-pulp-2-16-stable audit]# rpm -qa | grep mongo | sort mongodb-3.4.10-1.fc26.x86_64 mongodb-server-3.4.10-1.fc26.x86_64 python2-mongoengine-0.11.0-2.fc26.noarch python2-pymongo-3.4.0-6.fc26.x86_64 python2-pymongo-gridfs-3.4.0-6.fc26.x86_64 [root@fedora-26-pulp-2-16-stable audit]# rpm -qa | grep pulp | sort pulp-admin-client-2.16.1-1.fc26.noarch pulp-deb-admin-extensions-1.7.0-1.fc26.noarch pulp-deb-plugins-1.7.0-1.fc26.noarch pulp-docker-admin-extensions-3.1.3-1.fc26.noarch pulp-docker-plugins-3.1.3-1.fc26.noarch pulp-ostree-admin-extensions-1.3.0-1.fc26.noarch pulp-ostree-plugins-1.3.0-1.fc26.noarch pulp-puppet-admin-extensions-2.16.1-1.fc26.noarch pulp-puppet-plugins-2.16.1-1.fc26.noarch pulp-puppet-tools-2.16.1-1.fc26.noarch pulp-python-admin-extensions-2.0.2-1.fc26.noarch pulp-python-plugins-2.0.2-1.fc26.noarch pulp-rpm-admin-extensions-2.16.1-1.fc26.noarch pulp-rpm-plugins-2.16.1-1.fc26.noarch pulp-selinux-2.16.1-1.fc26.noarch pulp-server-2.16.1-1.fc26.noarch python-pulp-bindings-2.16.1-1.fc26.noarch python-pulp-client-lib-2.16.1-1.fc26.noarch python-pulp-common-2.16.1-1.fc26.noarch python-pulp-deb-common-1.7.0-1.fc26.noarch python-pulp-docker-common-3.1.3-1.fc26.noarch python-pulp-oid_validation-2.16.1-1.fc26.noarch python-pulp-ostree-common-1.3.0-1.fc26.noarch python-pulp-puppet-common-2.16.1-1.fc26.noarch python-pulp-python-common-2.0.2-1.fc26.noarch python-pulp-repoauth-2.16.1-1.fc26.noarch python-pulp-rpm-common-2.16.1-1.fc26.noarch python-pulp-streamer-2.16.1-1.fc26.noarch </pre> <pre>[root@fedora-27-pulp-2-16-stable audit]# rpm -qa | grep mongo | sort mongodb-3.4.11-2.fc27.x86_64 mongodb-server-3.4.11-2.fc27.x86_64 python2-mongoengine-0.15.1-1.fc27.noarch python2-pymongo-3.5.1-1.fc27.x86_64 python2-pymongo-gridfs-3.5.1-1.fc27.x86_64 [root@fedora-27-pulp-2-16-stable audit]# rpm -qa | grep pulp | sort pulp-admin-client-2.16.1-1.fc27.noarch pulp-deb-admin-extensions-1.7.0-1.fc27.noarch pulp-deb-plugins-1.7.0-1.fc27.noarch pulp-docker-admin-extensions-3.1.3-1.fc27.noarch pulp-docker-plugins-3.1.3-1.fc27.noarch pulp-ostree-admin-extensions-1.3.0-1.fc27.noarch pulp-ostree-plugins-1.3.0-1.fc27.noarch pulp-puppet-admin-extensions-2.16.1-1.fc27.noarch pulp-puppet-plugins-2.16.1-1.fc27.noarch pulp-puppet-tools-2.16.1-1.fc27.noarch pulp-python-admin-extensions-2.0.2-1.fc27.noarch pulp-python-plugins-2.0.2-1.fc27.noarch pulp-rpm-admin-extensions-2.16.1-1.fc27.noarch pulp-rpm-plugins-2.16.1-1.fc27.noarch pulp-selinux-2.16.1-1.fc27.noarch pulp-server-2.16.1-1.fc27.noarch python-pulp-bindings-2.16.1-1.fc27.noarch python-pulp-client-lib-2.16.1-1.fc27.noarch python-pulp-common-2.16.1-1.fc27.noarch python-pulp-deb-common-1.7.0-1.fc27.noarch python-pulp-docker-common-3.1.3-1.fc27.noarch python-pulp-oid_validation-2.16.1-1.fc27.noarch python-pulp-ostree-common-1.3.0-1.fc27.noarch python-pulp-puppet-common-2.16.1-1.fc27.noarch python-pulp-python-common-2.0.2-1.fc27.noarch python-pulp-repoauth-2.16.1-1.fc27.noarch python-pulp-rpm-common-2.16.1-1.fc27.noarch python-pulp-streamer-2.16.1-1.fc27.noarch </pre> Finally, it's worth noting that the Pulp 2 Vagrant VMs still use Fedora 26. See: https://github.com/pulp/devel/blob/master/Vagrantfile.example#L30
.