# Pastebin T48F4gLb Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] REQUEST_METHOD: `GET` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] SCRIPT_NAME: `/identity` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] PATH_INFO: `/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] Environment variables: {'AUTH_TYPE': 'shibboleth', 'wsgi.multiprocess': True, 'HTTP_COOKIE': '_shibsession_64656661756c74687474703a2f2f6d7973702e76697368616b68612e636f6d2f73686962626f6c657468=_be86b8beae84108212a11837336bf92b', '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 0x7f37e369e4d0 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': '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:39:41Z', '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': 'b221de05f4624923a5512c9f437fccb2', 'REQUEST_URI': '/identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'HTTP_ACCEPT': '*/*', 'openstack.request_id': 'req-f489f6ef-cd53-40bc-b641-5d7e8b201142', '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': '59218', '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': '_be86b8beae84108212a11837336bf92b', 'wsgi.file_wrapper': , 'HTTP_ACCEPT_ENCODING': 'gzip, deflate', 'wsgi.input_terminated': True} {{(pid=5669) get_assertion_params_from_env /opt/stack/keystone/keystone/federation/utils.py:419}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] assertion data: {'AUTH_TYPE': u'shibboleth', 'HTTP_COOKIE': u'_shibsession_64656661756c74687474703a2f2f6d7973702e76697368616b68612e636f6d2f73686962626f6c657468=_be86b8beae84108212a11837336bf92b', '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 0x7f37e369e4d0 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'keystoneauth1/3.11.1 python-requests/2.20.0 CPython/2.7.12', 'HTTP_CONNECTION': u'keep-alive', 'REMOTE_PORT': u'59218', '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:39:41Z', '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'b221de05f4624923a5512c9f437fccb2', 'REQUEST_URI': u'/identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth', 'HTTP_ACCEPT': u'*/*', 'openstack.request_id': u'req-f489f6ef-cd53-40bc-b641-5d7e8b201142', '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'_be86b8beae84108212a11837336bf92b', 'wsgi.file_wrapper': , 'HTTP_ACCEPT_ENCODING': u'gzip, deflate', 'wsgi.input_terminated': True} {{(pid=5669) process /opt/stack/keystone/keystone/federation/utils.py:514}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] assertion: {'AUTH_TYPE': [u'shibboleth'], 'HTTP_COOKIE': [u'_shibsession_64656661756c74687474703a2f2f6d7973702e76697368616b68612e636f6d2f73686962626f6c657468=_be86b8beae84108212a11837336bf92b'], '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'59218'], '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:39:41Z'], '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'keystoneauth1/3.11.1 python-requests/2.20.0 CPython/2.7.12'], 'HTTP_HOST': [u'192.168.122.221'], 'SCRIPT_NAME': [u'/identity'], 'Shi Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: b-Session-Index': [u'b221de05f4624923a5512c9f437fccb2'], 'REQUEST_URI': [u'/identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth'], 'HTTP_ACCEPT': [u'*/*'], 'openstack.request_id': [u'req-f489f6ef-cd53-40bc-b641-5d7e8b201142'], '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'_be86b8beae84108212a11837336bf92b'], 'HTTP_ACCEPT_ENCODING': [u'gzip, deflate']} {{(pid=5669) process /opt/stack/keystone/keystone/federation/utils.py:517}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 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=5669) process /opt/stack/keystone/keystone/federation/utils.py:520}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] updating a direct mapping: [u'vishakha'] {{(pid=5669) _verify_all_requirements /opt/stack/keystone/keystone/federation/utils.py:821}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] direct_maps: {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] local: {u'group': {u'domain': {u'name': u'Default'}, u'name': u'federated_users'}, u'user': {u'name': u'{0}'}} {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] direct_maps: {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] local: {u'domain': {u'name': u'Default'}, u'name': u'federated_users'} {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] direct_maps: {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] local: {u'name': u'Default'} {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] direct_maps: {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:703}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] local: {u'name': u'{0}'} {{(pid=5669) _update_local_mapping /opt/stack/keystone/keystone/federation/utils.py:704}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] identity_values: [{u'group': {u'domain': {u'name': u'Default'}, u'name': u'federated_users'}, u'user': {u'name': u'vishakha'}}] {{(pid=5669) process /opt/stack/keystone/keystone/federation/utils.py:540}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.federation.utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 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=5669) process /opt/stack/keystone/keystone/federation/utils.py:542}} Nov 08 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.auth.core [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] 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 15:09:41 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.fernet_utils [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 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=5669) load_keys /opt/stack/keystone/keystone/common/fernet_utils.py:307}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: [pid: 5669|app: 0|req: 7/14] 192.168.122.222 () {90 vars in 1965 bytes} [Thu Nov 8 15:09:41 2018] GET /identity/v3/OS-FEDERATION/identity_providers/keystoneidp/protocols/saml2/auth => generated 435 bytes in 660 msecs (HTTP/1.1 201) 6 headers in 405 bytes (1 switches on core 0) Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-a4f9edab-94c8-4223-a920-6013248cd13b None nova] Authenticating user token {{(pid=5668) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-5a7ad583-6af1-4782-a6a6-17ffb16b1e29 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 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-5a7ad583-6af1-4782-a6a6-17ffb16b1e29 None vishakha] REQUEST_METHOD: `POST` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-5a7ad583-6af1-4782-a6a6-17ffb16b1e29 None vishakha] SCRIPT_NAME: `/identity` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-5a7ad583-6af1-4782-a6a6-17ffb16b1e29 None vishakha] PATH_INFO: `/v3/auth/tokens` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.auth.core [None req-5a7ad583-6af1-4782-a6a6-17ffb16b1e29 None vishakha] 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 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.fernet_utils [None req-5a7ad583-6af1-4782-a6a6-17ffb16b1e29 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=5668) load_keys /opt/stack/keystone/keystone/common/fernet_utils.py:307}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: [pid: 5668|app: 0|req: 8/15] 192.168.122.222 () {64 vars in 1322 bytes} [Thu Nov 8 15:09:42 2018] POST /identity/v3/auth/tokens => generated 444 bytes in 286 msecs (HTTP/1.1 201) 6 headers in 405 bytes (1 switches on core 0) Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-f489f6ef-cd53-40bc-b641-5d7e8b201142 None None] Authenticating user token {{(pid=5669) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 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 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 None vishakha] REQUEST_METHOD: `GET` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 None vishakha] SCRIPT_NAME: `/identity` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 None vishakha] PATH_INFO: `/v3/auth/domains` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 None vishakha] RBAC: Authorizing `identity:get_auth_domains()` {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:402}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 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=rPRXWakQQ9aj2N13kS3U3Q, audit_chain_id=[u'rPRXWakQQ9aj2N13kS3U3Q']) at 0x7f37e3390d50>, project_id=None)` {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:410}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 None vishakha] RBAC: Policy Enforcement Target Data `identity:get_auth_domains => target()` {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:418}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 None vishakha] RBAC: Authorization granted {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:424}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: [pid: 5669|app: 0|req: 8/16] 192.168.122.222 () {60 vars in 1234 bytes} [Thu Nov 8 15:09:42 2018] GET /identity/v3/auth/domains => generated 322 bytes in 505 msecs (HTTP/1.1 200) 5 headers in 177 bytes (1 switches on core 0) Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-5a7ad583-6af1-4782-a6a6-17ffb16b1e29 None vishakha] Authenticating user token {{(pid=5668) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-9d20645f-8ec1-409c-acc3-a17ad621a91f 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 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-9d20645f-8ec1-409c-acc3-a17ad621a91f None vishakha] REQUEST_METHOD: `POST` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-9d20645f-8ec1-409c-acc3-a17ad621a91f None vishakha] SCRIPT_NAME: `/identity` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 15:09:42 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-9d20645f-8ec1-409c-acc3-a17ad621a91f None vishakha] PATH_INFO: `/v3/auth/tokens` {{(pid=5668) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.auth.core [None req-9d20645f-8ec1-409c-acc3-a17ad621a91f None vishakha] 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 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.fernet_utils [None req-9d20645f-8ec1-409c-acc3-a17ad621a91f 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=5668) load_keys /opt/stack/keystone/keystone/common/fernet_utils.py:307}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: [pid: 5668|app: 0|req: 9/17] 192.168.122.222 () {64 vars in 1322 bytes} [Thu Nov 8 15:09:42 2018] POST /identity/v3/auth/tokens => generated 2763 bytes in 696 msecs (HTTP/1.1 201) 6 headers in 428 bytes (1 switches on core 0) Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-755d5a3d-7bc5-4f52-8226-eb997dfe6067 None vishakha] Authenticating user token {{(pid=5669) process_request /usr/local/lib/python2.7/dist-packages/keystonemiddleware/auth_token/__init__.py:401}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.middleware.auth [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 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 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 None vishakha] REQUEST_METHOD: `GET` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:27}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 None vishakha] SCRIPT_NAME: `/identity` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:28}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.server.flask.request_processing.req_logging [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 None vishakha] PATH_INFO: `/v3/auth/projects` {{(pid=5669) log_request_info /opt/stack/keystone/keystone/server/flask/request_processing/req_logging.py:29}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 None vishakha] RBAC: Authorizing `identity:get_auth_projects()` {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:402}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 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=rPRXWakQQ9aj2N13kS3U3Q, audit_chain_id=[u'rPRXWakQQ9aj2N13kS3U3Q']) at 0x7f37e342c6d0>, project_id=None)` {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:410}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 None vishakha] RBAC: Policy Enforcement Target Data `identity:get_auth_projects => target()` {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:418}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: DEBUG keystone.common.rbac_enforcer.enforcer [None req-30f3a33c-f43a-4c61-93f6-64c02bbb7e20 None vishakha] RBAC: Authorization granted {{(pid=5669) enforce_call /opt/stack/keystone/keystone/common/rbac_enforcer/enforcer.py:424}} Nov 08 15:09:43 ubuntu devstack@keystone.service[5663]: [pid: 5669|app: 0|req: 9/18] 192.168.122.222 () {60 vars in 1237 bytes} [Thu Nov 8 15:09:43 2018] GET /identity/v3/auth/projects => generated 114 bytes in 371 msecs (HTTP/1.1 200) 5 headers in 177 bytes (1 switches on core 0) ^C