Project

Profile

Help

Issue #3687

Pulp 2 doesn't work on Fedora 27+

Added by Ichimonji10 about 1 year ago. Updated 2 months ago.

Status:
CLOSED - CURRENTRELEASE
Priority:
Urgent
Assignee:
Category:
-
Sprint/Milestone:
-
Severity:
3. High
Version:
Master
Platform Release:
2.16.2
Blocks Release:
OS:
Backwards Incompatible:
No
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
Pulp 2
QA Contact:
Complexity:
Smash Test:
Verified:
Yes
Verification Required:
No
Sprint:
Sprint 38

Description

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 python -m unittest pulp_smash.tests.pulp2.docker.api_v2.test_copy. (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:

[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'.

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 logs on Fedora 26 and 27:

[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)
[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)

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:

[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
[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

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


Related issues

Duplicates Pulp - Issue #3148: dupicate key error on task_status collection with mongoengine 0.14 CLOSED - DUPLICATE Actions

Associated revisions

Revision f045e190 View on GitHub
Added by dalley about 1 year ago

Fixes Pulp w/ Mongoengine v0.14.1+

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

Revision c6e8bed7 View on GitHub
Added by dalley about 1 year ago

Fixes Pulp w/ Mongoengine v0.14.1+

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

(cherry picked from commit f045e190172784312f27d2fc315a46f57be48bad)

History

#1 Updated by Ichimonji10 about 1 year ago

  • Description updated (diff)

#2 Updated by dalley about 1 year ago

  • Priority changed from Normal to High
  • Severity changed from 2. Medium to 3. High

#3 Updated by dalley about 1 year ago

  • Priority changed from High to Urgent
  • Triaged changed from No to Yes

#4 Updated by ttereshc about 1 year ago

I guess the problem is in mongoengine version and this issue is a dup of #3148.
Thoughts?

#5 Updated by dalley about 1 year ago

Agree @ttereshc, it does look like the same issue.

#6 Updated by dalley about 1 year ago

  • Duplicates Issue #3148: dupicate key error on task_status collection with mongoengine 0.14 added

#7 Updated by ttereshc about 1 year ago

FWIW, in F27 there is mongoengine 0.12, so a temporary solution is to limit mongoengine version to <=0.13.
But for F28 it's 0.14+, so Pulp won't work on F28 without any fixes.

https://apps.fedoraproject.org/packages/python-mongoengine/builds/

#8 Updated by dalley about 1 year ago

  • Subject changed from Pulp 2 doesn't work on Fedora 27 to Pulp 2 doesn't work on Fedora 27+

#9 Updated by dalley about 1 year ago

  • Sprint set to Sprint 37

#10 Updated by kersom about 1 year ago

Just a few notes:

I was able to downgrade the package python2-mongoengine to 0.12.0-1, and run tests against the system. The reported error did not appear again.

I looked the history of updates of python2-mongoengine package.

https://apps.fedoraproject.org/packages/python-mongoengine/updates/

In May 10 the package was updated to version python2-mongoengine-0.15.1-1.fc27, in the next day we started to have failures on our tests.

It seems to me that this update was the cause of test failures on F27.

Issue #3148, marked as duplicated for this one, was filed against an OS (Suse) that we do not use as part of test automation.

#11 Updated by rchan about 1 year ago

  • Status changed from NEW to CLOSED - DUPLICATE

Keeping the newer issue open (#3687) since it has a higher urgency due to impacting fedora and our nightly automation.

#12 Updated by rchan about 1 year ago

  • Status changed from CLOSED - DUPLICATE to NEW

#13 Updated by dalley about 1 year ago

  • Status changed from NEW to ASSIGNED
  • Assignee set to dalley

After bisecting commits using a source installation of Mongoengine, the culprit commit was this Pull Request to Mongoengine

https://github.com/MongoEngine/mongoengine/pull/1630

I will try to contact the developers for help regarding this issue. In the meantime I will also try to work around the issue from our end.

#14 Updated by rchan about 1 year ago

  • Sprint changed from Sprint 37 to Sprint 38

#15 Updated by dalley about 1 year ago

  • Status changed from ASSIGNED to POST

Problem wasn't in Mongoengine, it was in our own code relying on Mongoengine implementation details.

https://github.com/pulp/pulp/pull/3514

#16 Updated by dalley about 1 year ago

  • Status changed from POST to MODIFIED

#17 Updated by dkliban@redhat.com about 1 year ago

  • Platform Release set to 2.16.2

#19 Updated by ragbalak 12 months ago

  • Verified changed from No to Yes

I ran the pulp-smash file python -m unittest pulp_smash.tests.pulp2.docker.api_v2.test_copy
with
pulp_smash/tests/pulp2/docker/utils.py : line 20 : Commented out
pulp2_utils.require_issue_3687() (Else it was skipping)

This ran successfully 6 tests

#20 Updated by ipanova@redhat.com 12 months ago

  • Status changed from MODIFIED to CLOSED - CURRENTRELEASE

#21 Updated by bmbouter 2 months ago

  • Tags Pulp 2 added

Please register to edit this issue

Also available in: Atom PDF