https://linen.dev logo
Join Slack
Powered by
This message was deleted.
# opal
s
This message was deleted.
👀 1
o
Hi @Thilak Reddy, great question, let me check this out and get back to you.
Can you share your logs from opal client and opal server?
t
sure server logs
Copy code
2023-09-07 10:44:24.736 | WARNING  | __config__:when_ready:34 - Finished pre loading scopes...
[2023-09-07 10:44:24 +0000] [10] [INFO] Booting worker with pid: 10
2023-09-07T10:44:24.837680+0000 | opal_server.server                      | INFO  | OPAL is running in secure mode - will verify API requests with JWT tokens.
2023-09-07T10:44:24.838207+0000 | opal_server.pubsub                      | INFO  | Pub/Sub broadcaster is off
2023-09-07T10:44:24.891179+0000 | opal_server.server                      | INFO  | *** OPAL Server Startup ***
2023-09-07T10:44:24.891501+0000 | opal_server.server                      | INFO  | leadership lock acquired, leader pid: 10
2023-09-07T10:44:24.892151+0000 | opal_server.data.data_update_publisher  | INFO  | [10] Starting Polling Updates
2023-09-07T10:44:34.961023+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.13.110:47242 - "GET /healthcheck HTTP/1.1" 200
2023-09-07T10:44:41.544773+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.12.90:63668 - "GET / HTTP/1.1" 200
2023-09-07T10:44:42.137017+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.11.187:8438 - "GET / HTTP/1.1" 200
2023-09-07T10:44:46.958924+0000 | fastapi_websocket_rpc.websocket_rpc_e...| INFO  | Client connected
2023-09-07T10:44:46.962396+0000 | websockets.legacy.server                | INFO  | connection open
2023-09-07T10:44:46.967975+0000 | fastapi_websocket_pubsub.event_notifier | INFO  | New subscription {'id': 'a4679d3f7a42463aba21f3f440ee3fa5', 'subscriber_id': '8139e19dff8c4140bd4524e541f15056', 'topic': 'policy:.', 'callback': <function RpcEventServerMethods.subscribe.<locals>.callback at 0x7fe9e30c68c0>, 'notifier_id': None}
2023-09-07T10:44:46.973829+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.14.232:39960 - "GET /policy?path=. HTTP/1.1" 503
client logs
Copy code
[2023-09-07 11:10:10 +0000] [1] [INFO] Starting gunicorn 20.1.0
[2023-09-07 11:10:10 +0000] [1] [INFO] Listening at: <http://0.0.0.0:7000> (1)
[2023-09-07 11:10:10 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2023-09-07 11:10:10 +0000] [7] [INFO] Booting worker with pid: 7
2023-09-07T11:10:11.185955+0000 | opal_client.policy_store.opa_client     | INFO  | Authentication mode for policy store: PolicyStoreAuth.NONE
2023-09-07T11:10:11.187529+0000 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
2023-09-07T11:10:11.187632+0000 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
2023-09-07T11:10:11.187696+0000 | opal_common.fetcher.fetcher_register    | INFO  | Fetcher Register loaded
2023-09-07T11:10:11.187899+0000 | opal_client.callbacks.register          | INFO  | Callbacks register loaded
2023-09-07T11:10:11.188081+0000 | opal_client.client                      | INFO  | API authentication disabled (public encryption key was not provided)
2023-09-07T11:10:11.204788+0000 | opal_client.engine.runner               | INFO  | Launching engine runner
2023-09-07T11:10:11.206108+0000 | opal_client.engine.runner               | INFO  | Running policy engine inline: opa run --server --addr=:8181 --authentication=off --authorization=off --log-level=info
2023-09-07T11:10:12.209273+0000 | opal_client.engine.runner               | INFO  | Running policy engine initial start callbacks
2023-09-07T11:10:12.209958+0000 | opal_client.policy_store.opa_client     | INFO  | OPA client health: False (policy: False, data: False)
2023-09-07T11:10:12.210049+0000 | opal_client.policy_store.opa_client     | INFO  | persisting health check policy: ready=False, healthy=False
2023-09-07T11:10:12.210110+0000 | opal_client.policy_store.opa_client     | INFO  | Policy and data statistics: policy: (successful 0, failed 0);	data: (successful 0, failed 0)
2023-09-07T11:10:12.210165+0000 | opal_client.policy_store.opa_client     | INFO  | OPA client health: False (policy: False, data: False)
2023-09-07T11:10:12.210550+0000 | opal_client.policy_store.opa_client     | INFO  | Ignoring setting policy - engine/healthcheck/opal.rego, set in POLICY_PATHS_TO_IGNORE.
2023-09-07T11:10:12.210818+0000 | opal_client.data.updater                | INFO  | Launching data updater
2023-09-07T11:10:12.210936+0000 | opal_client.policy.updater              | INFO  | Launching policy updater
2023-09-07T11:10:12.210999+0000 | opal_client.data.updater                | INFO  | Subscribing to topics: ['policy_data']
2023-09-07T11:10:12.211153+0000 | opal_client.policy.updater              | INFO  | Subscribing to topics: ['policy:.']
2023-09-07T11:10:12.211325+0000 | fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - <ws://opal-opal-server-opal-server:7002/ws>
2023-09-07T11:10:12.211551+0000 | fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - <ws://opal-opal-server-opal-server:7002/ws>
2023-09-07T11:10:12.213053+0000 | fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - <ws://opal-opal-server-opal-server:7002/ws>
2023-09-07T11:10:12.213221+0000 | fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - <ws://opal-opal-server-opal-server:7002/ws>
2023-09-07T11:10:12.229765+0000 | opal_client.policy.updater              | INFO  | Connected to server
2023-09-07T11:10:12.229961+0000 | opal_client.policy.updater              | INFO  | Refetching policy code (full bundle)
2023-09-07T11:10:12.230213+0000 | opal_client.policy.fetcher              | INFO  | Fetching policy bundle from <http://opal-opal-server-opal-server:7002/policy>
2023-09-07T11:10:12.231196+0000 | opal_client.data.updater                | INFO  | Connected to server
2023-09-07T11:10:12.231278+0000 | opal_client.data.updater                | INFO  | Performing data configuration, reason: Initial load
2023-09-07T11:10:12.231336+0000 | opal_client.data.updater                | INFO  | Getting data-sources configuration from '<http://opal-opal-server-opal-server:7002/data/config>'
2023-09-07T11:10:12.236469+0000 | opal_common.utils                       |WARNING | Unexpected response code 503: {'detail': 'policy repo was not found'}
2023-09-07T11:10:12.236853+0000 | opal_client.data.updater                | INFO  | Triggering data update with id: 052b5ec52f8241f48b2e59433a9fd971
2023-09-07T11:10:12.237110+0000 | opal_client.data.updater                | INFO  | Fetching policy data
2023-09-07T11:10:12.237213+0000 | opal_client.data.fetcher                | INFO  | Fetching data from url: https://<our-api-server>
2023-09-07T11:10:12.239744+0000 | fastapi_websocket_pubsub.pub_sub_client | INFO  | Connected to PubSub server <ws://opal-opal-server-opal-server:7002/ws>
2023-09-07T11:10:12.622635+0000 | opal_client.policy.fetcher              | INFO  | Fetching policy bundle from <http://opal-opal-server-opal-server:7002/policy>
2023-09-07T11:10:12.627486+0000 | opal_common.utils                       |WARNING | Unexpected response code 503: {'detail': 'policy repo was not found'}
o
Hey @Thilak Reddy, are there any more logs from the server?
t
nope, rest of the logs are basically health check, new subscription from client(my client pod keeps restarting due to health check failure) and /policy endpoint calls only
o
Can you restart your OPAL server and show as the logs from the beginning until OPAL client connection?
t
sure
Copy code
[2023-09-07 11:27:23 +0000] [1] [INFO] Starting gunicorn 20.1.0
[2023-09-07 11:27:23 +0000] [1] [INFO] Listening at: <http://0.0.0.0:7002> (1)
[2023-09-07 11:27:23 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornWorker
2023-09-07 11:27:24.460 | WARNING  | __config__:when_ready:34 - Finished pre loading scopes...
[2023-09-07 11:27:24 +0000] [9] [INFO] Booting worker with pid: 9
2023-09-07T11:27:24.563772+0000 | opal_server.server                      | INFO  | OPAL is running in secure mode - will verify API requests with JWT tokens.
2023-09-07T11:27:24.564278+0000 | opal_server.pubsub                      | INFO  | Pub/Sub broadcaster is off
2023-09-07T11:27:24.611983+0000 | opal_server.server                      | INFO  | *** OPAL Server Startup ***
2023-09-07T11:27:24.612241+0000 | opal_server.server                      | INFO  | leadership lock acquired, leader pid: 9
2023-09-07T11:27:24.612799+0000 | opal_server.data.data_update_publisher  | INFO  | [9] Starting Polling Updates
2023-09-07T11:27:37.673201+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.13.110:35028 - "GET /healthcheck HTTP/1.1" 200
2023-09-07T11:27:45.571357+0000 | fastapi_websocket_rpc.websocket_rpc_e...| INFO  | Client connected
2023-09-07T11:27:45.574216+0000 | websockets.legacy.server                | INFO  | connection open
2023-09-07T11:27:45.580670+0000 | fastapi_websocket_pubsub.event_notifier | INFO  | New subscription {'id': '5d1018b3afe8457b8ce0f726c0a8a13b', 'subscriber_id': 'e19c5a494a074227bf16202ce8bac8e7', 'topic': 'policy:.', 'callback': <function RpcEventServerMethods.subscribe.<locals>.callback at 0x7f7ddb60a680>, 'notifier_id': None}
2023-09-07T11:27:45.587878+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.13.27:38074 - "GET /policy?path=. HTTP/1.1" 503
2023-09-07T11:27:45.631805+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.13.27:38080 - "GET /policy?path=. HTTP/1.1" 503
2023-09-07T11:27:46.003718+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.13.27:38088 - "GET /policy?path=. HTTP/1.1" 503
2023-09-07T11:27:47.072611+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.13.27:38104 - "GET /policy?path=. HTTP/1.1" 503
2023-09-07T11:27:49.664794+0000 | uvicorn.protocols.http.httptools_impl   | INFO  | 10.59.12.90:28710 - "GET / HTTP/1.1" 200
same logs as above though
my server image is custom built without any changes, custom built cause i wanted a change but new OPAL images haven’t been published yet but don’t think that should cause any problems, right?
o
A good way to test would be to try the default server and see if it is working, can you try this?
Anyway we will take another look on the logs and try to understand the issue
t
hm, let me try with default image and see if that works
o
Please also verify your env variables
t
any variables in particular?
o
Especially OPAL_POLICY_REPO_URL and other git related vars if you have
👍 1
t
so using the default image works fine, i see these logs which were missing from the above ones (when i used custom image)
Copy code
2023-09-07T11:52:41.953310+0000 | opal_server.policy.watcher.task         | INFO  | Launching policy watcher
2023-09-07T11:52:41.953585+0000 | opal_server.data.data_update_publisher  | INFO  | [9] Starting Polling Updates
2023-09-07T11:52:41.953667+0000 | opal_server.policy.watcher.task         | INFO  | listening on webhook topic: 'webhook'
2023-09-07T11:52:41.953841+0000 | fastapi_websocket_pubsub.event_notifier | INFO  | New subscription {'id': '7791a450dd4a47639d0f390fd4b0496d', 'subscriber_id': 'c39fbb296ee64babb82c3b08236943f0', 'topic': 'webhook', 'callback': <bound method BasePolicyWatcherTask._on_webhook of <opal_server.policy.watcher.task.PolicyWatcherTask object at 0x7ff0d656e2f0>>, 'notifier_id': None}
2023-09-07T11:52:41.954688+0000 | opal_common.git.repo_cloner             | INFO  | Cloning repo from '<https://github.com/thilak009/opal-policy-store-test>' to '/opal/regoclone/opal_repo_clone' (branch: 'main')
2023-09-07T11:52:43.010878+0000 | opal_common.git.repo_cloner             | INFO  | Clone succeeded
2023-09-07T11:52:43.014323+0000 | opal_common.sources.base_policy_source  | INFO  | Polling task is off
in this i can see logs around cloning the repo I will build my image fresh again (i built the last one a while back) and try it out, will let you know if i face any issues after that Thanks @Oded Bd
r
HI @Thilak Reddy, Have you disabled 
OPAL_REPO_WATCHER_ENABLED
?
You are trying to use 
opal
only for pushing data (managing policy outside of opal), right? Take a look at that recently merged PR - introduced a flag for disabling policy updates in client, thus not requiring any ugly hacks on server to prevent policy pushes…
You should be able to use 
OPAL_POLICY_UPDATER_ENABLED=false
on client 🙂
t
Have you disabled 
OPAL_REPO_WATCHER_ENABLED
?
don’t think so, but can’t guarantee if my shell had some env variables loaded when i built my image(was playing around testing stuff), so will get back after i build and use a fresh image
You should be able to use 
OPAL_POLICY_UPDATER_ENABLED=false
on client
yup i was the one who contributed the change lol so i should set 
OPAL_REPO_WATCHER_ENABLED=false
on server and 
OPAL_POLICY_UPDATER_ENABLED=false
on client and that should eliminate the hacky way i am using for not syncing policy right?
r
@Thilak Reddy Haha sorry, Wasn’t focused. Yeah I did felt like this use case sounds familiar 😜 I think that the combination you’ve just mentioned should work - Wasn’t it the purpose behind your PR to begin with?
t
haha, yeah 😂, i ended up mixing some old configs for a deployment with new images, my bad
2 Views
Open in Slack
PreviousNext
Powered by