OpenStack Compute (nova)

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

Series stein
Bug #1807747

Bug #1807747 reported by Matt Riedemann on 2018-12-10

This bug affects 1 person

Affects		Status	Importance	Assigned to	Milestone
	OpenStack Compute (nova)	Fix Released	Medium	Matt Riedemann
	Stein	Fix Committed	Medium	Lee Yarwood

Bug Description

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/

Tags:

Revision history for this message

Matt Riedemann (mriedem) wrote on 2018-12-10:

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

Changed in nova:
status:	Confirmed → Triaged
assignee:	nobody → Matt Riedemann (mriedem)

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2018-12-10: Fix proposed to nova (master)

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

Changed in nova:
status:	Triaged → In Progress

Revision history for this message

Ben Nemec (bnemec) wrote on 2018-12-10:

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

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-05-18: Fix merged to nova (master)

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

Changed in nova:
status:	In Progress → Fix Released

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-05-21: Fix proposed to nova (stable/stein)

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

Revision history for this message

OpenStack Infra (hudson-openstack) wrote on 2019-05-24: Fix merged to nova (stable/stein)

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

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.

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