Project

Profile

Help

Issue #3687

closed

Pulp 2 doesn't work on Fedora 27+

Added by Ichimonji10 almost 6 years ago. Updated almost 5 years ago.

Status:
CLOSED - CURRENTRELEASE
Priority:
Urgent
Assignee:
Category:
-
Sprint/Milestone:
-
Start date:
Due date:
Estimated time:
Severity:
3. High
Version:
Master
Platform Release:
2.16.2
OS:
Triaged:
Yes
Groomed:
No
Sprint Candidate:
No
Tags:
Pulp 2
Sprint:
Sprint 38
Quarter:

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

Is duplicate of Pulp - Issue #3148: dupicate key error on task_status collection with mongoengine 0.14 CLOSED - DUPLICATEActions
Actions #1

Updated by Ichimonji10 almost 6 years ago

  • Description updated (diff)
Actions #2

Updated by dalley almost 6 years ago

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

Updated by dalley almost 6 years ago

  • Priority changed from High to Urgent
  • Triaged changed from No to Yes
Actions #4

Updated by ttereshc almost 6 years ago

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

Actions #5

Updated by dalley almost 6 years ago

Agree ttereshc, it does look like the same issue.

Actions #6

Updated by dalley almost 6 years ago

  • Is duplicate of Issue #3148: dupicate key error on task_status collection with mongoengine 0.14 added
Actions #7

Updated by ttereshc almost 6 years 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/

Actions #8

Updated by dalley almost 6 years ago

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

Updated by dalley almost 6 years ago

  • Sprint set to Sprint 37
Actions #10

Updated by kersom almost 6 years 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.

Actions #11

Updated by rchan almost 6 years 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.

Actions #12

Updated by rchan almost 6 years ago

  • Status changed from CLOSED - DUPLICATE to NEW
Actions #13

Updated by dalley almost 6 years 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.

Actions #14

Updated by rchan almost 6 years ago

  • Sprint changed from Sprint 37 to Sprint 38
Actions #15

Updated by dalley almost 6 years 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

Added by dalley almost 6 years ago

Revision f045e190 | View on GitHub

Fixes Pulp w/ Mongoengine v0.14.1+

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

Actions #16

Updated by dalley almost 6 years ago

  • Status changed from POST to MODIFIED
Actions #17

Updated by dkliban@redhat.com almost 6 years ago

  • Platform Release set to 2.16.2

Added by dalley over 5 years ago

Revision c6e8bed7 | View on GitHub

Fixes Pulp w/ Mongoengine v0.14.1+

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

(cherry picked from commit f045e190172784312f27d2fc315a46f57be48bad)

Actions #18

Updated by dalley over 5 years ago

Actions #19

Updated by ragbalak over 5 years ago

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

Actions #20

Updated by ipanova@redhat.com over 5 years ago

  • Status changed from MODIFIED to CLOSED - CURRENTRELEASE
Actions #21

Updated by bmbouter almost 5 years ago

  • Tags Pulp 2 added

Also available in: Atom PDF