Just a couple of times, the openQA FreeIPA web UI test has failed due to the web UI falling over showing a 'whoami.data is undefined' error: https://openqa.fedoraproject.org/tests/373613 https://openqa.fedoraproject.org/tests/380970 This is a pretty rare failure - those are the only two instances I've found over hundreds of runs of the test. This happens when logging into the UI as the 'admin' user: after the test enters the password, a 'Loading data' notification appears very briefly and then this error is shown. I'll attach a screenshot of the error (in case the tests get garbage collected from openQA), and log tarballs from both client and server ends.
Created attachment 1554629 [details] screenshot of browser error
Created attachment 1554630 [details] tarball of /var/log from the client
Created attachment 1554631 [details] tarball of /var/log from the server
Looks like it is an issue on the web UI side, perhaps, due to vaultconfig_show returning an invocation error. whoami call is issued within a batch call, so results are batched too and if vaultconfig_show is failing (due to KRA not enabled), perhaps json result is not fully correct? I guess we need to see if vaultconfig_show on a system without KRA enabled does something fishy. [Wed Apr 10 18:16:57.597366 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: batch(({'method': 'config_show', 'params': ([], {})}, {'method': 'whoami', 'params': ([], {})}, {'method': 'env', 'params': ([], {})}, {'method': 'dns_is_enabled', 'params': ([], {})}, {'method': 'trustconfig_show', 'params': ([], {})}, {'method': 'domainlevel_get', 'params': ([], {})}, {'method': 'ca_is_enabled', 'params': ([], {})}, {'method': 'vaultconfig_show', 'params': ([], {})}), version='2.230') [Wed Apr 10 18:16:57.597542 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: batch(({'method': 'config_show', 'params': ([], {})}, {'method': 'whoami', 'params': ([], {})}, {'method': 'env', 'params': ([], {})}, {'method': 'dns_is_enabled', 'params': ([], {})}, {'method': 'trustconfig_show', 'params': ([], {})}, {'method': 'domainlevel_get', 'params': ([], {})}, {'method': 'ca_is_enabled', 'params': ([], {})}, {'method': 'vaultconfig_show', 'params': ([], {})}), version='2.230') [Wed Apr 10 18:16:57.597732 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: config_show(version='2.230') [Wed Apr 10 18:16:57.597863 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: config_show(rights=False, all=False, raw=False, version='2.230') [Wed Apr 10 18:16:57.612202 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: config_show(): SUCCESS [Wed Apr 10 18:16:57.612332 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: whoami(version='2.230') [Wed Apr 10 18:16:57.612419 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: whoami(version='2.230') [Wed Apr 10 18:16:57.615420 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: whoami(): SUCCESS [Wed Apr 10 18:16:57.615543 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: env(None, version='2.230') [Wed Apr 10 18:16:57.615631 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: env(None, server=False, all=True, version='2.230') [Wed Apr 10 18:16:57.615934 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: env(None): SUCCESS [Wed Apr 10 18:16:57.616018 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: dns_is_enabled(version='2.230') [Wed Apr 10 18:16:57.616088 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: dns_is_enabled(version='2.230') [Wed Apr 10 18:16:57.617112 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: dns_is_enabled(): SUCCESS [Wed Apr 10 18:16:57.617222 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: trustconfig_show(version='2.230') [Wed Apr 10 18:16:57.617319 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: trustconfig_show(rights=False, trust_type='ad', all=False, raw=False, version='2.230') [Wed Apr 10 18:16:57.618022 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: trustconfig_show(): NotFound [Wed Apr 10 18:16:57.618135 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: domainlevel_get(version='2.230') [Wed Apr 10 18:16:57.618200 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: domainlevel_get(version='2.230') [Wed Apr 10 18:16:57.618915 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: domainlevel_get(): SUCCESS [Wed Apr 10 18:16:57.619006 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: ca_is_enabled(version='2.230') [Wed Apr 10 18:16:57.619084 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: ca_is_enabled(version='2.230') [Wed Apr 10 18:16:57.620439 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: ca_is_enabled(): SUCCESS [Wed Apr 10 18:16:57.620537 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: vaultconfig_show(version='2.230') [Wed Apr 10 18:16:57.620613 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: vaultconfig_show(all=False, raw=False, version='2.230') [Wed Apr 10 18:16:57.620721 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: kra_is_enabled(version='2.230') [Wed Apr 10 18:16:57.620773 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: kra_is_enabled(version='2.230') [Wed Apr 10 18:16:57.621367 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: admin: batch: vaultconfig_show(): InvocationError [Wed Apr 10 18:16:57.621486 2019] [wsgi:error] [pid 8335:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: [jsonserver_session] admin: batch(({'method': 'config_show', 'params': ([], {})}, {'method': 'whoami', 'params': ([], {})}, {'method': 'env', 'params': ([], {})}, {'method': 'dns_is_enabled', 'params': ([], {})}, {'method': 'trustconfig_show', 'params': ([], {})}, {'method': 'domainlevel_get', 'params': ([], {})}, {'method': 'ca_is_enabled', 'params': ([], {})}, {'method': 'vaultconfig_show', 'params': ([], {})}), version='2.230'): SUCCESS
On a system without KRA and trust, both plugins fail with an exception. The batch command returns correct error structures for both excepted errors. This should work just fine: >>> pp(api.Command.batch([{'method': 'trustconfig_show', 'params': ([], {})}, {'method': 'vaultconfig_show', 'params': ([], {})}])) {'count': 2, 'results': ({'error': ': trust configuration not found', 'error_code': 4001, 'error_kw': {'reason': ': trust configuration not found'}, 'error_name': 'NotFound'}, {'error': 'KRA service is not enabled', 'error_code': 3000, 'error_kw': {}, 'error_name': 'InvocationError'})} # ipa -vv vaultconfig_show ipa: INFO: Request: { "id": 0, "method": "vaultconfig_show/1", "params": [ [], { "version": "2.231" } ] } ipa: INFO: Response: { "error": { "code": 3000, "data": {}, "message": "KRA service is not enabled", "name": "InvocationError" }, "id": 0, "principal": "admin", "result": null, "version": "4.7.90.dev201904111944+gitd68fe6b98" } ipa: ERROR: KRA service is not enabled # ipa -vv trustconfig-show ipa: INFO: Request: { "id": 0, "method": "trustconfig_show/1", "params": [ [], { "version": "2.231" } ] } ipa: INFO: Response: { "error": { "code": 4001, "data": { "reason": ": trust configuration not found" }, "message": ": trust configuration not found", "name": "NotFound" }, "id": 0, "principal": "admin", "result": null, "version": "4.7.90.dev201904111944+gitd68fe6b98" } ipa: ERROR: : trust configuration not found
ok, so the buggy code is in 'update_logged_in' callback in Application_controller.js: update_logged_in: function(logged_in) { this.app_widget.set('logged', logged_in); var whoami = IPA.whoami; var fullname = ''; var entity = whoami.metadata.object; if (whoami.data.cn) { fullname = whoami.data.cn[0]; } else if (whoami.data.displayname) { fullname = whoami.data.displayname[0]; } else if (whoami.data.gecos) { fullname = whoami.data.gecos[0]; } else if (whoami.data.krbprincipalname) { fullname = whoami.data.krbprincipalname[0]; } else if (whoami.data.ipaoriginaluid) { fullname = whoami.data.ipaoriginaluid[0]; } this.app_widget.set('fullname', fullname); }, the screenshot talks about 'whoami.data' is undefined. I wonder if this is due to get_whoami_command() in ipa.js doing two rpc calls in a row -- first whoami() and then actuall <object>-show method for the object type returned by the whoami(). I don't see the latter call somehow.
Actually, the latter user_show() is there but after json_metadata() call, so ordering is off. [Wed Apr 10 18:16:57.659567 2019] [wsgi:error] [pid 8334:tid 139967029143296] [remote 10.0.2.102:46124] ipa: DEBUG: raw: json_metadata(None, None, object='all', version='2.230') [Wed Apr 10 18:16:57.659646 2019] [wsgi:error] [pid 8334:tid 139967029143296] [remote 10.0.2.102:46124] ipa: DEBUG: json_metadata(None, None, object='all', version='2.230') [Wed Apr 10 18:16:57.781372 2019] [wsgi:error] [pid 8334:tid 139967029143296] [remote 10.0.2.102:46124] ipa: INFO: [jsonserver_session] admin: json_metadata(None, None, object='all', version='2.230'): SUCCESS [Wed Apr 10 18:16:57.835640 2019] [wsgi:error] [pid 8334:tid 139967029143296] [remote 10.0.2.102:46124] ipa: DEBUG: Destroyed connection context.ldap2_139967055160488 [Wed Apr 10 18:16:58.266861 2019] [wsgi:error] [pid 8337:tid 139967029143296] [remote 10.0.2.102:46122] ipa: INFO: [jsonserver_session] admin: json_metadata(None, None, command='all', version='2.230'): SUCCESS [Wed Apr 10 18:16:58.477359 2019] [wsgi:error] [pid 8337:tid 139967029143296] [remote 10.0.2.102:46122] ipa: DEBUG: Destroyed connection context.ldap2_139967055160488 [Wed Apr 10 18:16:58.662855 2019] [wsgi:error] [pid 8336:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: Created connection context.ldap2_139967055160376 [Wed Apr 10 18:16:58.662987 2019] [wsgi:error] [pid 8336:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: WSGI jsonserver.__call__: [Wed Apr 10 18:16:58.663090 2019] [wsgi:error] [pid 8336:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: WSGI WSGIExecutioner.__call__: [Wed Apr 10 18:16:58.663535 2019] [wsgi:error] [pid 8336:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: raw: user_show('admin', all=True, version='2.230') [Wed Apr 10 18:16:58.663780 2019] [wsgi:error] [pid 8336:tid 139967029143296] [remote 10.0.2.102:46130] ipa: DEBUG: user_show('admin', rights=False, all=True, raw=False, version='2.230', no_members=False) [Wed Apr 10 18:16:58.678678 2019] [wsgi:error] [pid 8336:tid 139967029143296] [remote 10.0.2.102:46130] ipa: INFO: [jsonserver_session] admin: user_show/1('admin', all=True, version='2.230'): SUCCESS
And the full reason looks like we move into 'profile' phase before 'init' phase completed. In 'profile' phase we call 'this.app.choose_profile()' which triggers the code path to call update_logged_in(). So I think we need to make sure profile phase is deferred until init phase truly completes.
Seems there are two issues. First is that commands in the 'init' task is not synchronized and 'init' phase ends while they are continue running. Second is that we have one RPC-call after another and don't wait a 'promise' from second one. Both issues are solvable, so I going to start work on the ticket.
Upstream ticket: https://pagure.io/freeipa/issue/7917
Fixed upstream: master: 6a9c20a Fix occasional 'whoami.data is undefined' error in FreeIPA web UI
FEDORA-2019-75a963e4cb has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-75a963e4cb
freeipa-4.8.2-1.fc31 has been pushed to the Fedora 31 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-2019-75a963e4cb
freeipa-4.8.2-1.fc31 has been pushed to the Fedora 31 stable repository. If problems still persist, please make note of it in this bug report.