Bug 1473713

Summary:	Token flush does not complete when expired tokens becomes large enough
Product:	Red Hat OpenStack	Reporter:	Harry Rybacki <hrybacki>
Component:	openstack-keystone	Assignee:	John Dennis <jdennis>
Status:	CLOSED CURRENTRELEASE	QA Contact:	Prasanth Anbalagan <panbalag>
Severity:	high	Docs Contact:
Priority:	urgent
Version:	10.0 (Newton)	CC:	akrzos, cshastri, dhill, dshevrin, jdennis, jjoyce, josorior, jraju, jschluet, kbasil, lmiccini, mlopes, nchandek, nkinder, panbalag, rcritten, rlondhe, rmascena, slinaber, srevivo, tvignaud, vcojot
Target Milestone:	z2	Keywords:	Reopened, Triaged, ZStream
Target Release:	11.0 (Ocata)
Hardware:	x86_64
OS:	Linux
Whiteboard:
Fixed In Version:	openstack-keystone-11.0.3-1.el7ost	Doc Type:	If docs needed, set a value
Doc Text:		Story Points:	---
Clone Of:	1404324	Environment:
Last Closed:	2018-04-17 12:07:11 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:
Bug Depends On:	1404324, 1476762
Bug Blocks:	1451122, 1467120, 1469457, 1470221, 1470226, 1470227, 1470230

Comment 4 Prasanth Anbalagan 2017-08-30 17:54:35 UTC

Token database does not get flushed due to https://bugzilla.redhat.com/show_bug.cgi?id=1476762. Logs below show that token database keeps growing and is not flushed even though the expires time has passed by. jjoyce, please let me know if you will be able to provide a rebuild with the fix for the above bug.

***************
VERSION
***************

[heat-admin@controller-0 ~]$ yum list installed | grep openstack-keystone
openstack-keystone.noarch          1:11.0.3-1.el7ost   @rhos-11.0-signed        

***********
LOGS
***********

[heat-admin@controller-0 ~]$ sudo crontab -u keystone -l
# HEADER: This file was autogenerated at 2017-08-29 13:56:23 +0000 by puppet.
# HEADER: While it can still be managed manually, it is definitely not recommended.
# HEADER: Note particularly that the comments starting with 'Puppet Name' should
# HEADER: not be deleted, as doing so could cause duplicate cron jobs.
# Puppet Name: keystone-manage token_flush
PATH=/bin:/usr/bin:/usr/sbin SHELL=/bin/sh
1 * * * * sleep `expr ${RANDOM} \% 0`; keystone-manage token_flush >>/var/log/keystone/keystone-tokenflush.log 2>&1
# Puppet Name: cinder-manage db purge
PATH=/bin:/usr/bin:/usr/sbin SHELL=/bin/sh
1 0 * * * cinder-manage db purge 0 >>/var/log/cinder/cinder-rowsflush.log 2>&1


MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|      272 |
+----------+
1 row in set (0.00 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|      273 |
+----------+
1 row in set (0.00 sec)
..
...
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|      625 |
+----------+
1 row in set (0.00 sec)
..

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     1149 |
+----------+
1 row in set (0.00 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     1152 |
+----------+
1 row in set (0.00 sec)

..
...
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     3058 |
+----------+
1 row in set (0.00 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     3061 |
+----------+
1 row in set (0.00 sec)
..
...
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     3776 |
+----------+
1 row in set (0.00 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     3927 |
+----------+
1 row in set (0.00 sec)
..
...
....
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     6437 |
+----------+
1 row in set (0.00 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     6442 |
+----------+
1 row in set (0.00 sec)

..
...
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     7686 |
+----------+
1 row in set (0.00 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     7688 |
+----------+
1 row in set (0.00 sec)
..
..
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     8766 |
+----------+
1 row in set (0.01 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|     8768 |
+----------+
1 row in set (0.00 sec)
..
...
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|    10886 |
+----------+
1 row in set (0.00 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|    10893 |
+----------+
1 row in set (0.01 sec)
..
..
MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|    11045 |
+----------+
1 row in set (0.01 sec)

MariaDB [keystone]> select count(*) from token;
+----------+
| count(*) |
+----------+
|    11398 |
+----------+
1 row in set (0.01 sec)

*********************
SYSTEM TIME
*********************

[heat-admin@controller-0 ~]$ date
Wed Aug 30 17:31:59 UTC 2017

*******************
TOKEN INFORMATION
*******************

MariaDB [keystone]> select expires from token;
+---------------------+
| expires             |
+---------------------+
| 2017-08-29 14:48:50 |
| 2017-08-29 14:53:58 |
| 2017-08-29 14:54:00 |
| 2017-08-29 14:54:11 |
| 2017-08-29 14:54:21 |
| 2017-08-29 14:54:31 |
| 2017-08-29 14:54:42 |
| 2017-08-29 14:54:52 |
| 2017-08-29 14:55:17 |
| 2017-08-29 14:55:17 |
| 2017-08-29 14:55:18 |
| 2017-08-29 14:55:19 |
| 2017-08-29 14:55:21 |
| 2017-08-29 14:55:21 |
| 2017-08-29 14:55:22 |
| 2017-08-29 14:55:23 |
| 2017-08-29 14:56:20 |
| 2017-08-29 14:58:50 |
| 2017-08-29 14:58:50 |
| 2017-08-29 14:58:51 |
| 2017-08-29 14:58:51 |
| 2017-08-29 14:58:51 |
| 2017-08-29 14:58:51 |
| 2017-08-29 14:59:02 |
| 2017-08-29 14:59:03 |
| 2017-08-29 14:59:03 |
| 2017-08-29 14:59:03 |
| 2017-08-29 14:59:05 |
| 2017-08-29 14:59:05 |
| 2017-08-29 14:59:07 |
| 2017-08-29 14:59:07 |
| 2017-08-29 14:59:07 |
| 2017-08-29 15:00:40 |
| 2017-08-29 15:02:37 |
| 2017-08-29 15:02:37 |
| 2017-08-29 15:02:42 |
| 2017-08-29 15:02:42 |
| 2017-08-29 15:02:44 |
| 2017-08-29 15:02:44 |
| 2017-08-29 15:02:45 |
| 2017-08-29 15:02:47 |
| 2017-08-29 15:02:56 |
| 2017-08-29 15:13:58 |
| 2017-08-29 15:13:58 |
| 2017-08-29 15:53:37 |
| 2017-08-29 15:53:58 |
| 2017-08-29 15:55:07 |
| 2017-08-29 15:58:45 |
| 2017-08-29 15:58:53 |
| 2017-08-29 15:59:08 |
| 2017-08-29 16:13:58 |
| 2017-08-29 16:13:58 |
| 2017-08-29 16:23:13 |
| 2017-08-29 16:23:14 |
| 2017-08-29 16:23:15 |
| 2017-08-29 16:23:35 |
| 2017-08-29 16:23:35 |
| 2017-08-29 16:23:58 |
| 2017-08-29 16:52:34 |
| 2017-08-29 16:55:37 |
| 2017-08-29 16:57:37 |
| 2017-08-29 16:59:38 |
| 2017-08-29 17:00:52 |
| 2017-08-29 17:03:58 |
| 2017-08-29 17:13:58 |
| 2017-08-29 17:13:58 |
| 2017-08-29 17:23:58 |
| 2017-08-29 17:51:30 |
| 2017-08-29 17:54:51 |
| 2017-08-29 17:56:36 |
| 2017-08-29 18:00:08 |
| 2017-08-29 18:02:52 |
| 2017-08-29 18:03:58 |
| 2017-08-29 18:13:58 |
| 2017-08-29 18:13:58 |
| 2017-08-29 18:23:58 |
..
...
....

Comment 6 Prasanth Anbalagan 2017-08-31 19:07:27 UTC

Verified as follows - token database gets flused as expected.

Note that the parameter "allow_expired_window" needs to be configured in /etc/keystone/keystone.conf (starting from OSP11 onwards) in order for the hourly cron job to flush tokens.

***********
LOGS
***********

[heat-admin@controller-0 ~]$ sudo crontab -u keystone -l
# HEADER: This file was autogenerated at 2017-08-31 13:54:59 +0000 by puppet.
# HEADER: While it can still be managed manually, it is definitely not recommended.
# HEADER: Note particularly that the comments starting with 'Puppet Name' should
# HEADER: not be deleted, as doing so could cause duplicate cron jobs.
# Puppet Name: keystone-manage token_flush
PATH=/bin:/usr/bin:/usr/sbin SHELL=/bin/sh
1 * * * * keystone-manage token_flush >>/var/log/keystone/keystone-tokenflush.log 2>&1
# Puppet Name: cinder-manage db purge
PATH=/bin:/usr/bin:/usr/sbin SHELL=/bin/sh
1 0 * * * cinder-manage db purge 0 >>/var/log/cinder/cinder-rowsflush.log 2>&1


***********************************
Thu Aug 31 15:50:56 UTC 2017
***********************************
[heat-admin@controller-0 ~]$ date
Thu Aug 31 15:50:56 UTC 2017

[heat-admin@controller-0 ~]$ sudo mysql
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 8806
Server version: 5.5.42-MariaDB-wsrep MariaDB Server, wsrep_25.11.r4026

Copyright (c) 2000, 2017, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> use keystone; select count(*) from token;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
+----------+
| count(*) |
+----------+
|    10408 |
+----------+
1 row in set (0.01 sec)

[heat-admin@controller-0 ~]$ date
Thu Aug 31 19:04:59 UTC 2017
[heat-admin@controller-0 ~]$ 


MariaDB [keystone]> use keystone; select count(*) from token;
Database changed
+----------+
| count(*) |
+----------+
|       10 |
+----------+
1 row in set (0.00 sec)

Comment 7 Prasanth Anbalagan 2017-08-31 19:07:47 UTC

Verified as follows - token database gets flushed as expected.

Note that the parameter "allow_expired_window" needs to be configured in /etc/keystone/keystone.conf (starting from OSP11 onwards) in order for the hourly cron job to flush tokens.

***********
LOGS
***********

[heat-admin@controller-0 ~]$ sudo crontab -u keystone -l
# HEADER: This file was autogenerated at 2017-08-31 13:54:59 +0000 by puppet.
# HEADER: While it can still be managed manually, it is definitely not recommended.
# HEADER: Note particularly that the comments starting with 'Puppet Name' should
# HEADER: not be deleted, as doing so could cause duplicate cron jobs.
# Puppet Name: keystone-manage token_flush
PATH=/bin:/usr/bin:/usr/sbin SHELL=/bin/sh
1 * * * * keystone-manage token_flush >>/var/log/keystone/keystone-tokenflush.log 2>&1
# Puppet Name: cinder-manage db purge
PATH=/bin:/usr/bin:/usr/sbin SHELL=/bin/sh
1 0 * * * cinder-manage db purge 0 >>/var/log/cinder/cinder-rowsflush.log 2>&1


***********************************
Thu Aug 31 15:50:56 UTC 2017
***********************************
[heat-admin@controller-0 ~]$ date
Thu Aug 31 15:50:56 UTC 2017

[heat-admin@controller-0 ~]$ sudo mysql
Welcome to the MariaDB monitor.  Commands end with ; or \g.
Your MariaDB connection id is 8806
Server version: 5.5.42-MariaDB-wsrep MariaDB Server, wsrep_25.11.r4026

Copyright (c) 2000, 2017, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> use keystone; select count(*) from token;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Database changed
+----------+
| count(*) |
+----------+
|    10408 |
+----------+
1 row in set (0.01 sec)

[heat-admin@controller-0 ~]$ date
Thu Aug 31 19:04:59 UTC 2017
[heat-admin@controller-0 ~]$ 


MariaDB [keystone]> use keystone; select count(*) from token;
Database changed
+----------+
| count(*) |
+----------+
|       10 |
+----------+
1 row in set (0.00 sec)

Comment 9 errata-xmlrpc 2017-09-13 21:49:48 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:2719

Comment 11 Raildo Mascena de Sousa Filho 2017-09-26 13:25:26 UTC

Hi Rohit, 

So, we made the backport (and not a workaround) for that issue in the OSP10 and we verified that the patch had, in fact, made it into the respective build. So, can you give to us more details on how this issue still happing? Do you know if they follow properly the steps described by the QE here: https://bugzilla.redhat.com/show_bug.cgi?id=1473713#c7

Comment 12 Raildo Mascena de Sousa Filho 2017-10-23 15:16:46 UTC

Hi Rohit, Did you had time to take a look in my previous response about that?

Comment 14 Raildo Mascena de Sousa Filho 2018-04-16 16:19:07 UTC

Hi Rohit, 

Sorry for be asking you about that again, but do you have any updates from Cu about this BZ?

Comment 16 Raildo Mascena de Sousa Filho 2018-04-17 12:07:11 UTC

Hi Rohit,

So based on our previous comments and also in the lack of response from Customer, I'm closing this bug as CURRENTRELEASE since in point of view it was already fixed from this release. If the Customer believes that the issue still exists, feel free to reopen it.