"cannot format data, exception: Expected a dictionary, got <class 'oslo_context.context._DeprecatedPolicyValues" all over n-api logs

[Matt Riedemann]

We're doing policy enforcement wrong somehow, I'm seeing this in the nova-api logs when a server is being deleted:

http://logs.openstack.org/81/606981/4/check/tempest-slow/fafde23/controller/logs/screen-n-api.txt.gz#_Dec_08_01_45_42_745709

Dec 08 01:45:42.745709 ubuntu-xenial-ovh-gra1-0001066161 <email address hidden>[22839]: DEBUG oslo_policy.policy [None req-a0211268-269b-4227-ba65-a680ec13b6e3 tempest-TestMultiAttachVolumeSwap-1803326020 tempest-TestMultiAttachVolumeSwap-1803326020] enforce: rule="context_is_admin" creds={"domain_id": null, "is_admin": null, "is_admin_project": true, "project_domain_id": "default", "project_id": "5db98765c5d94a73bae8aba2f13c7762", "roles": ["reader", "member"], "service_project_domain_id": null, "service_project_id": null, "service_roles": [], "service_user_domain_id": null, "service_user_id": null, "system_scope": null, "user_domain_id": "default", "user_id": "9bc61597b6794ca49c79ce599c26b223"} target=cannot format data, exception: Expected a dictionary, got <class 'oslo_context.context._DeprecatedPolicyValues'> instead. {{(pid=22842) enforce /usr/local/lib/python2.7/dist-packages/oslo_policy/policy.py:902}}

I would think that's coming from here but I'm not sure:

https://github.com/openstack/nova/blob/08d617084e5aa69ada0898d674022621d130aef3/nova/api/openstack/compute/servers.py#L674

But the debug error comes before we get that far because it's logged before this:

Dec 08 01:45:42.747544 ubuntu-xenial-ovh-gra1-0001066161 <email address hidden>[22839]: DEBUG nova.api.openstack.wsgi [None req-a0211268-269b-4227-ba65-a680ec13b6e3 tempest-TestMultiAttachVolumeSwap-1803326020 tempest-TestMultiAttachVolumeSwap-1803326020] Calling method '<bound method ServersController.delete of <nova.api.openstack.compute.servers.ServersController object at 0x7f91cdb05c90>>' {{(pid=22842) _process_stack /opt/stack/nova/nova/api/openstack/wsgi.py:507}}

So maybe some kind of middleware? It's probably this:

https://github.com/openstack/nova/blob/08d617084e5aa69ada0898d674022621d130aef3/nova/context.py#L151

And that eventually calls enforce() in the policy code passing credentials as the target:

https://github.com/openstack/nova/blob/08d617084e5aa69ada0898d674022621d130aef3/nova/policy.py#L178

And the _DeprecatedPolicyValues comes from oslo.context:

https://github.com/openstack/oslo.context/blob/0daf01065d1d51694e06aaecb3dcf4dcc78710fe/oslo_context/context.py#L318

The fix might be here: https://review.openstack.org/#/c/564349/

[Matt Riedemann (mriedem)]

The format error comes from this:

https://github.com/openstack/oslo.policy/blob/b9fd10e2612f26c93d49c168a0408aba6d20e5bf/oslo_policy/policy.py#L891

because mask_dict_password expects a dict:

https://github.com/openstack/oslo.utils/blob/e67579790e4a0df05b712b58345be531f29914f5/oslo_utils/strutils.py#L394

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/624185

[Ben Nemec (bnemec)]

There's a patch to oslo.utils to fix this too: https://review.openstack.org/#/c/620686/

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/624185
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=c27af238ad99c0330eb4b55398f44be28e6f0485
Submitter: Zuul
Branch: master

commit c27af238ad99c0330eb4b55398f44be28e6f0485
Author: Matt Riedemann <email address hidden>
Date: Mon Dec 10 14:58:46 2018 -0500

    Fix target used in nova.policy.check_is_admin

    The target passed to Enforcer.authorize should be a dict,
    similar to the target dict to the RequestContext.can method.
    However, we were passing an instance of _DeprecatedPolicyValues
    because that is ultimately what comes out of
    RequestContext.to_policy_values(). As of change
    I4642c57990b145c0e691140970574412682e66a5 in oslo.policy, that
    incorrect type for the target parameter results in an error in
    the debug logs for the policy check:

      cannot format data, exception: Expected a dictionary, got
      <class 'oslo_context.context._DeprecatedPolicyValues'> instead.

    This resolves the issue by using the same default target dict
    that RequestContext.can uses if a target is not supplied.

    Note that we get here from NovaKeystoneContext via API middleware
    before any request handler is invoked in the wsgi stack, so there
    is no context from the request as to what to pass for the target
    besides the user_id/project_id.

    Change-Id: I4442a7b95d15233f76f7795d45b18ac440ddb831
    Closes-Bug: #1807747

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/stein
Review: https://review.opendev.org/660330

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.opendev.org/660330
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=e13513010fdb48a4538daa3ca8b7ae3853635587
Submitter: Zuul
Branch: stable/stein

commit e13513010fdb48a4538daa3ca8b7ae3853635587
Author: Matt Riedemann <email address hidden>
Date: Mon Dec 10 14:58:46 2018 -0500

    Fix target used in nova.policy.check_is_admin

    The target passed to Enforcer.authorize should be a dict,
    similar to the target dict to the RequestContext.can method.
    However, we were passing an instance of _DeprecatedPolicyValues
    because that is ultimately what comes out of
    RequestContext.to_policy_values(). As of change
    I4642c57990b145c0e691140970574412682e66a5 in oslo.policy, that
    incorrect type for the target parameter results in an error in
    the debug logs for the policy check:

      cannot format data, exception: Expected a dictionary, got
      <class 'oslo_context.context._DeprecatedPolicyValues'> instead.

    This resolves the issue by using the same default target dict
    that RequestContext.can uses if a target is not supplied.

    Note that we get here from NovaKeystoneContext via API middleware
    before any request handler is invoked in the wsgi stack, so there
    is no context from the request as to what to pass for the target
    besides the user_id/project_id.

    Change-Id: I4442a7b95d15233f76f7795d45b18ac440ddb831
    Closes-Bug: #1807747
    (cherry picked from commit c27af238ad99c0330eb4b55398f44be28e6f0485)

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 19.0.1 release.

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/nova 20.0.0.0rc1 release candidate.