Erratic row list behavior with cross-policy rule

Bug #1659440 reported by Eric K on 2017-01-25
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
congress
Critical
Unassigned

Bug Description

More investigation needed, but it's a mysterious and erratic behavior seemingly having to do with this rule in policy1:
u(x,y) :- q(x,y), NOT policy2:a(x,y)

---
Interaction:

user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
+------+------+
| Col0 | Col1 |
+------+------+
| 2 | 3 |
| 5 | 7 |
| 1 | 2 |
+------+------+
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
Not Found::table 'u' doesn't exist (HTTP 404) (Request-ID: req-4c34cbf7-bb9d-401e-9a90-be47ed0418ee)
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
+------+------+
| Col0 | Col1 |
+------+------+
| 2 | 3 |
| 5 | 7 |
+------+------+
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
+------+------+
| Col0 | Col1 |
+------+------+
| 2 | 3 |
| 5 | 7 |
| 1 | 2 |
+------+------+
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
+------+------+
| Col0 | Col1 |
+------+------+
| 2 | 3 |
| 5 | 7 |
| 1 | 2 |
+------+------+
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
Not Found::table 'u' doesn't exist (HTTP 404) (Request-ID: req-ad01a9df-4344-48f1-aa4f-e9540a73d51a)
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
Not Found::table 'u' doesn't exist (HTTP 404) (Request-ID: req-c8dd0cab-f5eb-449f-b135-ebfe35a597c9)
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
Not Found::table 'u' doesn't exist (HTTP 404) (Request-ID: req-a8ca2949-f72e-4940-821d-6d246d427ce3)
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
Not Found::table 'u' doesn't exist (HTTP 404) (Request-ID: req-f113b164-8d6a-49ae-bdf8-488c5dae85bf)
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
+------+------+
| Col0 | Col1 |
+------+------+
| 2 | 3 |
| 5 | 7 |
+------+------+
user@host:/opt/stack/congress$ openstack congress policy row list policy1 u
+------+------+
| Col0 | Col1 |
+------+------+
| 2 | 3 |
| 5 | 7 |
| 1 | 2 |
+------+------+

$ openstack congress policy rule list policy1
// ID: 0e324d3b-fc21-4306-8a9e-bf74a6aa14d0
// Name: None
p(x,y) :- r(x,y), NOT equal(x,9)

// ID: 0f97e1f7-3e12-4aba-9961-408ae4df8e3a
// Name: None
t(x) :- nova:flavors(vcpus=x), NOT s(x)

// ID: 1847f9c1-f39c-4e5e-b7e9-bfbfe3ee9efe
// Name: None
temp(1,2)

// ID: 2647f56b-c70e-46eb-9172-f394506fbfd2
// Name: None
r(9,9)

// ID: 7d92a6ea-0c76-4896-8429-9683a8ac4799
// Name: None
p(x,y) :- q(x,y), r(y,x)

// ID: 7da9af59-2c57-47c6-b334-f269985ed2e4
// Name: None
r(2,1)

// ID: 826105e1-8610-4d1f-bae5-7b7c5ff76458
// Name: None
q(5,7)

// ID: 9c43c445-8c86-4c6f-bf40-5e5d3e83b5aa
// Name: None
r(5,7)

// ID: acf96885-5659-471b-97bd-26d142d57791
// Name: None
u(x,y) :- q(x,y), NOT policy2:a(x,y)

// ID: bdffb134-fe87-43d6-9518-6e0a6a5a2ac1
// Name: None
r(3,2)

// ID: d2a6c959-b09d-4e43-a5fe-1f6ac5d10e5b
// Name: None
q(1,2)

// ID: e105ca18-03e3-4b72-9e86-218f9cfcda15
// Name: None
q(2,3)

// ID: f2d04fda-d54e-434b-9af6-5df9eb4b7a7f
// Name: None
s(x) :- nova:flavors(vcpus=x), p(x,y)

---

Selected log:

