Bug 1473713 - Token flush does not complete when expired tokens becomes large enough
Summary: Token flush does not complete when expired tokens becomes large enough
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat OpenStack
Classification: Red Hat
Component: openstack-keystone
Version: 10.0 (Newton)
Hardware: x86_64
OS: Linux
urgent
high
Target Milestone: z2
: 11.0 (Ocata)
Assignee: John Dennis
QA Contact: Prasanth Anbalagan
URL:
Whiteboard:
Depends On: 1404324 1476762
Blocks: 1451122 1467120 1469457 1470221 1470226 1470227 1470230
TreeView+ depends on / blocked
 
Reported: 2017-07-21 13:34 UTC by Harry Rybacki
Modified: 2021-09-09 12:27 UTC (History)
22 users (show)

Fixed In Version: openstack-keystone-11.0.3-1.el7ost
Doc Type: If docs needed, set a value
Doc Text:
Clone Of: 1404324
Environment:
Last Closed: 2018-04-17 12:07:11 UTC
Target Upstream Version:
Embargoed:


Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Launchpad 1649616 0 None None None 2017-07-21 13:34:33 UTC
Red Hat Product Errata RHBA-2017:2719 0 normal SHIPPED_LIVE openstack-keystone bug fix advisory 2017-09-14 01:48:32 UTC

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.


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