Bug 1314503

Summary:	[RFE] Token expiry logging level
Product:	Red Hat OpenStack	Reporter:	Andreas Karis <akaris>
Component:	openstack-keystone	Assignee:	John Dennis <jdennis>
Status:	CLOSED ERRATA	QA Contact:	Prasanth Anbalagan <panbalag>
Severity:	low	Docs Contact:
Priority:	medium
Version:	7.0 (Kilo)	CC:	akaris, hrybacki, jdennis, kbasil, nkinder, panbalag, sclewis, srevivo
Target Milestone:	beta	Keywords:	FutureFeature, Reopened, Triaged
Target Release:	13.0 (Queens)
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	openstack-keystone-13.0.1-0.20180228160929.c06d74f.el7ost	Doc Type:	Enhancement
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2018-06-27 13:26:26 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:

Description Andreas Karis 2016-03-03 19:03:29 UTC

Description of problem:
With the new default token timeouts of 3600 seconds, tokens tend to expire fairly often. However, we log token expiry with a log level of WARNING, resulting in a bad signal-to-noise ratio when reading the logs.

Version-Release number of selected component (if applicable):
OSP 7

How reproducible:


Steps to Reproduce:
1. Default installation of OSP 7
2. Verify that verbose is false and that debug is false
3. Let it run for a while and check logs

Actual results:
[root@overcloud-controller-0 ~]# egrep -i 'authorization|token|expir' /var/log/nova/nova-api.log | tail
2016-03-03 00:43:43.001 6440 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 01:33:14.106 6439 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 01:33:14.107 6439 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 24ffb14540c74a7c964f9627fe2af8fb", "code": 404, "title": "Not Found"}}
2016-03-03 01:33:14.107 6439 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 01:53:42.876 6440 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 01:53:42.877 6440 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 20e487a2ae144d07b6c4e5236e0112fd", "code": 404, "title": "Not Found"}}
2016-03-03 01:53:42.877 6440 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:33:14.094 6439 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:33:14.094 6439 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 944d7ffafaf64c26ade111f70dd3c287", "code": 404, "title": "Not Found"}}
2016-03-03 02:33:14.095 6439 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
[root@overcloud-controller-0 ~]# egrep -i 'authorization|token|expir' /var/log/neutron/server.log | tail
2016-03-03 02:03:14.852 6555 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:03:15.426 6556 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:03:15.426 6556 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 0a199522e14744448386c3ad3a55dbcd", "code": 404, "title": "Not Found"}}
2016-03-03 02:03:15.426 6556 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:03:15.857 6555 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:03:15.857 6555 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 364e83dd2f684c92949c50684dcd5a62", "code": 404, "title": "Not Found"}}
2016-03-03 02:03:15.857 6555 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:33:14.385 6556 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-03-03 02:33:14.385 6556 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 8840f8989e50412aa3b9bc3253f7dc97", "code": 404, "title": "Not Found"}}
2016-03-03 02:33:14.386 6556 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
[root@overcloud-controller-0 ~]# egrep -i 'authorization|token|expir' /var/log/keystone/keystone.log | tail
2016-03-03 01:53:15.101 4605 WARNING keystone.common.wsgi [-] Could not find token: 94e68f2aa66d4ad589ba22081ffd9fb4
2016-03-03 01:53:15.352 4605 WARNING keystone.common.wsgi [-] Could not find token: febfd4ff1b1c46bfbe6a8e83b44b929a
2016-03-03 01:53:42.874 4605 WARNING keystone.common.wsgi [-] Could not find token: 20e487a2ae144d07b6c4e5236e0112fd
2016-03-03 02:03:14.564 4606 WARNING keystone.common.wsgi [-] Could not find token: fe118f783d27472fa49a481f0baa8f10
2016-03-03 02:03:14.848 4605 WARNING keystone.common.wsgi [-] Could not find token: 31f5910a4df345208a8eb06dfe1d34ca
2016-03-03 02:03:15.423 4606 WARNING keystone.common.wsgi [-] Could not find token: 0a199522e14744448386c3ad3a55dbcd
2016-03-03 02:03:15.855 4605 WARNING keystone.common.wsgi [-] Could not find token: 364e83dd2f684c92949c50684dcd5a62
2016-03-03 02:23:49.047 4605 WARNING keystone.common.wsgi [-] Could not find token: 41092ab5430e4e5593811aa7f89054e4
2016-03-03 02:33:14.091 4605 WARNING keystone.common.wsgi [-] Could not find token: 944d7ffafaf64c26ade111f70dd3c287
2016-03-03 02:33:14.381 4605 WARNING keystone.common.wsgi [-] Could not find token: 8840f8989e50412aa3b9bc3253f7dc97