2017-01-23 21:35:34.871 INFO congress.api.application [req-4c34cbf7-bb9d-401e-9a90-be47ed0418ee admin 464bf75a44e34bb88bd7d8f7f36386c4] Handling request 'GET /v1/policies/policy1/tables/u/rows' with CollectionHandler((/v1/data-sources/(?P<ds_id>[^/]+)|/v1/policies/(?P<policy_id>[^/]+))/tables/(?P<table_id>[^/]+)/rows$)
2017-01-23 21:35:34.871 INFO congress.api.row_model [req-4c34cbf7-bb9d-401e-9a90-be47ed0418ee admin 464bf75a44e34bb88bd7d8f7f36386c4] get_items(context={'table_id': 'u', 'policy_id': 'policy1'})
2017-01-23 21:35:34.872 DEBUG oslo_messaging._drivers.amqpdriver [req-4c34cbf7-bb9d-401e-9a90-be47ed0418ee admin 464bf75a44e34bb88bd7d8f7f36386c4] CALL msg_id: abf6310d90804bdcbe6b7dac92a29a2d exchange 'congress' topic 'congress-service-__engine-bus' from (pid=84546) _send /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:442
2017-01-23 21:35:34.874 DEBUG oslo_messaging._drivers.amqpdriver [-] received message msg_id: abf6310d90804bdcbe6b7dac92a29a2d reply to reply_b0d97f3a4b1044598a94df7c2ee49efb from (pid=84546) __call__ /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:194
2017-01-23 21:35:34.875 ERROR oslo_messaging.rpc.server [-] Exception during message handling
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server Traceback (most recent call last):
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 155, in _process_incoming
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server res = self.dispatcher.dispatch(message)
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 222, in dispatch
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server return self._do_dispatch(endpoint, method, ctxt, args)
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 192, in _do_dispatch
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server result = func(ctxt, **new_args)
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server File "/opt/stack/congress/congress/policy_engines/agnostic.py", line 2197, in get_row_data
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server return self.dse.get_row_data(table_id, source_id, trace)
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server File "/opt/stack/congress/congress/policy_engines/agnostic.py", line 812, in get_row_data
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server raise exception.NotFound("table '%s' doesn't exist" % table_id)
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server NotFound: table 'u' doesn't exist
2017-01-23 21:35:34.875 TRACE oslo_messaging.rpc.server
2017-01-23 21:35:34.876 DEBUG oslo_messaging._drivers.amqpdriver [-] sending reply msg_id: abf6310d90804bdcbe6b7dac92a29a2d reply queue: reply_b0d97f3a4b1044598a94df7c2ee49efb time elapsed: 0.00151785300113s from (pid=84546) _send_reply /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:73
2017-01-23 21:35:34.878 DEBUG oslo_messaging._drivers.amqpdriver [-] received reply msg_id: abf6310d90804bdcbe6b7dac92a29a2d from (pid=84546) __call__ /usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py:299
2017-01-23 21:35:34.879 ERROR congress.api.row_model [req-4c34cbf7-bb9d-401e-9a90-be47ed0418ee admin 464bf75a44e34bb88bd7d8f7f36386c4] Error occurred while processing source_id 'policy1' for row data of the table 'u'
2017-01-23 21:35:34.879 TRACE congress.api.row_model Traceback (most recent call last):
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/opt/stack/congress/congress/api/row_model.py", line 86, in get_items
2017-01-23 21:35:34.879 TRACE congress.api.row_model timeout=self.dse_long_timeout)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/opt/stack/congress/congress/api/base.py", line 40, in invoke_rpc
2017-01-23 21:35:34.879 TRACE congress.api.row_model caller, name, kwargs, timeout=timeout, local=local)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/opt/stack/congress/congress/dse2/data_service.py", line 193, in rpc
2017-01-23 21:35:34.879 TRACE congress.api.row_model service, action, kwargs, timeout=timeout, local=local, retry=retry)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/opt/stack/congress/congress/dse2/dse_node.py", line 336, in invoke_service_rpc
2017-01-23 21:35:34.879 TRACE congress.api.row_model result = client.call(self.context, method, **kwargs)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 465, in call
2017-01-23 21:35:34.879 TRACE congress.api.row_model return self.prepare().call(ctxt, method, **kwargs)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/client.py", line 169, in call
2017-01-23 21:35:34.879 TRACE congress.api.row_model retry=self.retry)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/transport.py", line 97, in _send
2017-01-23 21:35:34.879 TRACE congress.api.row_model timeout=timeout, retry=retry)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 458, in send
2017-01-23 21:35:34.879 TRACE congress.api.row_model retry=retry)
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/_drivers/amqpdriver.py", line 449, in _send
2017-01-23 21:35:34.879 TRACE congress.api.row_model raise result
2017-01-23 21:35:34.879 TRACE congress.api.row_model NotFound_Remote: table 'u' doesn't exist
2017-01-23 21:35:34.879 TRACE congress.api.row_model Traceback (most recent call last):
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/server.py", line 155, in _process_incoming
2017-01-23 21:35:34.879 TRACE congress.api.row_model res = self.dispatcher.dispatch(message)
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 222, in dispatch
2017-01-23 21:35:34.879 TRACE congress.api.row_model return self._do_dispatch(endpoint, method, ctxt, args)
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/usr/local/lib/python2.7/dist-packages/oslo_messaging/rpc/dispatcher.py", line 192, in _do_dispatch
2017-01-23 21:35:34.879 TRACE congress.api.row_model result = func(ctxt, **new_args)
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/opt/stack/congress/congress/policy_engines/agnostic.py", line 2197, in get_row_data
2017-01-23 21:35:34.879 TRACE congress.api.row_model return self.dse.get_row_data(table_id, source_id, trace)
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.879 TRACE congress.api.row_model File "/opt/stack/congress/congress/policy_engines/agnostic.py", line 812, in get_row_data
2017-01-23 21:35:34.879 TRACE congress.api.row_model raise exception.NotFound("table '%s' doesn't exist" % table_id)
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.879 TRACE congress.api.row_model NotFound: table 'u' doesn't exist
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.879 TRACE congress.api.row_model
2017-01-23 21:35:34.880 ERROR congress.api.application [req-4c34cbf7-bb9d-401e-9a90-be47ed0418ee admin 464bf75a44e34bb88bd7d8f7f36386c4] ApiApplication: found DataModelException
2017-01-23 21:35:34.880 TRACE congress.api.application Traceback (most recent call last):
2017-01-23 21:35:34.880 TRACE congress.api.application File "/opt/stack/congress/congress/api/application.py", line 53, in __call__
2017-01-23 21:35:34.880 TRACE congress.api.application response = handler.handle_request(request)
2017-01-23 21:35:34.880 TRACE congress.api.application File "/opt/stack/congress/congress/api/webservice.py", line 426, in handle_request
2017-01-23 21:35:34.880 TRACE congress.api.application return self.list_members(request)
2017-01-23 21:35:34.880 TRACE congress.api.application File "/opt/stack/congress/congress/api/webservice.py", line 452, in list_members
2017-01-23 21:35:34.880 TRACE congress.api.application context=self._get_context(request))
2017-01-23 21:35:34.880 TRACE congress.api.application File "/opt/stack/congress/congress/api/row_model.py", line 94, in get_items
2017-01-23 21:35:34.880 TRACE congress.api.application raise webservice.DataModelException.create(e)
2017-01-23 21:35:34.880 TRACE congress.api.application DataModelException: Not Found::table 'u' doesn't exist

