Bug 1699109 - Occasional 'whoami.data is undefined' error in FreeIPA web UI
Summary: Occasional 'whoami.data is undefined' error in FreeIPA web UI
Keywords:
Status: POST
Alias: None
Product: Fedora
Classification: Fedora
Component: freeipa
Version: 30
Hardware: All
OS: Linux
unspecified
medium
Target Milestone: ---
Assignee: IPA Maintainers
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2019-04-11 20:00 UTC by Adam Williamson
Modified: 2019-05-21 19:14 UTC (History)
11 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:


Attachments (Terms of Use)
screenshot of browser error (113.98 KB, image/png)
2019-04-11 20:02 UTC, Adam Williamson
no flags Details
tarball of /var/log from the client (2.12 MB, application/octet-stream)
2019-04-11 20:03 UTC, Adam Williamson
no flags Details
tarball of /var/log from the server (2.59 MB, application/octet-stream)
2019-04-11 20:05 UTC, Adam Williamson
no flags Details

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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@IPA.EXAMPLE",
    "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@IPA.EXAMPLE",
    "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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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@DOMAIN.LOCAL: 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


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