Bug 1699109

Summary: Occasional 'whoami.data is undefined' error in FreeIPA web UI
Product: [Fedora] Fedora Reporter: Adam Williamson <awilliam>
Component: freeipaAssignee: IPA Maintainers <ipa-maint>
Status: CLOSED ERRATA QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: medium Docs Contact:
Priority: unspecified    
Version: 30CC: abokovoy, cheimes, fdc, ipa-maint, jcholast, jhrozek, pvoborni, rcritten, ssorce, stsymbal, twoerner
Target Milestone: ---   
Target Release: ---   
Hardware: All   
OS: Linux   
Whiteboard:
Fixed In Version: freeipa-4.8.2-1.fc31 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2019-11-20 01:02:14 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:
Attachments:
Description Flags
screenshot of browser error
none
tarball of /var/log from the client
none
tarball of /var/log from the server none

Description Adam Williamson 2019-04-11 20:00:37 UTC 
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.
Comment 1 Adam Williamson 2019-04-11 20:02:32 UTC 
Created attachment 1554629 [details]
screenshot of browser error
Comment 2 Adam Williamson 2019-04-11 20:03:54 UTC 
Created attachment 1554630 [details]
tarball of /var/log from the client
Comment 3 Adam Williamson 2019-04-11 20:05:18 UTC 
Created attachment 1554631 [details]
tarball of /var/log from the server
Comment 4 Alexander Bokovoy 2019-04-12 08:21:01 UTC 
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
Comment 5 Christian Heimes 2019-04-12 09:16:16 UTC 
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
Comment 6 Alexander Bokovoy 2019-04-12 09:35:00 UTC 
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.
Comment 7 Alexander Bokovoy 2019-04-12 09:37:10 UTC 
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
Comment 8 Alexander Bokovoy 2019-04-12 09:41:52 UTC 
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.
Comment 9 Serhii Tsymbaliuk 2019-04-16 12:21:13 UTC 
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.
Comment 10 Serhii Tsymbaliuk 2019-04-17 07:23:23 UTC 
Upstream ticket:
https://pagure.io/freeipa/issue/7917
Comment 11 Serhii Tsymbaliuk 2019-05-21 12:55:42 UTC 
Fixed upstream:
master:
    6a9c20a Fix occasional 'whoami.data is undefined' error in FreeIPA web UI
Comment 12 Rob Crittenden 2019-05-21 19:14:13 UTC 
Upstream ticket:
https://pagure.io/freeipa/issue/7917
Comment 13 Fedora Update System 2019-11-12 20:48:20 UTC 
FEDORA-2019-75a963e4cb has been submitted as an update to Fedora 31. https://bodhi.fedoraproject.org/updates/FEDORA-2019-75a963e4cb
Comment 14 Fedora Update System 2019-11-13 10:53:06 UTC 
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
Comment 15 Fedora Update System 2019-11-20 01:02:14 UTC 
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.