Bug 1503321 - FreeIPA server upgraded from F26 to F27 fails to start with "ModuleNotFoundError: No module named 'ipapython.secrets'"
Summary: FreeIPA server upgraded from F26 to F27 fails to start with "ModuleNotFoundEr...
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: freeipa
Version: 27
Hardware: All
OS: Linux
unspecified
high
Target Milestone: ---
Assignee: IPA Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard: CommonBugs RejectedBlocker
Depends On: 1452866
Blocks:
TreeView+ depends on / blocked
 
Reported: 2017-10-17 21:19 UTC by Adam Williamson
Modified: 2018-02-20 17:12 UTC (History)
11 users (show)

Fixed In Version: freeipa-4.6.3-2.fc27
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-02-20 17:12:34 UTC
Type: Bug
Embargoed:


Attachments (Terms of Use)

Description Adam Williamson 2017-10-17 21:19:02 UTC
The openQA test for FreeIPA upgrade from Fedora 26 to Fedora 27 is failing. This seems to be because IPA does not start correctly after the upgrade. Looking at the system logs, it appears ipa-custodia.service fails to start up, with this traceback:

Oct 17 09:44:13 ipa001.domain.local systemd[1]: Starting IPA Custodia Service...
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: 2017-10-17 12:44:13 - custodia                         - Custodia instance <main>
Oct 17 09:44:13 ipa001.domain.local python3[1091]: detected unhandled Python exception in '/usr/libexec/ipa/ipa-custodia'
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: Traceback (most recent call last):
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib/python3.6/site-packages/custodia/server/__init__.py", line 66, in _create_plugin
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     handler = _load_plugin_class(menu, handler_name)
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib/python3.6/site-packages/custodia/server/__init__.py", line 53, in _load_plugin_class
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     m = importlib.import_module(module)
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib64/python3.6/importlib/__init__.py", line 126, in import_module
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     return _bootstrap._gcd_import(name[level:], package, level)
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "<frozen importlib._bootstrap>", line 978, in _gcd_import
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "<frozen importlib._bootstrap>", line 961, in _find_and_load
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "<frozen importlib._bootstrap>", line 936, in _find_and_load_unlocked
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "<frozen importlib._bootstrap>", line 205, in _call_with_frames_removed
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "<frozen importlib._bootstrap>", line 978, in _gcd_import
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "<frozen importlib._bootstrap>", line 961, in _find_and_load
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "<frozen importlib._bootstrap>", line 948, in _find_and_load_unlocked
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: ModuleNotFoundError: No module named 'ipapython.secrets'
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: During handling of the above exception, another exception occurred:
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: Traceback (most recent call last):
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib/python3.6/site-packages/custodia/server/__init__.py", line 116, in _load_plugins
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     config[menu][name] = _create_plugin(cfgparser, s, menu)
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib/python3.6/site-packages/custodia/server/__init__.py", line 71, in _create_plugin
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     '[%r]: %s' % (e, handler_name))
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: ValueError: Invalid format for "handler" option [ModuleNotFoundError("No module named 'ipapython.secrets'",)]: ipapython.secrets.kem.IPAKEMKeys
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: During handling of the above exception, another exception occurred:
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: Traceback (most recent call last):
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/libexec/ipa/ipa-custodia", line 6, in <module>
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     main()
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib/python3.6/site-packages/ipaserver/secrets/service.py", line 26, in main
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     return custodia.server.main(argparser)
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib/python3.6/site-packages/custodia/server/__init__.py", line 138, in main
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     _load_plugins(config, cfgparser)
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:   File "/usr/lib/python3.6/site-packages/custodia/server/__init__.py", line 119, in _load_plugins
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]:     raise RuntimeError(menu, name, e)
Oct 17 09:44:13 ipa001.domain.local ipa-custodia[1091]: RuntimeError: ('authorizers', 'kemkeys', ValueError('Invalid format for "handler" option [ModuleNotFoundError("No module named \'ipapython.secrets\'",)]: ipapython.secrets.kem.IPAKEMKeys',))
Oct 17 09:44:13 ipa001.domain.local systemd[1]: ipa-custodia.service: Main process exited, code=exited, status=1/FAILURE
Oct 17 09:44:13 ipa001.domain.local systemd[1]: Failed to start IPA Custodia Service.

Note that python3-ipalib is installed, and contains the ipapython library, but not an ipapython.secrets module. AFAICS there *is* no ipapython.secrets module available in any package. I am not sure where the attempt to use it comes from; perhaps the module got removed / moved between 26 and 27, and new installs don't attempt to use it, but the upgrade process somehow fails to remove some old reference to it?

