yahoo-eng-team team mailing list archive

[Matt Riedemann <mriedem.os@xxxxxxxxx>]

Public bug reported:

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
devstack@n-api.service[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
devstack@n-api.service[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/

** Affects: nova
     Importance: Medium
     Assignee: Matt Riedemann (mriedem)
         Status: Triaged


** Tags: api logging policy

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to OpenStack Compute (nova).
https://bugs.launchpad.net/bugs/1807747

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

Status in OpenStack Compute (nova):
  Triaged

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
  devstack@n-api.service[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
  devstack@n-api.service[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/

To manage notifications about this bug go to:
https://bugs.launchpad.net/nova/+bug/1807747/+subscriptions