Bug 1503321
| Summary: | FreeIPA server upgraded from F26 to F27 fails to start with "ModuleNotFoundError: No module named 'ipapython.secrets'" | ||
|---|---|---|---|
| Product: | [Fedora] Fedora | Reporter: | Adam Williamson <awilliam> |
| Component: | freeipa | Assignee: | IPA Maintainers <ipa-maint> |
| Status: | CLOSED ERRATA | QA Contact: | Fedora Extras Quality Assurance <extras-qa> |
| Severity: | high | Docs Contact: | |
| Priority: | unspecified | ||
| Version: | 27 | CC: | abokovoy, awilliam, cheimes, gmarr, ipa-maint, jhrozek, jpazdziora, pvoborni, rcritten, samuel-rhbugs, ssorce |
| Target Milestone: | --- | ||
| Target Release: | --- | ||
| Hardware: | All | ||
| OS: | Linux | ||
| Whiteboard: | CommonBugs RejectedBlocker | ||
| Fixed In Version: | freeipa-4.6.3-2.fc27 | Doc Type: | If docs needed, set a value |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2018-02-20 17:12:34 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
| Embargoed: | |||
| Bug Depends On: | 1452866 | ||
| Bug Blocks: | |||
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. 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 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... 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 Logs are at e.g. https://openqa.fedoraproject.org/tests/158993#downloads . https://openqa.fedoraproject.org/tests/158993/file/_console_avc_crash-var_log.tar.gz is /var/log/ . Note, the upgrade failure is caused by https://bugzilla.redhat.com/show_bug.cgi?id=1452866 , I think. 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 It looks a lot like 1452866 really is at the root of this. 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. 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. 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. 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
freeipa-4.6.3-1.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-787ba41890 freeipa-4.6.3-2.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2018-787ba41890 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 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. |
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.