Proposing as a Server Beta blocker per criterion "For each one of the release-blocking package sets, it must be possible to successfully complete a direct upgrade from fully updated installations of the last two stable Fedora releases with that package set installed." - there's a bit of uncertainty as to whether this is enough to cover FreeIPA issues on upgrade, but I believe we've taken them as blockers before.

Comment 1 Alexander Bokovoy 2017-10-18 05:03:24 UTC
Adam, can you point to the OpenQA logs? We have custodia config upgrade (actual modules to load are specified in the custodia config file) and I'd like to see ipaupgrade.log of this.

Comment 2 Christian Heimes 2017-10-18 07:23:41 UTC
The package ipapython.secrets have been renamed to ipaserver.secrets in 4.6. ipa-server-upgrade should update /etc/ipa/custodia/custodia.conf to use the new package names. Please post your upgrade log and a copy of /etc/ipa/custodia/custodia.conf

Comment 3 Alexander Bokovoy 2017-10-18 09:22:06 UTC
We do custodia configuration update in ipa-server-upgrade. Probably custodia restarted as part of all services before this step. Maybe it needs to be moved earlier in the upgrade sequence...

Comment 4 Christian Heimes 2017-10-18 09:26:26 UTC
The order is correct and has always worked in the past. I have seen the very issue before. It was caused by a failed / aborted ipa-server-upgrade run. I'm 98% sure it's a botched upgrade. We should keep track of ipa-server-upgrade and report failed upgrades. I have opend https://pagure.io/freeipa/issue/7215

Comment 6 Adam Williamson 2017-10-18 16:43:53 UTC
Note, the upgrade failure is caused by https://bugzilla.redhat.com/show_bug.cgi?id=1452866 , I think.

Comment 7 Geoffrey Marr 2017-10-23 21:41:13 UTC
Discussed during the 2017-10-23 blocker review meeting: [1]

The decision to classify this bug as an AcceptedBlocker was made, even though there is no current criteria to warrant blocking on this. We plan to make a near-future change to the criteria so that a bug like this from this point on will be blocker-qualifying.

[1] https://meetbot.fedoraproject.org/fedora-blocker-review/2017-10-23/f27-blocker-review.2017-10-23-16.00.txt

Comment 8 Adam Williamson 2017-10-30 22:45:09 UTC
It looks a lot like 1452866 really is at the root of this.

Comment 9 Adam Williamson 2017-11-07 20:31:30 UTC
I'm marking this as CommonBugs on the basis that I suspect some people are gonna try and upgrade before we actually have this fixed, regardless of exactly what we decide our Official Story for people upgrading from Fedora 26 Server to Fedora 27 is. And for those folks a note saying "run the upgrade script manually with the network active" would be helpful.

Comment 10 Adam Williamson 2017-11-30 01:02:26 UTC
Proposing as a (0-day) blocker for the proposed delayed F27 Server release we will be discussing at a special go/no-go meeting tomorrow.

Comment 11 Adam Williamson 2017-12-02 03:30:08 UTC
Discussed at 2017-11-30 special F27 Server Go/No-Go meeting, acting as a blocker review meeting: https://meetbot-raw.fedoraproject.org/fedora-meeting-1/2017-11-30/f27-server-final-go-no-go-meeting.2017-11-30-18.04.html . We agreed to reject this as a blocker, for several reasons. There's an easy workaround we can document (just run the upgrade script manually post-upgrade). The issue can be fixed with an update (all upgrades use network repos). And since F27 has already been 'released', and people aren't probably paying super-close attention to the Server mess, "delaying" the Server "release" for this bug probably isn't going to make much practical difference to whether people in the real world decide to upgrade and hit this bug anyway. So we figure there's no major benefit to blocking on it.

Comment 12 Rob Crittenden 2018-01-29 12:34:22 UTC
This is related to the automatic upgrade not succeeding in the rpm %post. There are two upstream related fixes in pagure tickets 7039 and 6968:

ipa-4-6:
    b2d3b56 Run server upgrade in ipactl start/restart

master (4-6):
    a36f2ae Ensure network is online prior to an upgrade
ipa-4-5:
    6ca6942 Ensure network is online prior to an upgrade

Comment 13 Fedora Update System 2018-02-05 21:40:07 UTC
freeipa-4.6.3-1.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-787ba41890

Comment 14 Fedora Update System 2018-02-09 00:09:51 UTC
freeipa-4.6.3-2.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-787ba41890

Comment 15 Fedora Update System 2018-02-09 18:46:51 UTC
freeipa-4.6.3-2.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2018-787ba41890

Comment 16 Fedora Update System 2018-02-20 17:12:34 UTC
freeipa-4.6.3-2.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.


Note You need to log in before you can comment on or make changes to this bug.