all POST to /v3/auth/tokens are delayed (25 seconds)

asked 2020-05-01 23:22:24 -0500

kit gravatar image

updated 2020-05-02 20:03:51 -0500

Every attempt to access keystone endpoint /v3/auth/tokens is slow, taking 25 seconds every attempt. Any recommendations on debugging would be appreciated.

12 of those 25 seconds takes place here:

2020-05-01 14:21:28.689 1536 DEBUG powervc_keystone.filters.local_filter [req-79b8a9b6-8459-469f-9d9b-550ce9e2d805 - - - - -] Local user filter is : (memberOf=powervc-filter) _get_user_filter /usr/lib/python2.7/site-packages/powervc_keystone/filters/local_filter.py:91 ---------------------- 12 second delay --------------------- 2020-05-01 14:21:40.084 1536 DEBUG keystone.server.flask.request_processing.middleware.auth_context [req-a75cf9de-22f2-4436-a931-b53806a24960 - - - - -] Authenticating user token process_request /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py:401 I would think this is a long delay to go between _get_user_filter and process_request.

   # openstack endpoint list -f csv --timing

"URL","Seconds"
"GET https://site:5000/v3/",0.033619
"POST https://site:5000/v3/auth/tokens",25.817121
"POST https://site:5000/v3/auth/tokens",25.473447
"GET https://site:5000/v3/endpoints",0.060054
"GET https://site:5000/v3/services",0.042752
"Total",51.426993

POST to /auth/tokens takes 25 seconds.

More directly using curl,

    curl -v \
     -k \
     -i \
  -H "Content-Type: application/json" \
  -d '
{ "auth": {
    "identity": {
      "methods": ["password"],
      "password": {
        "user": {
          "name": "un",
          "domain": { "id": "default" },
          "password": "pw"
        }
      }
    },
    "scope": {
      "project": {
        "name": "project_name",
        "domain": { "id": "default" }
      }
    }
  }
}' \
  "https://site:5000/v3/auth/tokens" ; echo

* About to connect() to site.com port 5000 (#0)
*   Trying 0.0.0.0...
* Connected to site (0.0.0.0) port 5000 (#0)
* Initializing NSS with certpath: sql:/etc/pki/nssdb
* skipping SSL peer certificate verification
* SSL connection using TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
* Server certificate:
*       subject: CN=site
*       start date: Feb 17 21:46:52 2020 GMT
*       expire date: Feb 16 21:46:52 2030 GMT
*       common name: site
*       issuer: CN=site
> POST /v3/auth/tokens HTTP/1.1
> User-Agent: curl/7.29.0
> Host: site:5000
> Accept: */*
> Content-Type: application/json
> Content-Length: 347
>
* upload completely sent off: 347 out of 347 bytes
--------------------------------- 25 second delay here -----------------------
< HTTP/1.1 201 CREATED
HTTP/1.1 201 CREATED
< Date: Sat, 02 May 2020 04:14:46 GMT
Date: Sat, 02 May 2020 04:14:46 GMT
< Server: Apache
Server: Apache
< X-Subject-Token: token
X-Subject-Token: token
< Vary: X-Auth-Token,User-Agent
Vary: X-Auth-Token,User-Agent
< x-openstack-request-id: req
x-openstack-request-id: req
< Content-Length: 8359
Content-Length: 8359
< Content-Type: application/json
Content-Type: application/json
edit retag flag offensive close merge delete

Comments

That's a bit long. Perhaps you find answers in the Keystone log file.

Bernd Bausch gravatar imageBernd Bausch ( 2020-05-02 00:48:38 -0500 )edit