# Pastebin nh10MxMo Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] REQUEST_METHOD: `GET` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] SCRIPT_NAME: `/identity` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] PATH_INFO: `/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] Environment variables: {'AUTH_TYPE': 'shibboleth', 'wsgi.multiprocess': True, 'HTTP_COOKIE': '_shibsession_64656661756c74687474703a2f2f6d7973702e76697368616b68612e636f6d2f73686962626f6c657468=_9c3a51ebbfaf6ada7fac371e6165caf0', 'CONTEXT_DOCUMENT_ROOT': '/opt/stack/horizon/.blackhole/', 'SERVER_SOFTWARE': 'Apache/2.4.18 (Ubuntu)', 'uwsgi.version': '2.0.17.1', 'CONTEXT_PREFIX': '', 'keystone.token_auth': , 'webob.adhoc_attrs': {'response': <_AuthTokenResponse at 0x7f37e369ec50 200 OK>}, 'SERVER_SIGNATURE': '
Apache/2.4.18 (Ubuntu) Server at 192.168.122.221 Port 80
\n', 'REQUEST_METHOD': 'GET', 'keystone.oslo_request_context': , 'PATH_INFO': '/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'SERVER_PROTOCOL': 'HTTP/1.1', 'QUERY_STRING': '', 'PATH': '/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'proxy-sendchunked': '1', 'werkzeug.proxy_fix.orig_wsgi_url_scheme': 'http', 'openstack_user': 'vishakha', 'HTTP_USER_AGENT': 'openstack_auth keystoneauth1/3.11.1 python-requests/2.20.0 CPython/2.7.12', 'HTTP_CONNECTION': 'keep-alive', 'SERVER_NAME': '192.168.122.221', 'REMOTE_ADDR': '192.168.122.222', 'Shib-AuthnContext-Class': 'urn:oasis:names:tc:SAML:2.0:ac:classes:Password', 'wsgi.url_scheme': 'http', 'Shib-Authentication-Method': 'urn:oasis:names:tc:SAML:2.0:ac:classes:Password', 'APACHE_RUN_GROUP': 'stack', 'REMOTE_USER': '', 'SERVER_PORT': '80', 'werkzeug.proxy_fix.orig_http_host': '192.168.122.221', 'openstack_user_domain': 'Default', 'openstack_roles': 'reader;member;admin', 'SERVER_ADDR': '192.168.122.221', 'DOCUMENT_ROOT': '/opt/stack/horizon/.blackhole/', 'Shib-Authentication-Instant': '2018-11-08T09:13:26Z', 'werkzeug.request': , 'SCRIPT_FILENAME': 'proxy:uwsgi://uwsgi-uds-keystone-wsgi-public//v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'openstack_project_domain': 'Default', 'SERVER_ADMIN': '[no address given]', 'wsgi.input': , 'openstack_project': 'admin', 'HTTP_HOST': '192.168.122.221', 'SCRIPT_NAME': '/identity', 'wsgi.multithread': False, 'Shib-Session-Index': '42ac29f14d5a45318b7d2bc7bd871093', 'REQUEST_URI': '/identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'HTTP_ACCEPT': '*/*', 'openstack.request_id': 'req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0', 'wsgi.version': (1, 0), 'Shib-Application-ID': 'default', 'GATEWAY_INTERFACE': 'CGI/1.1', 'wsgi.run_once': False, 'APACHE_RUN_USER': 'stack', 'wsgi.errors': , 'REMOTE_PORT': '58706', 'werkzeug.proxy_fix.orig_remote_addr': '192.168.122.222', 'REQUEST_SCHEME': 'http', 'uwsgi.node': 'ubuntu', 'Shib-Identity-Provider': 'http://idp.keystone.demo/idp', 'webob.is_body_seekable': False, 'CONTENT_TYPE': 'application/vnd.paos+xml', 'Shib-Session-ID': '_9c3a51ebbfaf6ada7fac371e6165caf0', 'wsgi.file_wrapper': , 'HTTP_ACCEPT_ENCODING': 'gzip, deflate', 'wsgi.input_terminated': True} {{(pid=5668) get_assertion_params_from_env /opt/stack/keystone/keystone/federation/utils.py:419}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG oslo_db.sqlalchemy.engines [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION {{(pid=5668) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:308}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] assertion data: {'AUTH_TYPE': u'shibboleth', 'HTTP_COOKIE': u'_shibsession_64656661756c74687474703a2f2f6d7973702e76697368616b68612e636f6d2f73686962626f6c657468=_9c3a51ebbfaf6ada7fac371e6165caf0', 'Shib-Identity-Provider': u'http://idp.keystone.demo/idp', 'CONTEXT_DOCUMENT_ROOT': u'/opt/stack/horizon/.blackhole/', 'SERVER_SOFTWARE': u'Apache/2.4.18 (Ubuntu)', 'werkzeug.proxy_fix.orig_remote_addr': u'192.168.122.222', 'CONTEXT_PREFIX': u'', 'REQUEST_SCHEME': u'http', 'webob.adhoc_attrs': {'response': <_AuthTokenResponse at 0x7f37e369ec50 200 OK>}, 'SERVER_SIGNATURE': u'
Apache/2.4.18 (Ubuntu) Server at 192.168.122.221 Port 80
\n', 'REQUEST_METHOD': u'GET', 'keystone.oslo_request_context': , 'PATH_INFO': u'/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'SERVER_PROTOCOL': u'HTTP/1.1', 'QUERY_STRING': u'', 'PATH': u'/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin', 'proxy-sendchunked': u'1', 'werkzeug.proxy_fix.orig_wsgi_url_scheme': u'http', 'openstack_user': u'vishakha', 'HTTP_USER_AGENT': u'openstack_auth keystoneauth1/3.11.1 python-requests/2.20.0 CPython/2.7.12', 'HTTP_CONNECTION': u'keep-alive', 'REMOTE_PORT': u'58706', 'SERVER_NAME': u'192.168.122.221', 'REMOTE_ADDR': u'192.168.122.222', 'Shib-AuthnContext-Class': u'urn:oasis:names:tc:SAML:2.0:ac:classes:Password', 'wsgi.url_scheme': u'http', 'Shib-Authentication-Method': u'urn:oasis:names:tc:SAML:2.0:ac:classes:Password', 'APACHE_RUN_GROUP': u'stack', 'SERVER_PORT': u'80', 'werkzeug.proxy_fix.orig_http_host': u'192.168.122.221', 'openstack_user_domain': u'Default', 'openstack_roles': u'reader;member;admin', 'SERVER_ADDR': u'192.168.122.221', 'DOCUMENT_ROOT': u'/opt/stack/horizon/.blackhole/', 'Shib-Authentication-Instant': u'2018-11-08T09:13:26Z', 'werkzeug.request': , 'SCRIPT_FILENAME': u'proxy:uwsgi://uwsgi-uds-keystone-wsgi-public//v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'openstack_project_domain': u'Default', 'SERVER_ADMIN': u'[no address given]', 'wsgi.input': , 'REMOTE_USER': u'', 'HTTP_HOST': u'192.168.122.221', 'SCRIPT_NAME': u'/identity', 'wsgi.multithread': False, 'Shib-Session-Index': u'42ac29f14d5a45318b7d2bc7bd871093', 'REQUEST_URI': u'/identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'HTTP_ACCEPT': u'*/*', 'openstack.request_id': u'req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0', 'wsgi.version': (1, 0), 'Shib-Application-ID': u'default', 'GATEWAY_INTERFACE': u'CGI/1.1', 'uwsgi.version': u'2.0.17.1', 'APACHE_RUN_USER': u'stack', 'wsgi.errors': , 'wsgi.multiprocess': True, 'keystone.token_auth': , 'uwsgi.node': u'ubuntu', 'wsgi.run_once': False, 'openstack_project': u'admin', 'webob.is_body_seekable': False, 'CONTENT_TYPE': u'application/vnd.paos+xml', 'Shib-Session-ID': u'_9c3a51ebbfaf6ada7fac371e6165caf0', 'wsgi.file_wrapper': , 'HTTP_ACCEPT_ENCODING': u'gzip, deflate', 'wsgi.input_terminated': True} {{(pid=5668) process /opt/stack/keystone/keystone/federation/utils.py:514}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] assertion: {'AUTH_TYPE': [u'shibboleth'], 'HTTP_COOKIE': [u'_shibsession_64656661756c74687474703a2f2f6d7973702e76697368616b68612e636f6d2f73686962626f6c657468=_9c3a51ebbfaf6ada7fac371e6165caf0'], 'CONTEXT_DOCUMENT_ROOT': [u'/opt/stack/horizon/.blackhole/'], 'SERVER_SOFTWARE': [u'Apache/2.4.18 (Ubuntu)'], 'CONTEXT_PREFIX': [u''], 'SERVER_SIGNATURE': [u'
Apache/2.4.18 (Ubuntu) Server at 192.168.122.221 Port 80
\n'], 'REQUEST_METHOD': [u'GET'], 'PATH_INFO': [u'/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth'], 'SERVER_PROTOCOL': [u'HTTP/1.1'], 'QUERY_STRING': [u''], 'PATH': [u'/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin'], 'proxy-sendchunked': [u'1'], 'werkzeug.proxy_fix.orig_wsgi_url_scheme': [u'http'], 'openstack_user': [u'vishakha'], 'werkzeug.proxy_fix.orig_remote_addr': [u'192.168.122.222'], 'HTTP_CONNECTION': [u'keep-alive'], 'SERVER_NAME': [u'192.168.122.221'], 'REMOTE_PORT': [u'58706'], 'Shib-AuthnContext-Class': [u'urn:oasis:names:tc:SAML:2.0:ac:classes:Password'], 'wsgi.url_scheme': [u'http'], 'Shib-Authentication-Method': [u'urn:oasis:names:tc:SAML:2.0:ac:classes:Password'], 'APACHE_RUN_GROUP': [u'stack'], 'REMOTE_USER': [u''], 'SERVER_PORT': [u'80'], 'werkzeug.proxy_fix.orig_http_host': [u'192.168.122.221'], 'openstack_user_domain': [u'Default'], 'openstack_roles': [u'reader', u'member', u'admin'], 'SERVER_ADDR': [u'192.168.122.221'], 'DOCUMENT_ROOT': [u'/opt/stack/horizon/.blackhole/'], 'Shib-Authentication-Instant': [u'2018-11-08T09:13:26Z'], 'SCRIPT_FILENAME': [u'proxy:uwsgi://uwsgi-uds-keystone-wsgi-public//v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth'], 'openstack_project_domain': [u'Default'], 'SERVER_ADMIN': [u'[no address given]'], 'HTTP_USER_AGENT': [u'openstack_auth keystoneauth1/3.11.1 python-requests/2.20.0 CPython/2.7.12'], 'HTTP_HOST': [u'192.168.122.221'], 'SCRIPT_NAME': [u'/i Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: dentity'], 'Shib-Session-Index': [u'42ac29f14d5a45318b7d2bc7bd871093'], 'REQUEST_URI': [u'/identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth'], 'HTTP_ACCEPT': [u'*/*'], 'openstack.request_id': [u'req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0'], 'Shib-Application-ID': [u'default'], 'GATEWAY_INTERFACE': [u'CGI/1.1'], 'uwsgi.version': [u'2.0.17.1'], 'APACHE_RUN_USER': [u'stack'], 'REMOTE_ADDR': [u'192.168.122.222'], 'REQUEST_SCHEME': [u'http'], 'uwsgi.node': [u'ubuntu'], 'Shib-Identity-Provider': [u'http://idp.keystone.demo/idp'], 'openstack_project': [u'admin'], 'CONTENT_TYPE': [u'application/vnd.paos+xml'], 'Shib-Session-ID': [u'_9c3a51ebbfaf6ada7fac371e6165caf0'], 'HTTP_ACCEPT_ENCODING': [u'gzip, deflate']} {{(pid=5668) process /opt/stack/keystone/keystone/federation/utils.py:517}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] rules: [{u'remote': [{u'type': u'openstack_user'}], u'local': [{u'group': {u'domain': {u'name': u'Default'}, u'name': u'federated_users'}, u'user': {u'name': u'{0}'}}]}] {{(pid=5668) process /opt/stack/keystone/keystone/federation/utils.py:520}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] updating a direct mapping: [u'vishakha'] {{(pid=5668) _verify_all_requirements /opt/stack/keystone/keystone/federation/utils.py:821}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] direct_maps: {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] local: {u'group': {u'domain': {u'name': u'Default'}, u'name': u'federated_users'}, u'user': {u'name': u'{0}'}} {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] direct_maps: {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] local: {u'domain': {u'name': u'Default'}, u'name': u'federated_users'} {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] direct_maps: {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] local: {u'name': u'Default'} {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] direct_maps: {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] local: {u'name': u'{0}'} {{(pid=5668) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] identity_values: [{u'group': {u'domain': {u'name': u'Default'}, u'name': u'federated_users'}, u'user': {u'name': u'vishakha'}}] {{(pid=5668) process /opt/stack/keystone/keystone/federation/utils.py:540}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] mapped_properties: {'group_ids': [], 'user': {'domain': {'id': 'Federated'}, 'type': 'ephemeral', u'name': u'vishakha'}, 'projects': [], 'group_names': [{u'domain': {u'name': u'Default'}, u'name': u'federated_users'}]} {{(pid=5668) process /opt/stack/keystone/keystone/federation/utils.py:542}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.auth.core [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] MFA Rules not processed for user `059a9875df6a44a1a7715953ed332d23`. Rule list: `[]` (Enabled: `True`). {{(pid=5668) check_auth_methods_against_rules /opt/stack/keystone/keystone/auth/core.py:446}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.fernet_utils [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] Loaded 2 Fernet keys from /etc/keystone/fernet-keys/, but `[fernet_tokens] max_active_keys = 3`; perhaps there have not been enough key rotations to reach `max_active_keys` yet? {{(pid=5668) load_keys /opt/stack/keystone/keystone/common/fernet_utils.py:307}} Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: [pid: 5668|app: 0|req: 1/1] 192.168.122.222 () {90 vars in 1980 bytes} [Thu Nov 8 14:43:27 2018] GET /identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth => generated 435 bytes in 731 msecs (HTTP/1.1 201) 6 headers in 405 bytes (1 switches on core 0) Nov 08 14:43:27 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [-] Authenticating user token {{(pid=5669) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG oslo_db.sqlalchemy.engines [None req-3a1fa2bb-843e-45f3-944d-6c872a703226 None None] MySQL server mode set to STRICT_TRANS_TABLES,STRICT_ALL_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,TRADITIONAL,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION {{(pid=5669) _check_effective_sql_mode /usr/local/lib/python2.7/dist-packages/oslo_db/sqlalchemy/engines.py:308}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-6e09beb5-22fb-415e-91c4-9861df97e68d None vishakha] RBAC: auth_context: {'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'trustor_id': None, 'user_domain_id': 'Federated', 'domain_id': None, 'trust_id': None, 'project_domain_id': None, 'service_roles': [], 'group_ids': [u'6ee4d242429e4199b66aec9300fae2a6'], 'user_id': u'059a9875df6a44a1a7715953ed332d23', 'roles': [], 'system_scope': None, 'trustee_id': None, 'domain_name': None, 'is_admin_project': True, 'token': , 'project_id': None} {{(pid=5669) fill_context /opt/stack/keystone/keystone/middleware/auth.py:249}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-6e09beb5-22fb-415e-91c4-9861df97e68d None vishakha] REQUEST_METHOD: `POST` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-6e09beb5-22fb-415e-91c4-9861df97e68d None vishakha] SCRIPT_NAME: `/identity` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-6e09beb5-22fb-415e-91c4-9861df97e68d None vishakha] PATH_INFO: `/v3/auth/tokens` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.auth.core [None req-6e09beb5-22fb-415e-91c4-9861df97e68d None vishakha] MFA Rules not processed for user `059a9875df6a44a1a7715953ed332d23`. Rule list: `[]` (Enabled: `True`). {{(pid=5669) check_auth_methods_against_rules /opt/stack/keystone/keystone/auth/core.py:446}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.fernet_utils [None req-6e09beb5-22fb-415e-91c4-9861df97e68d None vishakha] Loaded 2 Fernet keys from /etc/keystone/fernet-keys/, but `[fernet_tokens] max_active_keys = 3`; perhaps there have not been enough key rotations to reach `max_active_keys` yet? {{(pid=5669) load_keys /opt/stack/keystone/keystone/common/fernet_utils.py:307}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: [pid: 5669|app: 0|req: 1/2] 192.168.122.222 () {64 vars in 1337 bytes} [Thu Nov 8 14:43:27 2018] POST /identity/v3/auth/tokens => generated 444 bytes in 707 msecs (HTTP/1.1 201) 6 headers in 405 bytes (1 switches on core 0) Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-bb5d23ac-82b8-4d9e-94bc-a9f2876687f0 None None] Authenticating user token {{(pid=5668) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] RBAC: auth_context: {'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'trustor_id': None, 'user_domain_id': 'Federated', 'domain_id': None, 'trust_id': None, 'project_domain_id': None, 'service_roles': [], 'group_ids': [u'6ee4d242429e4199b66aec9300fae2a6'], 'user_id': u'059a9875df6a44a1a7715953ed332d23', 'roles': [], 'system_scope': None, 'trustee_id': None, 'domain_name': None, 'is_admin_project': True, 'token': , 'project_id': None} {{(pid=5668) fill_context /opt/stack/keystone/keystone/middleware/auth.py:249}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] REQUEST_METHOD: `GET` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] SCRIPT_NAME: `/identity` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] PATH_INFO: `/v3/auth/domains` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] RBAC: Authorizing `identity:get_auth_domains()` {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:402}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] RBAC: Policy Enforcement Cred Data `identity:get_auth_domains creds(service_project_id=None, service_user_id=None, service_user_domain_id=None, service_project_domain_id=None, trustor_id=None, user_domain_id=Federated, domain_id=None, trust_id=None, project_domain_id=None, service_roles=[], group_ids=[u'6ee4d242429e4199b66aec9300fae2a6'], user_id=059a9875df6a44a1a7715953ed332d23, roles=[], system_scope=None, trustee_id=None, domain_name=None, is_admin_project=True, token=*** (audit_id=-LaLkSnnTfG15YTlYSO2Mw, audit_chain_id=[u'-LaLkSnnTfG15YTlYSO2Mw']) at 0x7f37e3483690>, project_id=None)` {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:410}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] RBAC: Policy Enforcement Target Data `identity:get_auth_domains => target()` {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:418}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG oslo_policy.policy [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] The policy file policy.json could not be found. {{(pid=5668) load_rules /usr/local/lib/python2.7/dist-packages/oslo_policy/policy.py:559}} Nov 08 14:43:28 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] RBAC: Authorization granted {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:424}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: [pid: 5668|app: 0|req: 2/3] 192.168.122.222 () {60 vars in 1234 bytes} [Thu Nov 8 14:43:28 2018] GET /identity/v3/auth/domains => generated 322 bytes in 380 msecs (HTTP/1.1 200) 5 headers in 177 bytes (1 switches on core 0) Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-6e09beb5-22fb-415e-91c4-9861df97e68d None vishakha] Authenticating user token {{(pid=5669) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-a8d0f295-2847-4d7e-85eb-009da6f6471c None vishakha] RBAC: auth_context: {'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'trustor_id': None, 'user_domain_id': 'Federated', 'domain_id': None, 'trust_id': None, 'project_domain_id': None, 'service_roles': [], 'group_ids': [u'6ee4d242429e4199b66aec9300fae2a6'], 'user_id': u'059a9875df6a44a1a7715953ed332d23', 'roles': [], 'system_scope': None, 'trustee_id': None, 'domain_name': None, 'is_admin_project': True, 'token': , 'project_id': None} {{(pid=5669) fill_context /opt/stack/keystone/keystone/middleware/auth.py:249}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-a8d0f295-2847-4d7e-85eb-009da6f6471c None vishakha] REQUEST_METHOD: `POST` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-a8d0f295-2847-4d7e-85eb-009da6f6471c None vishakha] SCRIPT_NAME: `/identity` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-a8d0f295-2847-4d7e-85eb-009da6f6471c None vishakha] PATH_INFO: `/v3/auth/tokens` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.auth.core [None req-a8d0f295-2847-4d7e-85eb-009da6f6471c None vishakha] MFA Rules not processed for user `059a9875df6a44a1a7715953ed332d23`. Rule list: `[]` (Enabled: `True`). {{(pid=5669) check_auth_methods_against_rules /opt/stack/keystone/keystone/auth/core.py:446}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.fernet_utils [None req-a8d0f295-2847-4d7e-85eb-009da6f6471c None vishakha] Loaded 2 Fernet keys from /etc/keystone/fernet-keys/, but `[fernet_tokens] max_active_keys = 3`; perhaps there have not been enough key rotations to reach `max_active_keys` yet? {{(pid=5669) load_keys /opt/stack/keystone/keystone/common/fernet_utils.py:307}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: [pid: 5669|app: 0|req: 2/4] 192.168.122.222 () {64 vars in 1337 bytes} [Thu Nov 8 14:43:29 2018] POST /identity/v3/auth/tokens => generated 2763 bytes in 569 msecs (HTTP/1.1 201) 6 headers in 428 bytes (1 switches on core 0) Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-440ef3b4-cc5b-4102-a323-83b5b6841e10 None vishakha] Authenticating user token {{(pid=5668) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] RBAC: auth_context: {'service_project_id': None, 'service_user_id': None, 'service_user_domain_id': None, 'service_project_domain_id': None, 'trustor_id': None, 'user_domain_id': 'Federated', 'domain_id': None, 'trust_id': None, 'project_domain_id': None, 'service_roles': [], 'group_ids': [u'6ee4d242429e4199b66aec9300fae2a6'], 'user_id': u'059a9875df6a44a1a7715953ed332d23', 'roles': [], 'system_scope': None, 'trustee_id': None, 'domain_name': None, 'is_admin_project': True, 'token': , 'project_id': None} {{(pid=5668) fill_context /opt/stack/keystone/keystone/middleware/auth.py:249}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] REQUEST_METHOD: `GET` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] SCRIPT_NAME: `/identity` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] PATH_INFO: `/v3/auth/projects` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] RBAC: Authorizing `identity:get_auth_projects()` {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:402}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] RBAC: Policy Enforcement Cred Data `identity:get_auth_projects creds(service_project_id=None, service_user_id=None, service_user_domain_id=None, service_project_domain_id=None, trustor_id=None, user_domain_id=Federated, domain_id=None, trust_id=None, project_domain_id=None, service_roles=[], group_ids=[u'6ee4d242429e4199b66aec9300fae2a6'], user_id=059a9875df6a44a1a7715953ed332d23, roles=[], system_scope=None, trustee_id=None, domain_name=None, is_admin_project=True, token=*** (audit_id=-LaLkSnnTfG15YTlYSO2Mw, audit_chain_id=[u'-LaLkSnnTfG15YTlYSO2Mw']) at 0x7f37e34647d0>, project_id=None)` {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:410}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] RBAC: Policy Enforcement Target Data `identity:get_auth_projects => target()` {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:418}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-b91ae56f-70b0-4fdd-ba25-84023c6e06ad None vishakha] RBAC: Authorization granted {{(pid=5668) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:424}} Nov 08 14:43:29 ubuntu devstack@keystone.service[5663]: [pid: 5668|app: 0|req: 3/5] 192.168.122.222 () {60 vars in 1237 bytes} [Thu Nov 8 14:43:29 2018] GET /identity/v3/auth/projects => generated 114 bytes in 247 msecs (HTTP/1.1 200) 5 headers in 177 bytes (1 switches on core 0) ^C