Logs filled with unnecessary policy deprecation warnings

[Attila Fazekas]

My today master version of keystone log is full with:

2019-07-15 10:47:25.316828 As of the Stein release, the domain API now understands how to handle
2019-07-15 10:47:25.316831 system-scoped tokens in addition to project-scoped tokens, making the API more
2019-07-15 10:47:25.316834 accessible to users without compromising security or manageability for
2019-07-15 10:47:25.316837 administrators. The new default policies for this API account for these changes
2019-07-15 10:47:25.316840 automatically
2019-07-15 10:47:25.316843 . Either ensure your deployment is ready for the new default or copy/paste the deprecated policy into your policy file and maintain it manually.
2019-07-15 10:47:25.316846 warnings.warn(deprecated_msg)
2019-07-15 10:47:25.316849 \x1b[00m

2019-07-15 10:47:25.132244 2019-07-15 10:47:25.131 22582 WARNING py.warnings [req-0162c9d3-9953-4b2d-9587-6046651033c3 7b0f3387e0f942f3bae75cea0a5766a3 98500c83d03e4ba38aa27a78675d2b1b - default default] /usr/lo
cal/lib/python3.7/site-packages/oslo_policy/policy.py:695: UserWarning: Policy "identity:delete_credential":"rule:admin_required" was deprecated in S in favor of "identity:delete_credential":"(role:admin and sys
tem_scope:all) or user_id:%(target.credential.user_id)s". Reason: As of the Stein release, the credential API now understands how to handle system-scoped tokens in addition to project-scoped tokens, making the A
PI more accessible to users without compromising security or manageability for administrators. The new default policies for this API account for these changes automatically.. Either ensure your deployment is rea
dy for the new default or copy/paste the deprecated policy into your policy file and maintain it manually.
2019-07-15 10:47:25.132262 warnings.warn(deprecated_msg)
2019-07-15 10:47:25.132266 \x1b[00m
2019-07-15 10:47:25.132979 2019-07-15 10:47:25.132 22582 WARNING

This is fresh setup from `master` without any policy configuration, therefore keystone defaults itself triggers the warning.

grep -R 'As of the Stein release' keystone-error.log |wc -l
820

Current master is for `T` , there is no point to have 820 warning (first ~ 10 minute) for using the keystone default.

Please make these warnings less noise .

[Colleen Murphy (krinkle)]

These warnings happen every time the policies are reloaded which apparently happens dynamically, we should make sure to only emit these warnings when keystone starts.

The reason we emit these warnings is that while the policies are deprecated, the old rules and the new rules are OR'd together, making them more open by default, so we want people to opt into the new more secure policies by changing them in your policy config.

[Colleen Murphy (krinkle)]

Raising the priority of this to critical. I suspect the huge number of logs is contributing to our high unit test failure rate, e.g. http://logs.openstack.org/76/673476/1/gate/openstack-tox-lower-constraints/d31bc96/

[Colleen Murphy (krinkle)]

Actually, on devstack I'm not seeing these warnings emitted on every request, it just seems to be on the first request after keystone is reloaded. Yes, it is a lot of warnings because there is one for each policy, but it should only happen once until the next time keystone is reloaded. Can you confirm that's what you're seeing?

I think the noisy unit tests are a separate issue that we could fix with a fixture.

[Radosław Piliszek (yoctozepto)]

@Colleen, you might be right though it seems that this affects the first few requests, not a single request.
Deprecation warnings are thus repeated multiple times in logs.
This is one of deprecation messages grepped:

2019-08-01 09:51:59.260 22 WARNING py.warnings [req-8c25d5ef-b630-444c-887c-6fec08872bf3 60c01e13a80349468e63430fac36781e 61704891c9604994903470217ede5b9c - default default] /var/lib/kolla/venv/lib/python2.7/site-packages/oslo_policy/policy.py:695: UserWarning: Policy "identity:list_domains":"rule:admin_required" was deprecated in S in favor of "identity:list_domains":"role:reader and system_scope:all". Reason:
2019-08-01 09:52:04.209 21 WARNING py.warnings [req-e564c3c3-7e3c-4d8f-a1fc-72caaf3d436b 60c01e13a80349468e63430fac36781e 61704891c9604994903470217ede5b9c - default default] /var/lib/kolla/venv/lib/python2.7/site-packages/oslo_policy/policy.py:695: UserWarning: Policy "identity:list_domains":"rule:admin_required" was deprecated in S in favor of "identity:list_domains":"role:reader and system_scope:all". Reason:
2019-08-01 09:52:04.487 19 WARNING py.warnings [req-f07d9ab5-346a-47c6-8606-e2f73fe9a3e6 60c01e13a80349468e63430fac36781e 61704891c9604994903470217ede5b9c - default default] /var/lib/kolla/venv/lib/python2.7/site-packages/oslo_policy/policy.py:695: UserWarning: Policy "identity:list_domains":"rule:admin_required" was deprecated in S in favor of "identity:list_domains":"role:reader and system_scope:all". Reason:
2019-08-01 09:52:04.795 18 WARNING py.warnings [req-6ceb8e7e-e973-4213-9a85-c5b5b42509df 60c01e13a80349468e63430fac36781e 61704891c9604994903470217ede5b9c - default default] /var/lib/kolla/venv/lib/python2.7/site-packages/oslo_policy/policy.py:695: UserWarning: Policy "identity:list_domains":"rule:admin_required" was deprecated in S in favor of "identity:list_domains":"role:reader and system_scope:all". Reason:

[Colleen Murphy (krinkle)]

I was able to reproduce this on devstack by using WSGI_MODE=mod_wsgi and playing with the processes value in the WSGIDaemonProcess apache setting. The number of times the warnings get emitted is related to the number of WSGI workers. If you have three or more workers, it will get pretty noisy, but it's still not as critical as I originally thought because it will still only happen a fixed number of times after the reload.

[Radosław Piliszek (yoctozepto)]

Thanks for looking into this. Indeed it's done this way here. There are exactly 4 worker processes and 4 repeated warnings.

[Ben Nemec (bnemec)]

We have interprocess locking in Oslo, but I don't know that there would be any way to store whether a deprecation has been logged. We could probably put something together to handle it though.

[OpenStack Infra (hudson-openstack)]

Related fix proposed to branch: master
Review: https://review.opendev.org/674711

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/673932
Committed: https://git.openstack.org/cgit/openstack/oslo.policy/commit/?id=4d40252748bd31584f1cbb72d4641dec62cf1303
Submitter: Zuul
Branch: master

commit 4d40252748bd31584f1cbb72d4641dec62cf1303
Author: Colleen Murphy <email address hidden>
Date: Wed Jul 31 18:18:17 2019 -0700

    Add attribute to suppress deprecation warnings

    Without this patch, if a project is going through a heavy policy
    refactor, significant numbers of deprecation warnings are emitted. When
    the enforcer is repeated reinitialized, as is the case when unit
    testing, the vast amount of logs resulting from the warnings is both
    unnecessary and harmful as it impedes log readability and explodes the
    size of the logs, thereby causing CI instability as the infrastructure
    struggles to process the logs.

    This change adds a public attribute to the enforcer object to allow
    callers to suppress these logs. This is not exposed as a configuration
    option because we do not want to allow operators to suppress these logs,
    and the warnings that occur when the enforcer is only reinitialized when
    the process is reloaded are not nearly so debilitating as they are
    during, e.g., a unit test run when the enforcer is generally
    reinitialized for every test.

    The Python warnings module allows for setting global attributes to
    filter logs, and it might have been useful for the consuming project to
    filter these logs at that level rather than modifying the policy
    enforcer to turn log emissions on and off. The problem with this
    approach is that if the number of deprecations is extreme, as may be the
    case during a heavy refactor, the warnings filter can become so
    inefficient that the test run can take much longer, causing even further
    CI stability as test runs reach timeout limits.

    Needed-by: https://review.opendev.org/673933
    Change-Id: Ibfc7d4fca02b896953f80ddf1a9a8b9a19444f72
    Related-bug: #1836568

[OpenStack Infra (hudson-openstack)]

Change abandoned by Colleen Murphy (<email address hidden>) on branch: master
Review: https://review.opendev.org/674711
Reason: Abandoning in favor of https://review.opendev.org/673932

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/674940

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/673933
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=e8151070c052c2a26037cdad3ad3330899ff334b
Submitter: Zuul
Branch: master

commit e8151070c052c2a26037cdad3ad3330899ff334b
Author: Colleen Murphy <email address hidden>
Date: Wed Jul 31 18:28:16 2019 -0700

    Suppress policy deprecation warnings in unit tests

    Since the WSGI app is reinitialized pretty much for every unit test, and
    we have deprecated so many policies, we get hundreds of megabytes of
    deprecation warnings in the unit test logs. This is unnecessary for unit
    tests, a noisy hindrance to developers, and causes a high failure rate
    in our CI due to the huge logs. This change fixes the issue for the unit
    tests by adding warnings filters for DeprecationWarnings and
    UserWarnings from oslo.policy and oslo.context.

    This does not solve the issue that deployers see a lot of noise in their
    logs. However, since production servers aren't reinitializing the WSGI
    app quite so often, it's a less severe issue.

    Related-bug: #1836568

    Change-Id: Iaa7eae03bde7ab43a8c5a5886686f834cf7ec620
    Depends-on: https://review.opendev.org/673932

[Ben Nemec (bnemec)]

I found a new variation on this in oslopolicy-list-redundant. There are so many deprecation warnings printed when running the redundant rule checker against Keystone that it overwhelms any legitimate output.

I worked around the problem by running `PYTHONWARNINGS="ignore" oslopolicy-list-redundant...` but that's not a great user experience. I think we probably need to suppress the deprecation warnings entirely in this tool because that's not what it's intended for, and even the less verbose deprecation warnings are still going to be too much.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/682117

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.opendev.org/682798

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/682798
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=15b416c34c49d038c059179feba38d9b398104ac
Submitter: Zuul
Branch: master

commit 15b416c34c49d038c059179feba38d9b398104ac
Author: Colleen Murphy <email address hidden>
Date: Tue Sep 17 23:03:11 2019 -0700

    Consolidate policy deprecation warnings

    Suppress noisy deprecation warnings in favor of a single blanket
    warning. Oslopolicy-policy-generator will still emit the same
    deprecation warnings, and oslopolicy-policy-upgrade can be used to
    migrate existing custom policies to the upgraded version.

    This change requires no modification to oslo.policy and so no new
    release or requirements bump will be needed.

    Change-Id: I3c27c61cee3527b39f6a167b11198ab066614a1d
    Closes-bug: #1836568

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/674940
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=0526718feed24fe47c469bba7542a468c204585c
Submitter: Zuul
Branch: master

commit 0526718feed24fe47c469bba7542a468c204585c
Author: Colleen Murphy <email address hidden>
Date: Tue Aug 6 14:40:30 2019 -0700

    Make policy deprecation reasons less verbose

    oslo.policy emits a deprecation warning for every single rule that we
    have deprecated at least once when a request comes in, and possibly
    subsequent times if keystone is running in multiple processes, and even
    more after keystone is reloaded. It's not useful to repeat nearly
    identical multi-line messages for each policy every time: logs aren't
    meant to justify our reasoning, they're just meant to be informative.
    The relevant information and rationalization can be found in the release
    notes. Repeating these identical multi-line messages starts to use up
    space quickly and makes the logs unreadable.

    This patch reduces the DEPRECATED_REASON for each policy to one brief
    line, which should help make the logs more readable in general and
    especially when run in a multiprocess environment, reduce the disk
    footprint of the logs, and help with log indexing.

    Change-Id: I98a0c06586b18dbd2f6681a24a5af1ea2de70951
    Partial-bug: #1836568

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/keystone 16.0.0.0rc1 release candidate.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/682117
Committed: https://git.openstack.org/cgit/openstack/oslo.policy/commit/?id=5d3aeb53a9f3686353e0740c1891bd0e66e90650
Submitter: Zuul
Branch: master

commit 5d3aeb53a9f3686353e0740c1891bd0e66e90650
Author: Ben Nemec <email address hidden>
Date: Fri Sep 13 17:08:05 2019 +0000

    Suppress deprecation warnings in oslopolicy-list-redundant

    When running the tool against a project with a lot of deprecated
    policies, the deprecation warnings overwhelm the important output
    from the tool. Since checking for deprecations isn't the purpose of
    this tool, let's just suppress warnings and limit the output to the
    list of redundant policy rules that the user cares about.

    I will note that the suppress_deprecation_warnings member is marked
    as test only, but that was targeted at consumers of oslo.policy
    rather than oslo.policy itself. I could also argue that we're
    "testing" for redundant policies here, but that feels like semantic
    hair splitting. :-)

    Change-Id: I194af14ebd341366dbb1dd033654739a7f3d085c
    Partial-Bug: 1836568

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/train
Review: https://review.opendev.org/694842

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/694842
Committed: https://git.openstack.org/cgit/openstack/oslo.policy/commit/?id=4cf4d0b2d7519f328f0d6ab76f268d090407e0d3
Submitter: Zuul
Branch: stable/train

commit 4cf4d0b2d7519f328f0d6ab76f268d090407e0d3
Author: Ben Nemec <email address hidden>
Date: Fri Sep 13 17:08:05 2019 +0000

    Suppress deprecation warnings in oslopolicy-list-redundant

    When running the tool against a project with a lot of deprecated
    policies, the deprecation warnings overwhelm the important output
    from the tool. Since checking for deprecations isn't the purpose of
    this tool, let's just suppress warnings and limit the output to the
    list of redundant policy rules that the user cares about.

    I will note that the suppress_deprecation_warnings member is marked
    as test only, but that was targeted at consumers of oslo.policy
    rather than oslo.policy itself. I could also argue that we're
    "testing" for redundant policies here, but that feels like semantic
    hair splitting. :-)

    Change-Id: I194af14ebd341366dbb1dd033654739a7f3d085c
    Partial-Bug: 1836568
    (cherry picked from commit 5d3aeb53a9f3686353e0740c1891bd0e66e90650)