ValueError: Circular reference detected when enable keystonemiddle audit

[Liyingjun]

When keystonemiddleware audit is enabled[1], the following error will be raised when calling API:

ERROR oslo_messaging.notify.messaging [None req-3aae102e-2ad9-48eb-9d90-c0dd40f406af demo admin] Could not send notification to notifications. Payload={'event_type': 'audit.http.response', 'timestamp': u'2017-09-30 02:08:19.683070', '_context_query_params': {'page_reverse': False, 'limit': None, 'filters': {u'router:external': [True]}, 'marker': None, 'fields': [], 'sorts': [('id', True)]}, '_unique_id': '7bcac52804564f1b8c36512023333cc9', '_context_collection': 'networks', '_context_neutron_context': <neutron_lib.context.Context object at 0x7fd4edaf1210>, '_context_resource': 'network', '_context_pagination_helper': <neutron.api.api_common.PaginationNativeHelper object at 0x7fd4ed999e50>, 'payload': {'typeURI': 'http://schemas.dmtf.org/cloud/audit/1.0/event', 'eventTime': '2017-09-30T02:08:19.522814+0000', 'target': {'typeURI': 'service/network/networks', 'addresses': [{'url': 'unknown', 'name': 'admin'}, {'url': 'unknown', 'name': 'private'}, {'url': u'http://192.168.81.140:9696/', 'name': 'public'}], 'name': u'neutron', 'id': u'neutron'}, 'observer': {'id': 'target'}, 'tags': ['correlation_id?value=6d8800f9-62d5-5017-95de-01faa1ce3971'], 'eventType': 'activity', 'initiator': {'typeURI': 'service/security/account/user', 'name': u'admin', 'credential': {'token': 'gAAAAABZzvoFGHhvYSfs9wPTUe xxxxxxxx 4E1FLRXxh5CGz1G3iL1K4fzCWV', 'identity_status': 'Confirmed'}, 'host': {'agent': 'python-neutronclient', 'address': '192.168.81.140'}, 'project_id': u'7e42f18ee360464c8ad8a59fbb884f55', 'id': u'f6d2d8206c0149e69a7941c6bd24d6cb'}, 'reason': {'reasonCode': '200', 'reasonType': 'HTTP'}, 'reporterchain': [{'reporterTime': '2017-09-30T02:08:19.682515+0000', 'role': 'modifier', 'reporter': {'id': 'target'}}], 'action': 'read/list', 'outcome': 'success', 'id': '38d0536c-f456-5daf-953b-16325cd06d03', 'requestPath': '/v2.0/networks?router%3Aexternal=True'}, '_context_added_fields': [], '_context_sorting_helper': <neutron.api.api_common.SortingNativeHelper object at 0x7fd4ed999f90>, 'priority': 'INFO', '_context_uri_identifiers': {}, 'publisher_id': 'neutron-server', 'message_id': u'ba6db80f-797d-4f3b-b539-157e63519cee'}: ValueError: Circular reference detected
ERROR oslo_messaging.notify.messaging Traceback (most recent call last):
ERROR oslo_messaging.notify.messaging File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/notify/messaging.py", line 70, in notify
ERROR oslo_messaging.notify.messaging retry=retry)
ERROR oslo_messaging.notify.messaging File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 130, in _send_notification
ERROR oslo_messaging.notify.messaging retry=retry)
ERROR oslo_messaging.notify.messaging File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 582, in send_notification
ERROR oslo_messaging.notify.messaging envelope=(version == 2.0), notify=True, retry=retry)
ERROR oslo_messaging.notify.messaging File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 530, in _send
ERROR oslo_messaging.notify.messaging msg = rpc_common.serialize_msg(msg)
ERROR oslo_messaging.notify.messaging File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/common.py", line 293, in serialize_msg
ERROR oslo_messaging.notify.messaging _MESSAGE_KEY: jsonutils.dumps(raw_msg)}
ERROR oslo_messaging.notify.messaging File "/usr/local/lib/python2.7/dist-packages/oslo_serialization/jsonutils.py", line 190, in dumps
ERROR oslo_messaging.notify.messaging return json.dumps(obj, default=default, **kwargs)
ERROR oslo_messaging.notify.messaging File "/usr/lib/python2.7/json/__init__.py", line 251, in dumps
ERROR oslo_messaging.notify.messaging sort_keys=sort_keys, **kw).encode(obj)
ERROR oslo_messaging.notify.messaging File "/usr/lib/python2.7/json/encoder.py", line 207, in encode
ERROR oslo_messaging.notify.messaging chunks = self.iterencode(o, _one_shot=True)
ERROR oslo_messaging.notify.messaging File "/usr/lib/python2.7/json/encoder.py", line 270, in iterencode
ERROR oslo_messaging.notify.messaging return _iterencode(o, 0)
ERROR oslo_messaging.notify.messaging ValueError: Circular reference detected
ERROR oslo_messaging.notify.messaging