Expected results:
either see no expiration message (if verbose is false) or see less of them

Additional info:
Looking at the logs makes you think that something is wrong, whereas OpenStack works perfectly. Might it be a good idea to lower the log level of expired tokens to verbose or debug?

Comment 2 Adam Young 2016-04-15 17:55:57 UTC

I think that we need to leave this as is, as token expiration happening are a sign of a larger problem. Expired tokens should not be in common usage, and if this is coming through, it is often the only indicator that the workflows will not work if the token duration is too short.

What was the use cases that lead to the invalid tokens being used?  Are long running tasks failing, or is it due to something innocuous like Horizon sessions expiring?

Comment 3 Adam Young 2016-05-13 17:28:19 UTC

IAW the above discussion, going to close it.  If more information comes up on the underlying cause of the token expiration please open a new bug to address.

Comment 4 Andreas Karis 2016-05-13 17:33:05 UTC

Hello,

Sorry for the radio silence. The following is the output for token expiry, on a system which I deployed 2 days ago, in a lab, without VMs. If this is a sign of a larger issue, then we should investigate this. In my opinion, it would be sufficient to lower the syslog level from WARNING to INFO, or DEBUG. In the current abundance, this message doesn't deserve a WARNING, and spams logs of OSP 7 and/or 8.

[root@overcloud-controller-0 ~]# egrep -i 'authorization|token|expir' /var/log/nova/nova-api.log
2016-05-12 19:15:34.787 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 19:15:34.788 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 644bf970ba984d0e9d82710332b5a50a", "code": 404, "title": "Not Found"}}
2016-05-12 19:15:34.789 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 20:05:49.368 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 20:05:49.368 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: e869599607984d97a02aa245ed5ecd34", "code": 404, "title": "Not Found"}}
2016-05-12 20:05:49.369 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 21:05:49.525 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 21:05:49.525 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 5b0624ada3784a39868b86b3330edefe", "code": 404, "title": "Not Found"}}
2016-05-12 21:05:49.526 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 21:15:47.216 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 21:15:47.216 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 09b040b529c24d3dbb835af52766bca6", "code": 404, "title": "Not Found"}}
2016-05-12 21:15:47.217 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 22:15:47.278 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 22:15:47.279 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 5ef776434ca8429aa1a0b177f44f6e8c", "code": 404, "title": "Not Found"}}
2016-05-12 22:15:47.280 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 22:15:49.241 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 22:15:49.241 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: e7144794ac4b4c289031007928e67c20", "code": 404, "title": "Not Found"}}
2016-05-12 22:15:49.242 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 23:15:48.109 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-12 23:15:48.148 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 4111d2a7761543ca85e048edbbe4a6a7", "code": 404, "title": "Not Found"}}
2016-05-12 23:15:48.148 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 00:25:47.246 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 00:25:47.247 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: dc673200e0734fafb400a72be54bb1ca", "code": 404, "title": "Not Found"}}
2016-05-13 00:25:47.248 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 01:25:47.252 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 01:25:47.311 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: e1d731c099214bdcb7833781ae69b4bd", "code": 404, "title": "Not Found"}}
2016-05-13 01:25:47.312 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 01:45:35.759 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 01:45:35.760 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 21b1c8ca244145df8aafd55afdc5821e", "code": 404, "title": "Not Found"}}
2016-05-13 01:45:35.761 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 02:25:47.266 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 02:25:47.293 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 9f8026bcaaa04e75a507fe69bbaf897b", "code": 404, "title": "Not Found"}}
2016-05-13 02:25:47.302 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 03:25:47.479 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 03:25:47.479 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 9e6a3647132c415094e72125f4cd10e1", "code": 404, "title": "Not Found"}}
2016-05-13 03:25:47.480 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 03:55:34.756 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 03:55:34.757 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 1784088023df497b90370ffa8f3d933b", "code": 404, "title": "Not Found"}}
2016-05-13 03:55:34.758 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 04:25:47.535 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 04:25:47.536 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 18660ba2f61d49afb4bd3fd69f92c8ec", "code": 404, "title": "Not Found"}}
2016-05-13 04:25:47.537 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 05:25:47.546 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 05:25:47.565 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: ab06c1ea77364fb9bac45ba41f144a4a", "code": 404, "title": "Not Found"}}
2016-05-13 05:25:47.566 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 06:25:47.761 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 06:25:47.778 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: a9791de4dbd94831857b5990f0c3645e", "code": 404, "title": "Not Found"}}
2016-05-13 06:25:47.779 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 07:25:48.442 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 07:25:48.489 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: b8f9b94fccb145a9bcd44fbb6ca949d6", "code": 404, "title": "Not Found"}}
2016-05-13 07:25:48.492 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 07:45:48.728 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 07:45:48.729 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 5a9454f2ad7042fdb1274e8c699d2c59", "code": 404, "title": "Not Found"}}
2016-05-13 07:45:48.730 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 08:15:34.677 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 08:15:34.699 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: bc80e7562a9b4e37bbfdf925701c66b8", "code": 404, "title": "Not Found"}}
2016-05-13 08:15:34.700 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 08:45:48.853 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 08:45:48.854 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 3263850f1b144bee8621460f1ad40bbd", "code": 404, "title": "Not Found"}}
2016-05-13 08:45:48.855 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 11:15:34.659 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 11:15:34.725 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 068a1eb6dfa74b278d87d4c4318b4a48", "code": 404, "title": "Not Found"}}
2016-05-13 11:15:34.725 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 11:35:48.379 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 11:35:48.385 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 4ff240ff424c4419a0852b2605809971", "code": 404, "title": "Not Found"}}
2016-05-13 11:35:48.386 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 12:45:47.350 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 12:45:47.364 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 86ed1401b6c44329b7010cab0afb5207", "code": 404, "title": "Not Found"}}
2016-05-13 12:45:47.365 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 13:45:47.424 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 13:45:47.463 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 36f6489ff3814f05a9966e199132ccfd", "code": 404, "title": "Not Found"}}
2016-05-13 13:45:47.464 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 14:45:47.289 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 14:45:47.293 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 627edc6cb6c5471286f9e7455f46ae24", "code": 404, "title": "Not Found"}}
2016-05-13 14:45:47.294 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 15:15:49.110 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 15:15:49.112 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 8481a5a3c9ef4493a0d06bdc92229a21", "code": 404, "title": "Not Found"}}
2016-05-13 15:15:49.112 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 15:45:47.376 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 15:45:47.525 11277 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 0b6a4ea13a2e4efaba893babf41d3b31", "code": 404, "title": "Not Found"}}
2016-05-13 15:45:47.527 11277 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 16:15:49.717 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2016-05-13 16:15:49.739 11276 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: 2e798d070ff349ee96e0af2d1620f83f", "code": 404, "title": "Not Found"}}
2016-05-13 16:15:49.739 11276 WARNING keystonemiddleware.auth_token [-] Authorization failed for token

Comment 5 Andreas Karis 2016-05-13 17:33:55 UTC

You can reproduce this on any newly deployed OSP cluster, let it sit for 24 hours, and observe the abundance of these warning messages.

Comment 6 Adam Young 2016-05-20 17:14:24 UTC

OK, that log gives more context.  I think this is normal operations, and you are right, the logging level for these is too high.

Comment 8 Red Hat Bugzilla Rules Engine 2017-10-12 20:00:18 UTC

This bugzilla has been removed from the release and needs to be reviewed for Triaging and release planning for an appropriate Target Milestone.

Comment 15 Harry Rybacki 2018-01-05 16:31:25 UTC

Upstream review has merged: https://review.openstack.org/#/c/528129/

Comment 19 errata-xmlrpc 2018-06-27 13:26:26 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/RHEA-2018:2086