[2021-08-23 17:43:31 +0000] [1] [INFO] Starting gunicorn 20.1.0
[2021-08-23 17:43:31 +0000] [1] [INFO] Listening at: http://0.0.0.0:7000 (1)
[2021-08-23 17:43:31 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2021-08-23 17:43:31 +0000] [9] [INFO] Booting worker with pid: 9
2021-08-23T17:43:31.756294+0000 |opal_common.fetcher.fetcher_register | INFO | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
2021-08-23T17:43:31.756561+0000 |opal_common.fetcher.fetcher_register | INFO | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
2021-08-23T17:43:31.776586+0000 |opal_common.fetcher.fetcher_register | INFO | Loading FetcherProvider 'PostgresFetchProvider' found at: <class 'opal_fetcher_postgres.provider.PostgresFetchProvider'>
2021-08-23T17:43:31.776740+0000 |opal_common.fetcher.fetcher_register | INFO | Fetcher Register loaded
2021-08-23T17:43:31.797014+0000 |opal_client.opa.runner | INFO | Launching opa runner
2021-08-23T17:43:31.798399+0000 |opal_client.opa.runner | INFO | Running OPA inline: opa run --server --addr=:8181 --authentication=off --authorization=off --log-level=info
2021-08-23T17:43:31.813046+0000 |opal_client.opa.logger | INFO | Initializing server. {'addrs': [':8181'], 'diagnostic-addrs': [], 'time': '2021-08-23T17:43:31Z'}
2021-08-23T17:43:32.804447+0000 |opal_client.opa.runner | INFO | Running OPA initial start callbacks
2021-08-23T17:43:32.805396+0000 |opal_client.policy.updater | INFO | Launching policy updater
2021-08-23T17:43:32.805677+0000 |opal_client.data.updater | INFO | Launching data updater
2021-08-23T17:43:32.805880+0000 |opal_client.policy.updater | INFO | Subscribing to topics: ['policy:.']
2021-08-23T17:43:32.806317+0000 |opal_client.data.updater | INFO | Subscribing to topics: ['policy_data']
2021-08-23T17:43:32.806967+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO | Trying to connect to Pub/Sub server - ws://opal_server:7002/ws
2021-08-23T17:43:32.807783+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO | Trying server - ws://opal_server:7002/ws
2021-08-23T17:43:32.811801+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO | Trying to connect to Pub/Sub server - ws://opal_server:7002/ws
2021-08-23T17:43:32.812388+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO | Trying server - ws://opal_server:7002/ws
2021-08-23T17:43:32.871213+0000 |opal_client.policy.updater | INFO | Connected to server
2021-08-23T17:43:32.871684+0000 |opal_client.policy.updater | INFO | Refetching policy code (full bundle)
2021-08-23T17:43:32.873803+0000 |opal_client.data.updater | INFO | Connected to server
2021-08-23T17:43:32.873948+0000 |opal_client.data.updater | INFO | Performing data configuration, reason: Initial load
2021-08-23T17:43:32.874025+0000 |opal_client.data.updater | INFO | Getting data-sources configuration from 'http://opal_server:7002/data/config'
2021-08-23T17:43:32.879804+0000 |opal_client.data.updater | INFO | Triggering data update with id: bda17568be5c4c3180f8d62f387e6f0e
2021-08-23T17:43:32.879997+0000 |opal_client.data.updater | INFO | Fetching policy data
2021-08-23T17:43:32.880289+0000 |opal_client.data.fetcher | INFO | Fetching data from url: postgresql://postgres@example_db:5432/postgres
2021-08-23T17:43:32.896534+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO | Connected to PubSub server ws://opal_server:7002/ws
2021-08-23T17:43:32.898193+0000 |opal_client.policy.updater | INFO | got policy bundle, commit hash: 'c60470ef8046152a8498d81df0eff66ddd1632e2'
2021-08-23T17:43:32.900306+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41390', 'req_id': 1, 'req_method': 'GET', 'req_path': '/v1/policies', 'time': '2021-08-23T17:43:32Z'}
2021-08-23T17:43:32.901079+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41390', 'req_id': 1, 'req_method': 'GET', 'req_path': '/v1/policies', 'resp_bytes': 13, 'resp_duration': 0.568914, 'resp_status': 200, 'time': '2021-08-23T17:43:32Z'}
2021-08-23T17:43:32.903906+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41392', 'req_id': 2, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'time': '2021-08-23T17:43:32Z'}
2021-08-23T17:43:32.906962+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41392', 'req_id': 2, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'resp_bytes': 315, 'resp_duration': 3.040543, 'resp_status': 400, 'time': '2021-08-23T17:43:32Z'}
2021-08-23T17:43:32.913913+0000 |opal_client.data.updater | INFO | Saving fetched data to policy-store: source url='postgresql://postgres@example_db:5432/postgres', destination path='/cities'
2021-08-23T17:43:32.915890+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41394', 'req_id': 3, 'req_method': 'PUT', 'req_path': '/v1/data/cities', 'time': '2021-08-23T17:43:32Z'}
2021-08-23T17:43:32.916704+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41394', 'req_id': 3, 'req_method': 'PUT', 'req_path': '/v1/data/cities', 'resp_bytes': 0, 'resp_duration': 0.889005, 'resp_status': 204, 'time': '2021-08-23T17:43:32Z'}
2021-08-23T17:43:32.992279+0000 |opal_client.opa.logger | INFO | OPA is out of date. {'current_version': '0.30.2', 'download_opa': 'https://openpolicyagent.org/downloads/v0.31.0/opa_linux_amd64', 'latest_version': '0.31.0', 'release_notes': 'https://github.com/open-policy-agent/opa/releases/tag/v0.31.0', 'time': '2021-08-23T17:43:32Z'}
2021-08-23T17:43:34.911369+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41396', 'req_id': 4, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'time': '2021-08-23T17:43:34Z'}
2021-08-23T17:43:34.912880+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41396', 'req_id': 4, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'resp_bytes': 315, 'resp_duration': 1.120678, 'resp_status': 400, 'time': '2021-08-23T17:43:34Z'}
2021-08-23T17:43:34.913772+0000 |opal_client...base_policy_store_client |WARNING | OPA transaction failed, transaction id=c60470ef8046152a8498d81df0eff66ddd1632e2, actions=['set_policies'], error=RetryError(<Future at 0x7f7fa0672f70 state=finished raised ValueError>)
2021-08-23T17:43:34.914065+0000 |fastapi_websocket_rpc.websocket_rpc_c...|ERROR | RPC Error
Traceback (most recent call last):
File "/root/.local/lib/python3.8/site-packages/tenacity/_asyncio.py", line 45, in __call__
result = await fn(*args, **kwargs)
│ │ └ {'policy_id': 'rbac.rego', 'policy_code': '# Role-based Access Control (RBAC)\n# --------------------------------\n#\n# This ...
│ └ (<opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>,)
└ <function OpaClient.set_policy at 0x7f7fa0b1d940>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 173, in set_policy
return await proxy_response_unless_invalid(opa_response, accepted_status_codes=[status.HTTP_200_OK])
│ │ │ └ 200
│ │ └ <module 'starlette.status' from '/root/.local/lib/python3.8/site-packages/starlette/status.py'>
│ └ <ClientResponse(http://localhost:8181/v1/policies/rbac.rego) [400 Bad Request]>
│ <CIMultiDictProxy('Content-Type': 'applicatio...
└ <function proxy_response_unless_invalid at 0x7f7fa0b0cca0>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 54, in proxy_response_unless_invalid
raise ValueError("OPA Client: unexpected status code: {}, error: {}".format(response.status_code, error))
│ │ └ {'code': 'invalid_parameter', 'message': 'error(s) occurred while compiling module(s)', 'errors': [{'code': 'rego_type_error'...
│ └ 400
└ <starlette.responses.Response object at 0x7f7fa0672eb0>
ValueError: OPA Client: unexpected status code: 400, error: {'code': 'invalid_parameter', 'message': 'error(s) occurred while compiling module(s)', 'errors': [{'code': 'rego_type_error', 'message': 'undefined function data.utils.hasPermission', 'location': {'file': 'rbac.rego', 'row': 37, 'col': 2}}]}
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/root/.local/bin/gunicorn", line 8, in <module>
sys.exit(run())
│ │ └ <function run at 0x7f7fa2b85940>
│ └ <built-in function exit>
└ <module 'sys' (built-in)>
File "/root/.local/lib/python3.8/site-packages/gunicorn/app/wsgiapp.py", line 67, in run
WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
└ <class 'gunicorn.app.wsgiapp.WSGIApplication'>
File "/root/.local/lib/python3.8/site-packages/gunicorn/app/base.py", line 231, in run
super().run()
File "/root/.local/lib/python3.8/site-packages/gunicorn/app/base.py", line 72, in run
Arbiter(self).run()
│ └ <gunicorn.app.wsgiapp.WSGIApplication object at 0x7f7fa2b5f820>
└ <class 'gunicorn.arbiter.Arbiter'>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 202, in run
self.manage_workers()
│ └ <function Arbiter.manage_workers at 0x7f7fa2494160>
└ <gunicorn.arbiter.Arbiter object at 0x7f7fa2b5f940>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
self.spawn_workers()
│ └ <function Arbiter.spawn_workers at 0x7f7fa2494280>
└ <gunicorn.arbiter.Arbiter object at 0x7f7fa2b5f940>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 622, in spawn_workers
self.spawn_worker()
│ └ <function Arbiter.spawn_worker at 0x7f7fa24941f0>
└ <gunicorn.arbiter.Arbiter object at 0x7f7fa2b5f940>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker
worker.init_process()
│ └ <function UvicornWorker.init_process at 0x7f7fa1b44b80>
└ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
File "/root/.local/lib/python3.8/site-packages/uvicorn/workers.py", line 64, in init_process
super(UvicornWorker, self).init_process()
│ └ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
└ <class 'uvicorn.workers.UvicornWorker'>
File "/root/.local/lib/python3.8/site-packages/gunicorn/workers/base.py", line 142, in init_process
self.run()
│ └ <function UvicornWorker.run at 0x7f7fa1b44ca0>
└ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
File "/root/.local/lib/python3.8/site-packages/uvicorn/workers.py", line 77, in run
loop.run_until_complete(server.serve(sockets=self.sockets))
│ │ │ │ │ └ [<gunicorn.sock.TCPSocket object at 0x7f7fa1b30f10>]
│ │ │ │ └ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
│ │ │ └ <function Server.serve at 0x7f7fa1e1cc10>
│ │ └ <uvicorn.server.Server object at 0x7f7fa206b4f0>
│ └ <method 'run_until_complete' of 'uvloop.loop.Loop' objects>
└ <uvloop.Loop running=True closed=False debug=False>
> File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_rpc/websocket_rpc_client.py", line 127, in __connect__
await self.channel.on_connect()
│ │ └ <function RpcChannel.on_connect at 0x7f7fa0b46ee0>
│ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa06ab820>
└ <fastapi_websocket_rpc.websocket_rpc_client.WebSocketRpcClient object at 0x7f7fa0690d60>
File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_rpc/rpc_channel.py", line 237, in on_connect
await self.on_handler_event(self._connect_handlers, self)
│ │ │ │ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa06ab820>
│ │ │ └ [<bound method PubSubClient._primary_on_connect of <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa069...
│ │ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa06ab820>
│ └ <function RpcChannel.on_handler_event at 0x7f7fa0b46e50>
└ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa06ab820>
File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_rpc/rpc_channel.py", line 234, in on_handler_event
await asyncio.gather(*(callback(*args, **kwargs) for callback in handlers))
│ │ │ │ └ [<bound method PubSubClient._primary_on_connect of <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa069...
│ │ │ └ {}
│ │ └ (<fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa06ab820>,)
│ └ <function gather at 0x7f7fa1eb5ca0>
└ <module 'asyncio' from '/usr/local/lib/python3.8/asyncio/__init__.py'>
File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_pubsub/pub_sub_client.py", line 217, in _primary_on_connect
await asyncio.gather(*(callback(self, channel) for callback in self._on_connect))
│ │ │ │ │ └ [<bound method PolicyUpdater._on_connect of <opal_client.policy.updater.PolicyUpdater object at 0x7f7fa205f910>>]
│ │ │ │ └ <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa06907c0>
│ │ │ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa06ab820>
│ │ └ <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa06907c0>
│ └ <function gather at 0x7f7fa1eb5ca0>
└ <module 'asyncio' from '/usr/local/lib/python3.8/asyncio/__init__.py'>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy/updater.py", line 108, in _on_connect
await self.update_policy()
│ └ <function PolicyUpdater.update_policy at 0x7f7fa09f63a0>
└ <opal_client.policy.updater.PolicyUpdater object at 0x7f7fa205f910>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy/updater.py", line 214, in update_policy
await store_transaction.set_policies(bundle)
│ │ └ PolicyBundle(manifest=['data.json', 'rbac.rego', 'utils.rego'], hash='c60470ef8046152a8498d81df0eff66ddd1632e2', old_hash=Non...
│ └ <function AbstractPolicyStore.set_policies at 0x7f7fa0b02550>
└ <opal_client.policy_store.base_policy_store_client.PolicyStoreTransactionContextManager object at 0x7f7fa0672760>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 256, in set_policies
return await self._set_policies_from_complete_bundle(bundle)
│ │ └ PolicyBundle(manifest=['data.json', 'rbac.rego', 'utils.rego'], hash='c60470ef8046152a8498d81df0eff66ddd1632e2', old_hash=Non...
│ └ <function OpaClient._set_policies_from_complete_bundle at 0x7f7fa0b22430>
└ <opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 268, in _set_policies_from_complete_bundle
await self.set_policy(policy_id=module.path, policy_code=module.rego)
│ │ │ │ │ └ '# Role-based Access Control (RBAC)\n# --------------------------------\n#\n# This example defines an RBAC model for a Pet St...
│ │ │ │ └ RegoModule(path='rbac.rego', package_name='app.rbac', rego='# Role-based Access Control (RBAC)\n# ---------------------------...
│ │ │ └ 'rbac.rego'
│ │ └ RegoModule(path='rbac.rego', package_name='app.rbac', rego='# Role-based Access Control (RBAC)\n# ---------------------------...
│ └ <function AsyncRetrying.wraps.<locals>.async_wrapped at 0x7f7fa0b1daf0>
└ <opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>
File "/root/.local/lib/python3.8/site-packages/tenacity/_asyncio.py", line 79, in async_wrapped
return await fn(*args, **kwargs)
│ │ └ {'policy_id': 'rbac.rego', 'policy_code': '# Role-based Access Control (RBAC)\n# --------------------------------\n#\n# This ...
│ └ (<opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>,)
└ <function OpaClient.set_policy at 0x7f7fa0b1d9d0>
File "/root/.local/lib/python3.8/site-packages/tenacity/_asyncio.py", line 42, in __call__
do = self.iter(retry_state=retry_state)
│ │ └ <tenacity.RetryCallState object at 0x7f7fa0672bb0>
│ └ <function BaseRetrying.iter at 0x7f7fa0ac5c10>
└ <AsyncRetrying object at 0x7f7fa0b0ee80 (stop=<tenacity.stop.stop_after_attempt object at 0x7f7fa0b0ed30>, wait=<tenacity.wai...
File "/root/.local/lib/python3.8/site-packages/tenacity/__init__.py", line 373, in iter
six.raise_from(retry_exc, fut.exception())
│ │ │ │ └ <function Future.exception at 0x7f7fa1fba550>
│ │ │ └ <Future at 0x7f7fa0672f70 state=finished raised ValueError>
│ │ └ RetryError(<Future at 0x7f7fa0672f70 state=finished raised ValueError>)
│ └ <function raise_from at 0x7f7fa0bd2790>
└ <module 'six' from '/root/.local/lib/python3.8/site-packages/six.py'>
File "<string>", line 3, in raise_from
tenacity.RetryError: RetryError[<Future at 0x7f7fa0672f70 state=finished raised ValueError>]
2021-08-23T17:43:35.858602+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO | Trying server - ws://opal_server:7002/ws
2021-08-23T17:43:35.869748+0000 |opal_client.policy.updater | INFO | Connected to server
2021-08-23T17:43:35.869938+0000 |opal_client.policy.updater | INFO | Refetching policy code (full bundle)
2021-08-23T17:43:35.892245+0000 |opal_client.policy.updater | INFO | got policy bundle, commit hash: 'c60470ef8046152a8498d81df0eff66ddd1632e2'
2021-08-23T17:43:35.893954+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41402', 'req_id': 5, 'req_method': 'GET', 'req_path': '/v1/policies', 'time': '2021-08-23T17:43:35Z'}
2021-08-23T17:43:35.894336+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41402', 'req_id': 5, 'req_method': 'GET', 'req_path': '/v1/policies', 'resp_bytes': 13, 'resp_duration': 0.153132, 'resp_status': 200, 'time': '2021-08-23T17:43:35Z'}
2021-08-23T17:43:35.896196+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41404', 'req_id': 6, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'time': '2021-08-23T17:43:35Z'}
2021-08-23T17:43:35.897293+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41404', 'req_id': 6, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'resp_bytes': 315, 'resp_duration': 1.059368, 'resp_status': 400, 'time': '2021-08-23T17:43:35Z'}
2021-08-23T17:43:37.901788+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41406', 'req_id': 7, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'time': '2021-08-23T17:43:37Z'}
2021-08-23T17:43:37.902706+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41406', 'req_id': 7, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'resp_bytes': 315, 'resp_duration': 0.967893, 'resp_status': 400, 'time': '2021-08-23T17:43:37Z'}
2021-08-23T17:43:37.903923+0000 |opal_client...base_policy_store_client |WARNING | OPA transaction failed, transaction id=c60470ef8046152a8498d81df0eff66ddd1632e2, actions=['set_policies'], error=RetryError(<Future at 0x7f7f9e60d9a0 state=finished raised ValueError>)
2021-08-23T17:43:37.904287+0000 |fastapi_websocket_rpc.websocket_rpc_c...|ERROR | RPC Error
Traceback (most recent call last):
File "/root/.local/lib/python3.8/site-packages/tenacity/_asyncio.py", line 45, in __call__
result = await fn(*args, **kwargs)
│ │ └ {'policy_id': 'rbac.rego', 'policy_code': '# Role-based Access Control (RBAC)\n# --------------------------------\n#\n# This ...
│ └ (<opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>,)
└ <function OpaClient.set_policy at 0x7f7fa0b1d940>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 173, in set_policy
return await proxy_response_unless_invalid(opa_response, accepted_status_codes=[status.HTTP_200_OK])
│ │ │ └ 200
│ │ └ <module 'starlette.status' from '/root/.local/lib/python3.8/site-packages/starlette/status.py'>
│ └ <ClientResponse(http://localhost:8181/v1/policies/rbac.rego) [400 Bad Request]>
│ <CIMultiDictProxy('Content-Type': 'applicatio...
└ <function proxy_response_unless_invalid at 0x7f7fa0b0cca0>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 54, in proxy_response_unless_invalid
raise ValueError("OPA Client: unexpected status code: {}, error: {}".format(response.status_code, error))
│ │ └ {'code': 'invalid_parameter', 'message': 'error(s) occurred while compiling module(s)', 'errors': [{'code': 'rego_type_error'...
│ └ 400
└ <starlette.responses.Response object at 0x7f7f9e60dd60>
ValueError: OPA Client: unexpected status code: 400, error: {'code': 'invalid_parameter', 'message': 'error(s) occurred while compiling module(s)', 'errors': [{'code': 'rego_type_error', 'message': 'undefined function data.utils.hasPermission', 'location': {'file': 'rbac.rego', 'row': 37, 'col': 2}}]}
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
File "/root/.local/bin/gunicorn", line 8, in <module>
sys.exit(run())
│ │ └ <function run at 0x7f7fa2b85940>
│ └ <built-in function exit>
└ <module 'sys' (built-in)>
File "/root/.local/lib/python3.8/site-packages/gunicorn/app/wsgiapp.py", line 67, in run
WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
└ <class 'gunicorn.app.wsgiapp.WSGIApplication'>
File "/root/.local/lib/python3.8/site-packages/gunicorn/app/base.py", line 231, in run
super().run()
File "/root/.local/lib/python3.8/site-packages/gunicorn/app/base.py", line 72, in run
Arbiter(self).run()
│ └ <gunicorn.app.wsgiapp.WSGIApplication object at 0x7f7fa2b5f820>
└ <class 'gunicorn.arbiter.Arbiter'>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 202, in run
self.manage_workers()
│ └ <function Arbiter.manage_workers at 0x7f7fa2494160>
└ <gunicorn.arbiter.Arbiter object at 0x7f7fa2b5f940>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
self.spawn_workers()
│ └ <function Arbiter.spawn_workers at 0x7f7fa2494280>
└ <gunicorn.arbiter.Arbiter object at 0x7f7fa2b5f940>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 622, in spawn_workers
self.spawn_worker()
│ └ <function Arbiter.spawn_worker at 0x7f7fa24941f0>
└ <gunicorn.arbiter.Arbiter object at 0x7f7fa2b5f940>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker
worker.init_process()
│ └ <function UvicornWorker.init_process at 0x7f7fa1b44b80>
└ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
File "/root/.local/lib/python3.8/site-packages/uvicorn/workers.py", line 64, in init_process
super(UvicornWorker, self).init_process()
│ └ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
└ <class 'uvicorn.workers.UvicornWorker'>
File "/root/.local/lib/python3.8/site-packages/gunicorn/workers/base.py", line 142, in init_process
self.run()
│ └ <function UvicornWorker.run at 0x7f7fa1b44ca0>
└ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
File "/root/.local/lib/python3.8/site-packages/uvicorn/workers.py", line 77, in run
loop.run_until_complete(server.serve(sockets=self.sockets))
│ │ │ │ │ └ [<gunicorn.sock.TCPSocket object at 0x7f7fa1b30f10>]
│ │ │ │ └ <uvicorn.workers.UvicornWorker object at 0x7f7fa1b34160>
│ │ │ └ <function Server.serve at 0x7f7fa1e1cc10>
│ │ └ <uvicorn.server.Server object at 0x7f7fa206b4f0>
│ └ <method 'run_until_complete' of 'uvloop.loop.Loop' objects>
└ <uvloop.Loop running=True closed=False debug=False>
> File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_rpc/websocket_rpc_client.py", line 127, in __connect__
await self.channel.on_connect()
│ │ └ <function RpcChannel.on_connect at 0x7f7fa0b46ee0>
│ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa063e4f0>
└ <fastapi_websocket_rpc.websocket_rpc_client.WebSocketRpcClient object at 0x7f7fa0690d60>
File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_rpc/rpc_channel.py", line 237, in on_connect
await self.on_handler_event(self._connect_handlers, self)
│ │ │ │ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa063e4f0>
│ │ │ └ [<bound method PubSubClient._primary_on_connect of <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa069...
│ │ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa063e4f0>
│ └ <function RpcChannel.on_handler_event at 0x7f7fa0b46e50>
└ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa063e4f0>
File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_rpc/rpc_channel.py", line 234, in on_handler_event
await asyncio.gather(*(callback(*args, **kwargs) for callback in handlers))
│ │ │ │ └ [<bound method PubSubClient._primary_on_connect of <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa069...
│ │ │ └ {}
│ │ └ (<fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa063e4f0>,)
│ └ <function gather at 0x7f7fa1eb5ca0>
└ <module 'asyncio' from '/usr/local/lib/python3.8/asyncio/__init__.py'>
File "/root/.local/lib/python3.8/site-packages/fastapi_websocket_pubsub/pub_sub_client.py", line 217, in _primary_on_connect
await asyncio.gather(*(callback(self, channel) for callback in self._on_connect))
│ │ │ │ │ └ [<bound method PolicyUpdater._on_connect of <opal_client.policy.updater.PolicyUpdater object at 0x7f7fa205f910>>]
│ │ │ │ └ <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa06907c0>
│ │ │ └ <fastapi_websocket_rpc.rpc_channel.RpcChannel object at 0x7f7fa063e4f0>
│ │ └ <fastapi_websocket_pubsub.pub_sub_client.PubSubClient object at 0x7f7fa06907c0>
│ └ <function gather at 0x7f7fa1eb5ca0>
└ <module 'asyncio' from '/usr/local/lib/python3.8/asyncio/__init__.py'>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy/updater.py", line 108, in _on_connect
await self.update_policy()
│ └ <function PolicyUpdater.update_policy at 0x7f7fa09f63a0>
└ <opal_client.policy.updater.PolicyUpdater object at 0x7f7fa205f910>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy/updater.py", line 214, in update_policy
await store_transaction.set_policies(bundle)
│ │ └ PolicyBundle(manifest=['data.json', 'rbac.rego', 'utils.rego'], hash='c60470ef8046152a8498d81df0eff66ddd1632e2', old_hash=Non...
│ └ <function AbstractPolicyStore.set_policies at 0x7f7fa0b02550>
└ <opal_client.policy_store.base_policy_store_client.PolicyStoreTransactionContextManager object at 0x7f7f9e60dbe0>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 256, in set_policies
return await self._set_policies_from_complete_bundle(bundle)
│ │ └ PolicyBundle(manifest=['data.json', 'rbac.rego', 'utils.rego'], hash='c60470ef8046152a8498d81df0eff66ddd1632e2', old_hash=Non...
│ └ <function OpaClient._set_policies_from_complete_bundle at 0x7f7fa0b22430>
└ <opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 268, in _set_policies_from_complete_bundle
await self.set_policy(policy_id=module.path, policy_code=module.rego)
│ │ │ │ │ └ '# Role-based Access Control (RBAC)\n# --------------------------------\n#\n# This example defines an RBAC model for a Pet St...
│ │ │ │ └ RegoModule(path='rbac.rego', package_name='app.rbac', rego='# Role-based Access Control (RBAC)\n# ---------------------------...
│ │ │ └ 'rbac.rego'
│ │ └ RegoModule(path='rbac.rego', package_name='app.rbac', rego='# Role-based Access Control (RBAC)\n# ---------------------------...
│ └ <function AsyncRetrying.wraps.<locals>.async_wrapped at 0x7f7fa0b1daf0>
└ <opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>
File "/root/.local/lib/python3.8/site-packages/tenacity/_asyncio.py", line 79, in async_wrapped
return await fn(*args, **kwargs)
│ │ └ {'policy_id': 'rbac.rego', 'policy_code': '# Role-based Access Control (RBAC)\n# --------------------------------\n#\n# This ...
│ └ (<opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>,)
└ <function OpaClient.set_policy at 0x7f7fa0b1d9d0>
File "/root/.local/lib/python3.8/site-packages/tenacity/_asyncio.py", line 42, in __call__
do = self.iter(retry_state=retry_state)
│ │ └ <tenacity.RetryCallState object at 0x7f7f9e60de80>
│ └ <function BaseRetrying.iter at 0x7f7fa0ac5c10>
└ <AsyncRetrying object at 0x7f7fa0b0ee80 (stop=<tenacity.stop.stop_after_attempt object at 0x7f7fa0b0ed30>, wait=<tenacity.wai...
File "/root/.local/lib/python3.8/site-packages/tenacity/__init__.py", line 373, in iter
six.raise_from(retry_exc, fut.exception())
│ │ │ │ └ <function Future.exception at 0x7f7fa1fba550>
│ │ │ └ <Future at 0x7f7f9e60d9a0 state=finished raised ValueError>
│ │ └ RetryError(<Future at 0x7f7f9e60d9a0 state=finished raised ValueError>)
│ └ <function raise_from at 0x7f7fa0bd2790>
└ <module 'six' from '/root/.local/lib/python3.8/site-packages/six.py'>
File "<string>", line 3, in raise_from
tenacity.RetryError: RetryError[<Future at 0x7f7f9e60d9a0 state=finished raised ValueError>]
2021-08-23T17:43:39.286038+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO | Trying server - ws://opal_server:7002/ws
2021-08-23T17:43:39.297423+0000 |opal_client.policy.updater | INFO | Connected to server
2021-08-23T17:43:39.297608+0000 |opal_client.policy.updater | INFO | Refetching policy code (full bundle)
2021-08-23T17:43:39.328751+0000 |opal_client.policy.updater | INFO | got policy bundle, commit hash: 'c60470ef8046152a8498d81df0eff66ddd1632e2'
2021-08-23T17:43:39.331631+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41412', 'req_id': 8, 'req_method': 'GET', 'req_path': '/v1/policies', 'time': '2021-08-23T17:43:39Z'}
2021-08-23T17:43:39.332070+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41412', 'req_id': 8, 'req_method': 'GET', 'req_path': '/v1/policies', 'resp_bytes': 13, 'resp_duration': 0.132113, 'resp_status': 200, 'time': '2021-08-23T17:43:39Z'}
2021-08-23T17:43:39.334898+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41414', 'req_id': 9, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'time': '2021-08-23T17:43:39Z'}
2021-08-23T17:43:39.336371+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41414', 'req_id': 9, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'resp_bytes': 315, 'resp_duration': 0.946037, 'resp_status': 400, 'time': '2021-08-23T17:43:39Z'}
2021-08-23T17:43:41.342537+0000 |opal_client.opa.logger | INFO | Received request. {'client_addr': '127.0.0.1:41416', 'req_id': 10, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'time': '2021-08-23T17:43:41Z'}
2021-08-23T17:43:41.344037+0000 |opal_client.opa.logger | INFO | Sent response. {'client_addr': '127.0.0.1:41416', 'req_id': 10, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'resp_bytes': 315, 'resp_duration': 1.443397, 'resp_status': 400, 'time': '2021-08-23T17:43:41Z'}
2021-08-23T17:43:41.345722+0000 |opal_client...base_policy_store_client |WARNING | OPA transaction failed, transaction id=c60470ef8046152a8498d81df0eff66ddd1632e2, actions=['set_policies'], error=RetryError(<Future at 0x7f7f9e58b640 state=finished raised ValueError>)
2021-08-23T17:43:41.346221+0000 |fastapi_websocket_rpc.websocket_rpc_c...|ERROR | RPC Error
Traceback (most recent call last):
File "/root/.local/lib/python3.8/site-packages/tenacity/_asyncio.py", line 45, in __call__
result = await fn(*args, **kwargs)
│ │ └ {'policy_id': 'rbac.rego', 'policy_code': '# Role-based Access Control (RBAC)\n# --------------------------------\n#\n# This ...
│ └ (<opal_client.policy_store.opa_client.OpaClient object at 0x7f7fa0deb4f0>,)
└ <function OpaClient.set_policy at 0x7f7fa0b1d940>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 173, in set_policy
return await proxy_response_unless_invalid(opa_response, accepted_status_codes=[status.HTTP_200_OK])
│ │ │ └ 200
│ │ └ <module 'starlette.status' from '/root/.local/lib/python3.8/site-packages/starlette/status.py'>
│ └ <ClientResponse(http://localhost:8181/v1/policies/rbac.rego) [400 Bad Request]>
│ <CIMultiDictProxy('Content-Type': 'applicatio...
└ <function proxy_response_unless_invalid at 0x7f7fa0b0cca0>
File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.11-py3.8.egg/opal_client/policy_store/opa_client.py", line 54, in proxy_response_unless_invalid
raise ValueError("OPA Client: unexpected status code: {}, error: {}".format(response.status_code, error))
│ │ └ {'code': 'invalid_parameter', 'message': 'error(s) occurred while compiling module(s)', 'errors': [{'code': 'rego_type_error'...
│ └ 400
└ <starlette.responses.Response object at 0x7f7f9e58bac0>