Eric K (ekcs) on 2017-02-01
Changed in congress:
importance: High → Critical
Eric K (ekcs) wrote :

I think we should really fix this for Ocata release. I've made some progress but no solution yet.

As Tim thought, it has something to do with rule sync. rule synchronizer is deleting the rule one sync, and adding it back the next. The cause is that the rule['policy_name'] is incorrectly stored as 'classification' rather than 'policy1' when stored in the policy engine memory. Further investigation needed to figure out why that happens.

Below are some synchronizer logs from two consecutive rule syncs (newpolicy instead of policy1).

2017-01-31 14:49:42.925 DEBUG congress.synchronizer.policy_rule_synchronizer [^[[00;36m-] ^[[01;35mremoving rule {'comment': u'', 'policy_name': u'classification', 'id': u'c7398319-d4e1-41a6-be70-930bdae54e59', 'rule': u'u(x,y) :- q(x,y), NOT classification:a(x,y)', 'name': None}^[[00m ^[[00;33mfrom (pid=66261) synchronize_rules /opt/stack/congress/congress/synchronizer/policy_rule_synchronizer.py:268^[[00m^M

2017-01-31 14:50:12.924 DEBUG congress.synchronizer.policy_rule_synchronizer [^[[00;36m-] ^[[01;35madding rule {'comment': u'', 'policy_name': u'newpolicy', 'id': u'c7398319-d4e1-41a6-be70-930bdae54e59', 'rule': u'u(x,y) :- q(x,y), NOT classification:a(x,y)', 'name': None}^[[00m ^[[00;33mfrom (pid=66261) synchronize_rules /opt/stack/congress/congress/synchronizer/policy_rule_synchronizer.py:243^[[00m^M

Eric K (ekcs) wrote :

Turns out, this patch seems to have resolved the problem.
https://review.openstack.org/#/c/416777/

I guess it has something to do with synchronizer interrupting the rule insertion (the new lock prevents that). But I still can't explain the buggy behavior observed.

Changed in congress:
status: New → Fix Committed
Eric K (ekcs) on 2017-02-04
Changed in congress:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers