How to increase opal-client timeout limit when connecting database? #142

hongbo-miao · 2021-09-15T21:37:07Z

hongbo-miao
Sep 15, 2021

Hi OPAL team, I am wondering how to increase the timeout limit? Recently I switched from PostgreSQL to YugabyteDB.
YugabyteDB is a distributed SQL database which is compatible to PostgreSQL 11.2

I am using exact same db name, user, password. Only port changed from 5432 to 5433.

POSTGRES_PORT=5433
POSTGRES_DB=opa_db
POSTGRES_USER=admin
POSTGRES_PASSWORD=passw0rd

Also it has exactly same table and data like original PostgreSQL.

However, my opal-client now shows timeout.

opal-client log

[2021-09-15 21:26:08 +0000] [1] [INFO] Starting gunicorn 20.1.0
[2021-09-15 21:26:08 +0000] [1] [INFO] Listening at: http://0.0.0.0:7000 (1)
[2021-09-15 21:26:08 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornWorker
[2021-09-15 21:26:08 +0000] [9] [INFO] Booting worker with pid: 9
2021-09-15T21:26:09.755971+0000 |opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
2021-09-15T21:26:09.756388+0000 |opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
2021-09-15T21:26:09.799447+0000 |opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'PostgresFetchProvider' found at: <class 'opal_fetcher_postgres.provider.PostgresFetchProvider'>
2021-09-15T21:26:09.799725+0000 |opal_common.fetcher.fetcher_register    | INFO  | Fetcher Register loaded
2021-09-15T21:26:09.840520+0000 |opal_client.opa.runner                  | INFO  | Launching opa runner
2021-09-15T21:26:09.842725+0000 |opal_client.opa.runner                  | INFO  | Running OPA inline: opa run --server --addr=:8181 --authentication=off --authorization=off --config-file=/data/opa/config.yaml --log-level=info
2021-09-15T21:26:09.893981+0000 |opal_client.opa.logger                  | INFO  | Initializing server. {'addrs': [':8181'], 'diagnostic-addrs': [], 'time': '2021-09-15T21:26:09Z'}
2021-09-15T21:26:09.896708+0000 |opal_client.opa.logger                  | INFO  | Starting decision logger. {'plugin': 'decision_logs', 'time': '2021-09-15T21:26:09Z'}
2021-09-15T21:26:10.852670+0000 |opal_client.opa.runner                  | INFO  | Running OPA initial start callbacks
2021-09-15T21:26:10.854044+0000 |opal_client.data.updater                | INFO  | Launching data updater
2021-09-15T21:26:10.855069+0000 |opal_client.policy.updater              | INFO  | Launching policy updater
2021-09-15T21:26:10.855430+0000 |opal_client.data.updater                | INFO  | Subscribing to topics: ['policy_data']
2021-09-15T21:26:10.856392+0000 |opal_client.policy.updater              | INFO  | Subscribing to topics: ['policy:.']
2021-09-15T21:26:10.857380+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - ws://opal-server-service.hm-opa:7002/ws
2021-09-15T21:26:10.858479+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - ws://opal-server-service.hm-opa:7002/ws
2021-09-15T21:26:10.864488+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - ws://opal-server-service.hm-opa:7002/ws
2021-09-15T21:26:10.866010+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - ws://opal-server-service.hm-opa:7002/ws
2021-09-15T21:26:10.937717+0000 |opal_client.data.updater                | INFO  | Connected to server
2021-09-15T21:26:10.937891+0000 |opal_client.data.updater                | INFO  | Performing data configuration, reason: Initial load
2021-09-15T21:26:10.938040+0000 |opal_client.data.updater                | INFO  | Getting data-sources configuration from 'http://opal-server-service.hm-opa:7002/data/config'
2021-09-15T21:26:10.968952+0000 |opal_client.data.updater                | INFO  | Triggering data update with id: 5c8138ff970b450eab93df9e60e6efa6
2021-09-15T21:26:10.969518+0000 |opal_client.data.updater                | INFO  | Fetching policy data
2021-09-15T21:26:10.969904+0000 |opal_client.data.fetcher                | INFO  | Fetching data from url: postgresql://admin@yb-tservers.yb-operator:5433/opa_db
2021-09-15T21:26:11.009596+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Connected to PubSub server ws://opal-server-service.hm-opa:7002/ws
2021-09-15T21:26:11.029729+0000 |opal_client.policy.updater              | INFO  | Connected to server
2021-09-15T21:26:11.030896+0000 |opal_client.policy.updater              | INFO  | Refetching policy code (full bundle)
2021-09-15T21:26:11.135367+0000 |opal_client.policy.updater              | INFO  | got policy bundle, commit hash: '910d43e7e4da262d838c562ce3ae9910600fe445'
2021-09-15T21:26:11.140549+0000 |opal_client.opa.logger                  | INFO  | Received request.    {'client_addr': '[::1]:48238', 'req_id': 1, 'req_method': 'GET', 'req_path': '/v1/policies', 'time': '2021-09-15T21:26:11Z'}
2021-09-15T21:26:11.141845+0000 |opal_client.opa.logger                  | INFO  | Sent response.       {'client_addr': '[::1]:48238', 'req_id': 1, 'req_method': 'GET', 'req_path': '/v1/policies', 'resp_bytes': 13, 'resp_duration': 0.861539, 'resp_status': 200, 'time': '2021-09-15T21:26:11Z'}
2021-09-15T21:26:11.145842+0000 |opal_client.opa.logger                  | INFO  | Received request.    {'client_addr': '[::1]:48240', 'req_id': 2, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'time': '2021-09-15T21:26:11Z'}
2021-09-15T21:26:11.153508+0000 |opal_client.opa.logger                  | INFO  | Sent response.       {'client_addr': '[::1]:48240', 'req_id': 2, 'req_method': 'PUT', 'req_path': '/v1/policies/rbac.rego', 'resp_bytes': 2, 'resp_duration': 5.756797, 'resp_status': 200, 'time': '2021-09-15T21:26:11Z'}
2021-09-15T21:26:11.156706+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Connected to PubSub server ws://opal-server-service.hm-opa:7002/ws
2021-09-15T21:26:11.403212+0000 |opal_common.fetcher.engine.fetch_worker |ERROR  | Failed to process fetch event
Traceback (most recent call last):

File "/root/.local/bin/gunicorn", line 8, in <module>
  sys.exit(run())
  │   │    └ <function run at 0x7fa8b7cf7820>
  │   └ <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 0x7fa8b7dbe460>
  └ <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 0x7fa8b76070d0>
  └ <gunicorn.arbiter.Arbiter object at 0x7fa8b7dbe550>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
  self.spawn_workers()
  │    └ <function Arbiter.spawn_workers at 0x7fa8b76071f0>
  └ <gunicorn.arbiter.Arbiter object at 0x7fa8b7dbe550>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 622, in spawn_workers
  self.spawn_worker()
  │    └ <function Arbiter.spawn_worker at 0x7fa8b7607160>
  └ <gunicorn.arbiter.Arbiter object at 0x7fa8b7dbe550>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker
  worker.init_process()
  │      └ <function UvicornWorker.init_process at 0x7fa8b7058a60>
  └ <uvicorn.workers.UvicornWorker object at 0x7fa8b6fa9880>
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 0x7fa8b6fa9880>
        └ <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 0x7fa8b7058b80>
  └ <uvicorn.workers.UvicornWorker object at 0x7fa8b6fa9880>
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 0x7fa8b6cdda90>]
  │    │                  │      │             └ <uvicorn.workers.UvicornWorker object at 0x7fa8b6fa9880>
  │    │                  │      └ <function Server.serve at 0x7fa8b70edaf0>
  │    │                  └ <uvicorn.server.Server object at 0x7fa8b6cc06d0>
  │    └ <method 'run_until_complete' of 'uvloop.loop.Loop' objects>
  └ <uvloop.Loop running=True closed=False debug=False>
> File "/usr/local/lib/python3.8/site-packages/opal_common-0.1.13-py3.8.egg/opal_common/fetcher/engine/fetch_worker.py", line 32, in fetch_worker
  async with fetcher:
             └ <opal_fetcher_postgres.provider.PostgresFetchProvider object at 0x7fa8b57a1eb0>

File "/usr/src/app/opal_fetcher_postgres/provider.py", line 71, in __aenter__
  self._connection: asyncpg.Connection = await asyncpg.connect(
  │    │            │       │                  │       └ <function connect at 0x7fa8b5b74430>
  │    │            │       │                  └ <module 'asyncpg' from '/root/.local/lib/python3.8/site-packages/asyncpg/__init__.py'>
  │    │            │       └ <class 'asyncpg.connection.Connection'>
  │    │            └ <module 'asyncpg' from '/root/.local/lib/python3.8/site-packages/asyncpg/__init__.py'>
  │    └ None
  └ <opal_fetcher_postgres.provider.PostgresFetchProvider object at 0x7fa8b57a1eb0>

File "/root/.local/lib/python3.8/site-packages/asyncpg/connection.py", line 1981, in connect
  return await connect_utils._connect(
               │             └ <function _connect at 0x7fa8b5a5f9d0>
               └ <module 'asyncpg.connect_utils' from '/root/.local/lib/python3.8/site-packages/asyncpg/connect_utils.py'>
File "/root/.local/lib/python3.8/site-packages/asyncpg/connect_utils.py", line 732, in _connect
  con = await _connect_addr(
              └ <function _connect_addr at 0x7fa8b5a5f8b0>
File "/root/.local/lib/python3.8/site-packages/asyncpg/connect_utils.py", line 632, in _connect_addr
  return await __connect_addr(params, timeout, True, *args)
               │              │       │               └ (('yb-tservers.yb-operator', 5433), <uvloop.Loop running=True closed=False debug=False>, ConnectionConfiguration(command_time...
               │              │       └ 60
               │              └ ConnectionParameters(user='admin', password='passw0rd', database='opa_db', ssl=<ssl.SSLContext object at 0x7fa8b37631c0>, ssl...
               └ <function __connect_addr at 0x7fa8b5a5f940>
File "/root/.local/lib/python3.8/site-packages/asyncpg/connect_utils.py", line 716, in __connect_addr
  con = connection_class(pr, tr, loop, addr, config, params_input)
        │                │   │   │     │     │       └ ConnectionParameters(user='admin', password='passw0rd', database='opa_db', ssl=<ssl.SSLContext object at 0x7fa8b37631c0>, ssl...
        │                │   │   │     │     └ ConnectionConfiguration(command_timeout=None, statement_cache_size=100, max_cached_statement_lifetime=300, max_cacheable_stat...
        │                │   │   │     └ ('yb-tservers.yb-operator', 5433)
        │                │   │   └ <uvloop.Loop running=True closed=False debug=False>
        │                │   └ <TCPTransport closed=False reading=True 0x5631d905c0f0>
        │                └ <asyncpg.protocol.protocol.Protocol object at 0x7fa8b5b819e0>
        └ <class 'asyncpg.connection.Connection'>
File "/root/.local/lib/python3.8/site-packages/asyncpg/connection.py", line 86, in __init__
  serverversion.split_server_version_string(ver_string)
  │             │                           └ '11.2-YB-2.7.0.0-b0'
  │             └ <function split_server_version_string at 0x7fa8b5a6e280>
  └ <module 'asyncpg.serverversion' from '/root/.local/lib/python3.8/site-packages/asyncpg/serverversion.py'>
File "/root/.local/lib/python3.8/site-packages/asyncpg/serverversion.py", line 50, in split_server_version_string
  versions = [int(p) for p in parts][:3]
                              └ ['11', 0, '2-YB-2', '7', '0', '0']
File "/root/.local/lib/python3.8/site-packages/asyncpg/serverversion.py", line 50, in <listcomp>
  versions = [int(p) for p in parts][:3]
                  │      └ '2-YB-2'
                  └ '2-YB-2'

ValueError: invalid literal for int() with base 10: '2-YB-2'
2021-09-15T21:26:21.011380+0000 |opal_client.data.fetcher                |ERROR  | Timeout while fetching url: postgresql://admin@yb-tservers.yb-operator:5433/opa_db
Traceback (most recent call last):

File "/root/.local/bin/gunicorn", line 8, in <module>
  sys.exit(run())
  │   │    └ <function run at 0x7fa8b7cf7820>
  │   └ <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 0x7fa8b7dbe460>
  └ <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 0x7fa8b76070d0>
  └ <gunicorn.arbiter.Arbiter object at 0x7fa8b7dbe550>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
  self.spawn_workers()
  │    └ <function Arbiter.spawn_workers at 0x7fa8b76071f0>
  └ <gunicorn.arbiter.Arbiter object at 0x7fa8b7dbe550>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 622, in spawn_workers
  self.spawn_worker()
  │    └ <function Arbiter.spawn_worker at 0x7fa8b7607160>
  └ <gunicorn.arbiter.Arbiter object at 0x7fa8b7dbe550>
File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker
  worker.init_process()
  │      └ <function UvicornWorker.init_process at 0x7fa8b7058a60>
  └ <uvicorn.workers.UvicornWorker object at 0x7fa8b6fa9880>
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 0x7fa8b6fa9880>
        └ <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 0x7fa8b7058b80>
  └ <uvicorn.workers.UvicornWorker object at 0x7fa8b6fa9880>
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 0x7fa8b6cdda90>]
  │    │                  │      │             └ <uvicorn.workers.UvicornWorker object at 0x7fa8b6fa9880>
  │    │                  │      └ <function Server.serve at 0x7fa8b70edaf0>
  │    │                  └ <uvicorn.server.Server object at 0x7fa8b6cc06d0>
  │    └ <method 'run_until_complete' of 'uvloop.loop.Loop' objects>
  └ <uvloop.Loop running=True closed=False debug=False>
> File "/usr/local/lib/python3.8/site-packages/opal_client-0.1.13-py3.8.egg/opal_client/data/fetcher.py", line 63, in handle_url
  response = await self._engine.handle_url(url, config=config)
                   │    │       │          │           └ {'fetcher': 'PostgresFetchProvider', 'query': 'select role, allow from roles;', 'connection_params': {'password': 'passw0rd'}...
                   │    │       │          └ 'postgresql://admin@yb-tservers.yb-operator:5433/opa_db'
                   │    │       └ <function FetchingEngine.handle_url at 0x7fa8b5c3e040>
                   │    └ <opal_common.fetcher.engine.fetching_engine.FetchingEngine object at 0x7fa8b5b5a7f0>
                   └ <opal_client.data.fetcher.DataFetcher object at 0x7fa8b5b5a7c0>
File "/usr/local/lib/python3.8/site-packages/opal_common-0.1.13-py3.8.egg/opal_common/fetcher/engine/fetching_engine.py", line 104, in handle_url
  await asyncio.wait_for(wait_event.wait(), timeout)
        │       │        │          │       └ 10
        │       │        │          └ <function Event.wait at 0x7fa8b7172e50>
        │       │        └ <asyncio.locks.Event object at 0x7fa8b57d71f0 [unset]>
        │       └ <function wait_for at 0x7fa8b7154940>
        └ <module 'asyncio' from '/usr/local/lib/python3.8/asyncio/__init__.py'>
File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
  raise exceptions.TimeoutError()
        │          └ <class 'asyncio.exceptions.TimeoutError'>
        └ <module 'asyncio.exceptions' from '/usr/local/lib/python3.8/asyncio/exceptions.py'>

asyncio.exceptions.TimeoutError
2021-09-15T21:26:21.014992+0000 |opal_client.data.updater                |ERROR  | Failed to fetch url postgresql://admin@yb-tservers.yb-operator:5433/opa_db, got exception:

I am guessing query in YugabyteDB might be a little bit slow which causes opal-client timeout issue.
Is there a way to increase timeout limit? Thanks!

Answered by orweis

Sep 16, 2021

Hi @hongbo-miao - I'm afraid the configuration values for the timeouts are not exposed yet to env-variables.
(They are found as consts in 'opal_common/fetcher/engine/fetching_engine.py')

I've created a pull-request to expose these - https://github.com/authorizon/opal/pull/143
After which you'll be able to set 'OPAL_FETCHING_CALLBACK_TIMEOUT' to the number of seconds you'd like.

Meanwhile you can (if you're in a rush) edit 'fetching_engine.py' and change the const value of 'DEFAULT_CALLBACK_TIMEOUT'

In addition , @asafc - we should consider allowing the fetcher, and maybe even the fetch-event to control the timeout as well - so it will be even more dynamic.

View full answer

orweis · 2021-09-16T06:56:43Z

orweis
Sep 16, 2021
Maintainer

Hi @hongbo-miao - I'm afraid the configuration values for the timeouts are not exposed yet to env-variables.
(They are found as consts in 'opal_common/fetcher/engine/fetching_engine.py')

I've created a pull-request to expose these - https://github.com/authorizon/opal/pull/143
After which you'll be able to set 'OPAL_FETCHING_CALLBACK_TIMEOUT' to the number of seconds you'd like.

Meanwhile you can (if you're in a rush) edit 'fetching_engine.py' and change the const value of 'DEFAULT_CALLBACK_TIMEOUT'

In addition , @asafc - we should consider allowing the fetcher, and maybe even the fetch-event to control the timeout as well - so it will be even more dynamic.

4 replies

asafc Sep 16, 2021

I think this should indeed be a fetcher config value.

@hongbo-miao, i think i can work on a new release with a fix tomorrow - please let me know if it works for you.

hongbo-miao Sep 16, 2021
Author

Hi @asafc This one is not urgent, take your time. Appreciate! 😃

hongbo-miao Oct 18, 2021
Author

Hi team, I saw https://github.com/authorizon/opal/pull/143 got merged.
Are the new flags are OPAL_DEFAULT_ENQUEUE_TIMEOUT and OPAL_DEFAULT_CALLBACK_TIMEOUT.
Do we need pass to opal-client and/or opal-server? Thanks!

asafc Oct 18, 2021

Hi team, I saw https://github.com/authorizon/opal/pull/143 got merged.

Are the new flags are OPAL_DEFAULT_ENQUEUE_TIMEOUT and OPAL_DEFAULT_CALLBACK_TIMEOUT.

Do we need pass to opal-client and/or opal-server? Thanks!

These are opal client flags :)

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

How to increase opal-client timeout limit when connecting database? #142

{{title}}

{{editor}}'s edit

{{editor}}'s edit

Replies: 1 comment 4 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

Select a reply

How to increase opal-client timeout limit when connecting database? #142

hongbo-miao Sep 15, 2021

Replies: 1 comment · 4 replies

orweis Sep 16, 2021 Maintainer

asafc Sep 16, 2021

hongbo-miao Sep 16, 2021 Author

hongbo-miao Oct 18, 2021 Author

asafc Oct 18, 2021

hongbo-miao
Sep 15, 2021

Replies: 1 comment 4 replies

orweis
Sep 16, 2021
Maintainer

hongbo-miao Sep 16, 2021
Author

hongbo-miao Oct 18, 2021
Author