[1]: https://docs.openstack.org/keystonemiddleware/latest/audit.html

[Miguel Lavalle (minsel)]

Is this happening with Neutron master?

[Lance Bragstad (lbragstad)]

Can you share your keystonemiddleware configuration values? How are things setup?

[Liyingjun (liyingjun)]

api_audit_map.conf, http://paste.openstack.org/show/623044/
api-paste.ini, http://paste.openstack.org/show/623045/

[Liyingjun (liyingjun)]

And this is a fix proposed to keystonemiddleware [1], not sure if it's the proper place for the fix.

[1]: https://review.openstack.org/#/c/508659/

[Liyingjun (liyingjun)]

Miguel, yes, it's happening with neutron master

[Nate Johnston (nate-johnston)]

I am also seeing this issue with a customer using Queens; downstream bug is https://bugzilla.redhat.com/show_bug.cgi?id=1708468

[OpenStack Infra (hudson-openstack)]

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

[Pavlo Shchelokovskyy (pshchelo)]

we've just hit that on Rocky too.

IMO the proper place to fix this for many (all?) possibly affected projects at once would be in oslo_serialization to explicitly handle oslo_context.RequestContext object by calling to_dict() on them (it already has some specific handing for some object types).

somewhere around here https://opendev.org/openstack/oslo.serialization/src/branch/master/oslo_serialization/jsonutils.py#L123-L132

I bet many may be affected as children of RequestContext indeed may be quite complex objects w/o obvious native serialization - and that's what their to_dict and from_dict are for.

[Pavlo Shchelokovskyy (pshchelo)]

btw, I can't reproduce it on master currently

setup using fresh devstack/master:

1. place https://opendev.org/openstack/pycadf/raw/branch/master/etc/pycadf/neutron_api_audit_map.conf to /etc/neutron/api_audit_map.conf

2. add the following section to /etc/neutron/neutron.conf
[audit_middleware_notifications]
driver = messagingv2

3. add the following section to /etc/neutron/api-paste.ini
[filter:audit]
paste.filter_factory = keystonemiddleware.audit:filter_factory
audit_map_file = /etc/neutron/api_audit_map.conf

4. in the /etc/neutron/api-paste.ini add "audit" after "keystonecontext" in keystone pipeline:
[composite:neutronapi_v2_0]
use = call:neutron.auth:pipeline_factory
noauth = cors http_proxy_to_wsgi request_id catch_errors osprofiler extensions neutronapiapp_v2_0
keystone = cors http_proxy_to_wsgi request_id catch_errors osprofiler authtoken keystonecontext audit extensions neutronapiapp_v2_0

5. restart devstack@neutron-api service

6. use the same call as reported above which seems to be
openstack --os-cloud devstack network list --external

7. observe no traces in the log

changing auidit notif driver to log produces fully parsed (w/o 'context' and others objects) lines in logs.

Still need to check if notifications are really being sent (attach to rabbit where they are supposed to arrive and catch and parse them out)

versions of relevant (IMO) libraries:
oslo.context==3.0.2
oslo.messaging==12.1.0
oslo.serialization==3.1.1
keystonemiddleware==9.0.0
neutron-lib==2.3.0

[Pavlo Shchelokovskyy (pshchelo)]

Found the culprit:

https://bugs.launchpad.net/keystonemiddleware/+bug/1809101
fix
https://review.opendev.org/#/q/Ib9a62a4cd0b7b9ffb9fa2d6440e8072d45ee0fee
seems like was backported to a lot of branches, but may be not released yet
(and backport to Queens is still not merged)

[Pavlo Shchelokovskyy (pshchelo)]

So, as far as I understand - the issue should be fixed with the following versions of keystonemiddleware:

Stein - 5.3.0 (initial version in Stein)
Rocky - 5.2.2 (released 24.02.2020)
Queens - not merged yet https://review.opendev.org/#/c/656232/ once merged and released should be smth like 4.22.2
Pike - merged in stable/pike but not released, if released should be smth like 4.17.2

[OpenStack Infra (hudson-openstack)]

Change abandoned by Nate Johnston (<email address hidden>) on branch: master
Review: https://review.opendev.org/670570
Reason: Fixed in https://review.opendev.org/626226