search

permitio / opal-fetcher-postgres

An OPAL custom data fetcher to bring authorization state from Postgres
https://opal.ac
Apache License 2.0
20 stars 20 forks source link

opal client error #5

Closed hongbo-miao closed 2 years ago

hongbo-miao commented 2 years ago

Hi OPAL team, hmm, I started to get this error today for this repo. Any idea? Thanks!

➜ docker-compose up

[+] Building 13.2s (10/10) FINISHED
 => [internal] load build definition from Dockerfile                                                                                                                                                                                                     0.0s
 => => transferring dockerfile: 31B                                                                                                                                                                                                                      0.0s
 => [internal] load .dockerignore                                                                                                                                                                                                                        0.0s
 => => transferring context: 2B                                                                                                                                                                                                                          0.0s
 => [internal] load metadata for docker.io/authorizon/opal-client:latest                                                                                                                                                                                 3.2s
 => [1/5] FROM docker.io/authorizon/opal-client:latest@sha256:1da4cc56616d777cef36d26de4d82916fc392afeba2aae5519afea19c7dccbcf                                                                                                                           0.0s
 => [internal] load build context                                                                                                                                                                                                                        0.1s
 => => transferring context: 1.30MB                                                                                                                                                                                                                      0.1s
 => CACHED [2/5] WORKDIR /app/                                                                                                                                                                                                                           0.0s
 => [3/5] COPY . ./                                                                                                                                                                                                                                      0.1s
 => [4/5] RUN python setup.py install                                                                                                                                                                                                                    1.5s
 => [5/5] RUN pip install wait-for-it                                                                                                                                                                                                                    8.1s
 => exporting to image                                                                                                                                                                                                                                   0.1s
 => => exporting layers                                                                                                                                                                                                                                  0.1s
 => => writing image sha256:4b5659aa6f2b54c312ba3b93c55bc0d3c509181ef872aff0847ab07c2d7ba52b                                                                                                                                                             0.0s
 => => naming to docker.io/library/opal-fetcher-postgres_opal_client                                                                                                                                                                                     0.0s

Use 'docker scan' to run Snyk tests against images to find vulnerabilities and learn how to fix them
[+] Running 4/4
 ⠿ Container opal-fetcher-postgres_broadcast_channel_1  Created                                                                                                                                                                                          0.0s
 ⠿ Container opal-fetcher-postgres_example_db_1         Created                                                                                                                                                                                          0.0s
 ⠿ Container opal-fetcher-postgres_opal_server_1        Created                                                                                                                                                                                          0.0s
 ⠿ Container opal-fetcher-postgres_opal_client_1        Recreated                                                                                                                                                                                        0.1s
Attaching to broadcast_channel_1, example_db_1, opal_client_1, opal_server_1
broadcast_channel_1  |
broadcast_channel_1  | PostgreSQL Database directory appears to contain a database; Skipping initialization
broadcast_channel_1  |
broadcast_channel_1  | 2021-09-09 17:30:19.918 UTC [1] LOG:  starting PostgreSQL 13.4 on x86_64-pc-linux-musl, compiled by gcc (Alpine 10.3.1_git20210424) 10.3.1 20210424, 64-bit
broadcast_channel_1  | 2021-09-09 17:30:19.918 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
broadcast_channel_1  | 2021-09-09 17:30:19.918 UTC [1] LOG:  listening on IPv6 address "::", port 5432
broadcast_channel_1  | 2021-09-09 17:30:19.921 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
broadcast_channel_1  | 2021-09-09 17:30:19.924 UTC [21] LOG:  database system was shut down at 2021-09-09 17:29:57 UTC
broadcast_channel_1  | 2021-09-09 17:30:19.937 UTC [1] LOG:  database system is ready to accept connections
example_db_1         |
example_db_1         | PostgreSQL Database directory appears to contain a database; Skipping initialization
example_db_1         |
example_db_1         | 2021-09-09 17:30:20.076 UTC [1] LOG:  starting PostgreSQL 13.4 (Debian 13.4-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
example_db_1         | 2021-09-09 17:30:20.076 UTC [1] LOG:  listening on IPv4 address "0.0.0.0", port 5432
example_db_1         | 2021-09-09 17:30:20.076 UTC [1] LOG:  listening on IPv6 address "::", port 5432
example_db_1         | 2021-09-09 17:30:20.079 UTC [1] LOG:  listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
example_db_1         | 2021-09-09 17:30:20.084 UTC [27] LOG:  database system was shut down at 2021-09-09 17:29:57 UTC
example_db_1         | 2021-09-09 17:30:20.090 UTC [1] LOG:  database system is ready to accept connections
opal_server_1        | [2021-09-09 17:30:21 +0000] [1] [INFO] Starting gunicorn 20.1.0
opal_server_1        | [2021-09-09 17:30:21 +0000] [1] [INFO] Listening at: http://0.0.0.0:7002 (1)
opal_server_1        | [2021-09-09 17:30:21 +0000] [1] [INFO] Using worker: uvicorn.workers.UvicornWorker
opal_server_1        | [2021-09-09 17:30:21 +0000] [9] [INFO] Booting worker with pid: 9
opal_server_1        | [2021-09-09 17:30:21 +0000] [10] [INFO] Booting worker with pid: 10
opal_server_1        | [2021-09-09 17:30:21 +0000] [11] [INFO] Booting worker with pid: 11
opal_server_1        | [2021-09-09 17:30:21 +0000] [12] [INFO] Booting worker with pid: 12
opal_server_1        | 2021-09-09T17:30:21.657897+0000 |opal_common.authentication.signer       | INFO  | OPAL was not provided with JWT encryption keys, cannot verify api requests!
opal_server_1        | 2021-09-09T17:30:21.709369+0000 |opal_common.authentication.signer       | INFO  | OPAL was not provided with JWT encryption keys, cannot verify api requests!
opal_server_1        | 2021-09-09T17:30:21.736570+0000 |opal_server.server                      | INFO  | triggered startup event
opal_server_1        | 2021-09-09T17:30:21.736989+0000 |opal_common.topics.publisher            | INFO  | started topic publisher
opal_server_1        | 2021-09-09T17:30:21.737376+0000 |opal_server.server                      | INFO  | leadership lock acquired, leader pid: 9
opal_server_1        | 2021-09-09T17:30:21.737518+0000 |opal_server.server                      | INFO  | listening on webhook topic: 'webhook'
opal_server_1        | 2021-09-09T17:30:21.738816+0000 |fastapi_websocket_pubsub.event_notifier | INFO  | New subscription {'id': '41deef66f4714d4da2edec6ef1078b0b', 'subscriber_id': '9080fb2e6a82434095246fa9cda352b7', 'topic': 'webhook', 'callback': functools.partial(<function trigger_repo_watcher_pull at 0x7fc532fb0310>, <opal_server.policy.watcher.task.RepoWatcherTask object at 0x7fc532fb3640>), 'notifier_id': None}
opal_server_1        | 2021-09-09T17:30:21.739108+0000 |opal_server.policy.watcher.task         | INFO  | Launching repo watcher
opal_server_1        | 2021-09-09T17:30:21.739778+0000 |opal_common.git.repo_cloner             | INFO  | Cloning repo from 'https://github.com/authorizon/opal-example-policy-repo' to '/regoclone'
opal_server_1        | 2021-09-09T17:30:21.739956+0000 |opal_common.git.repo_cloner             | INFO  | Repo already exists in '/regoclone'
opal_server_1        | 2021-09-09T17:30:21.800354+0000 |opal_server.server                      | INFO  | triggered startup event
opal_server_1        | 2021-09-09T17:30:21.800808+0000 |opal_common.topics.publisher            | INFO  | started topic publisher
opal_server_1        | 2021-09-09T17:30:21.854116+0000 |opal_common.authentication.signer       | INFO  | OPAL was not provided with JWT encryption keys, cannot verify api requests!
opal_server_1        | 2021-09-09T17:30:21.906423+0000 |opal_server.server                      | INFO  | triggered startup event
opal_server_1        | 2021-09-09T17:30:21.906625+0000 |opal_common.topics.publisher            | INFO  | started topic publisher
opal_server_1        | 2021-09-09T17:30:21.956982+0000 |opal_common.authentication.signer       | INFO  | OPAL was not provided with JWT encryption keys, cannot verify api requests!
opal_server_1        | 2021-09-09T17:30:22.013798+0000 |opal_server.server                      | INFO  | triggered startup event
opal_server_1        | 2021-09-09T17:30:22.014042+0000 |opal_common.topics.publisher            | INFO  | started topic publisher
opal_client_1        | [2021-09-09 17:30:22 +0000] [9] [INFO] Starting gunicorn 20.1.0
opal_client_1        | [2021-09-09 17:30:22 +0000] [9] [INFO] Listening at: http://0.0.0.0:7000 (9)
opal_client_1        | [2021-09-09 17:30:22 +0000] [9] [INFO] Using worker: uvicorn.workers.UvicornWorker
opal_client_1        | [2021-09-09 17:30:22 +0000] [11] [INFO] Booting worker with pid: 11
opal_client_1        | 2021-09-09T17:30:22.776529+0000 |opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
opal_client_1        | 2021-09-09T17:30:22.776886+0000 |opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
opal_client_1        | 2021-09-09T17:30:22.802421+0000 |opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'PostgresFetchProvider' found at: <class 'opal_fetcher_postgres.provider.PostgresFetchProvider'>
opal_client_1        | 2021-09-09T17:30:22.802631+0000 |opal_common.fetcher.fetcher_register    | INFO  | Fetcher Register loaded
opal_client_1        | 2021-09-09T17:30:22.825239+0000 |opal_client.opa.runner                  | INFO  | Launching opa runner
opal_client_1        | 2021-09-09T17:30:22.826799+0000 |opal_client.opa.runner                  | INFO  | Running OPA inline: opa run --server --addr=:8181 --authentication=off --authorization=off --log-level=info
opal_client_1        | 2021-09-09T17:30:22.842910+0000 |opal_client.opa.logger                  | INFO  | Initializing server. {'addrs': [':8181'], 'diagnostic-addrs': [], 'time': '2021-09-09T17:30:22Z'}
opal_server_1        | 2021-09-09T17:30:23.451689+0000 |opal_common.git.repo_watcher            | INFO  | Launching polling task, interval: 30 seconds
opal_client_1        | 2021-09-09T17:30:23.834381+0000 |opal_client.opa.runner                  | INFO  | Running OPA initial start callbacks
opal_client_1        | 2021-09-09T17:30:23.834992+0000 |opal_client.data.updater                | INFO  | Launching data updater
opal_client_1        | 2021-09-09T17:30:23.835351+0000 |opal_client.policy.updater              | INFO  | Launching policy updater
opal_client_1        | 2021-09-09T17:30:23.835596+0000 |opal_client.data.updater                | INFO  | Subscribing to topics: ['policy_data']
opal_client_1        | 2021-09-09T17:30:23.836373+0000 |opal_client.policy.updater              | INFO  | Subscribing to topics: ['policy:.']
opal_client_1        | 2021-09-09T17:30:23.837027+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - ws://opal_server:7002/ws
opal_client_1        | 2021-09-09T17:30:23.837917+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - ws://opal_server:7002/ws
opal_client_1        | 2021-09-09T17:30:23.843181+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - ws://opal_server:7002/ws
opal_client_1        | 2021-09-09T17:30:23.843570+0000 |fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - ws://opal_server:7002/ws
opal_server_1        | 2021-09-09T17:30:23.849333+0000 |fastapi_websocket_pubsub.event_broadc...| INFO  | Listening for incoming events from broadcast channel (first listener started)
opal_server_1        | 2021-09-09T17:30:23.849735+0000 |fastapi_websocket_pubsub.event_broadc...| INFO  | Spawning broadcast listen task
opal_server_1        | 2021-09-09T17:30:23.874777+0000 |fastapi_websocket_pubsub.event_broadc...| INFO  | Subscribing to ALL TOPICS, and sharing messages with broadcast channel
opal_server_1        | 2021-09-09T17:30:23.875580+0000 |fastapi_websocket_pubsub.event_notifier | INFO  | New subscription {'id': '1d521aff17ce49cba19c32833ff51f7c', 'subscriber_id': '95cfad20c966449c93fd01fe5eae0fae', 'topic': '__EventNotifier_ALL_TOPICS__', 'callback': <bound method EventBroadcaster.__broadcast_notifications__ of <fastapi_websocket_pubsub.event_broadcaster.EventBroadcaster object at 0x7fc532fb7580>>, 'notifier_id': None}
opal_server_1        | 2021-09-09T17:30:23.876083+0000 |fastapi_websocket_rpc.websocket_rpc_e...| INFO  | Client connected
opal_server_1        | 2021-09-09T17:30:23.876830+0000 |fastapi_websocket_pubsub.event_broadc...| INFO  | Starting broadcaster listener
opal_server_1        | 2021-09-09T17:30:23.894454+0000 |fastapi_websocket_rpc.websocket_rpc_e...| INFO  | Client connected
opal_server_1        | 2021-09-09T17:30:23.904230+0000 |fastapi_websocket_pubsub.event_notifier | INFO  | New subscription {'id': 'c7e4128addde41f9b41e78d6e21bb9c7', 'subscriber_id': '96aa370defc74f14ab2ace2ee874faa3', 'topic': 'policy_data', 'callback': <function RpcEventServerMethods.subscribe.<locals>.callback at 0x7fc532a8fe50>, 'notifier_id': None}
opal_client_1        | 2021-09-09T17:30:23.908319+0000 |opal_client.data.updater                | INFO  | Connected to server
opal_client_1        | 2021-09-09T17:30:23.908431+0000 |opal_client.data.updater                | INFO  | Performing data configuration, reason: Initial load
opal_server_1        | 2021-09-09T17:30:23.908219+0000 |fastapi_websocket_pubsub.event_notifier | INFO  | New subscription {'id': '17bb79917a5e4d478fbd707a1fd535e5', 'subscriber_id': '3b5a87e12519497ebce614d10932d49b', 'topic': 'policy:.', 'callback': <function RpcEventServerMethods.subscribe.<locals>.callback at 0x7fc532a8fdc0>, 'notifier_id': None}
opal_client_1        | 2021-09-09T17:30:23.908553+0000 |opal_client.data.updater                | INFO  | Getting data-sources configuration from 'http://opal_server:7002/data/config'
opal_client_1        | 2021-09-09T17:30:23.911477+0000 |opal_client.policy.updater              | INFO  | Connected to server
opal_client_1        | 2021-09-09T17:30:23.911853+0000 |opal_client.policy.updater              | INFO  | Refetching policy code (full bundle)
opal_server_1        | 2021-09-09T17:30:23.914931+0000 |opal_server.data.api                    | INFO  | Serving source configuration
opal_server_1        | 2021-09-09T17:30:23.915966+0000 |uvicorn.protocols.http.httptools_impl   | INFO  | 172.25.0.5:60762 - "GET /data/config HTTP/1.1" 200
opal_client_1        | 2021-09-09T17:30:23.917804+0000 |opal_client.data.updater                | INFO  | Triggering data update with id: ca7697c68c3f4c489bd4bc663a0eb82d
opal_client_1        | 2021-09-09T17:30:23.918044+0000 |opal_client.data.updater                | INFO  | Fetching policy data
opal_client_1        | 2021-09-09T17:30:23.918305+0000 |opal_client.data.fetcher                | INFO  | Fetching data from url: postgresql://postgres@example_db:5432/postgres
opal_server_1        | 2021-09-09T17:30:23.936952+0000 |uvicorn.protocols.http.httptools_impl   | INFO  | 172.25.0.5:60764 - "GET /policy?path=. HTTP/1.1" 200
opal_client_1        | 2021-09-09T17:30:23.936638+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Connected to PubSub server ws://opal_server:7002/ws
opal_client_1        | 2021-09-09T17:30:23.939081+0000 |opal_client.policy.updater              | INFO  | got policy bundle, commit hash: '6d849b1ce92bae05c31146470e66e07c3c41b164'
opal_client_1        | 2021-09-09T17:30:23.942061+0000 |opal_client.opa.logger                  | INFO  | Received request.    GET /v1/policies
opal_client_1        | 2021-09-09T17:30:23.942817+0000 |opal_client.opa.logger                  | INFO  | Sent response.       GET /v1/policies -> 200
opal_client_1        | 2021-09-09T17:30:23.944976+0000 |opal_client.opa.logger                  | INFO  | Received request.    PUT /v1/data
opal_client_1        | 2021-09-09T17:30:23.945914+0000 |opal_client.opa.logger                  | INFO  | Sent response.       PUT /v1/data -> 204
example_db_1         | 2021-09-09 17:30:23.948 UTC [35] ERROR:  relation "city" does not exist at character 15
example_db_1         | 2021-09-09 17:30:23.948 UTC [35] STATEMENT:  SELECT * from city;
opal_client_1        | 2021-09-09T17:30:23.948788+0000 |opal_client.opa.logger                  | INFO  | Received request.    PUT /v1/policies/rbac.rego
opal_client_1        | 2021-09-09T17:30:23.956322+0000 |opal_client.opa.logger                  | INFO  | Sent response.       PUT /v1/policies/rbac.rego -> 200
opal_client_1        | 2021-09-09T17:30:23.958569+0000 |opal_client.opa.logger                  | INFO  | Received request.    PUT /v1/policies/utils.rego
opal_client_1        | 2021-09-09T17:30:23.961442+0000 |opal_client.opa.logger                  | INFO  | Sent response.       PUT /v1/policies/utils.rego -> 200
opal_client_1        | 2021-09-09T17:30:23.962971+0000 |fastapi_websocket_pubsub.pub_sub_client | INFO  | Connected to PubSub server ws://opal_server:7002/ws
example_db_1         | 2021-09-09 17:30:24.421 UTC [35] ERROR:  current transaction is aborted, commands ignored until end of transaction block
example_db_1         | 2021-09-09 17:30:24.421 UTC [35] STATEMENT:  SELECT * from city;
example_db_1         | 2021-09-09 17:30:25.058 UTC [35] ERROR:  current transaction is aborted, commands ignored until end of transaction block
example_db_1         | 2021-09-09 17:30:25.058 UTC [35] STATEMENT:  SELECT * from city;
example_db_1         | 2021-09-09 17:30:27.559 UTC [35] ERROR:  current transaction is aborted, commands ignored until end of transaction block
example_db_1         | 2021-09-09 17:30:27.559 UTC [35] STATEMENT:  SELECT * from city;
opal_client_1        | 2021-09-09T17:30:33.938164+0000 |opal_client.data.fetcher                |ERROR  | Timeout while fetching url: postgresql://postgres@example_db:5432/postgres
opal_client_1        | Traceback (most recent call last):
opal_client_1        |
opal_client_1        |   File "/root/.local/bin/gunicorn", line 8, in <module>
opal_client_1        |     sys.exit(run())
opal_client_1        |     │   │    └ <function run at 0x7f4ef9412940>
opal_client_1        |     │   └ <built-in function exit>
opal_client_1        |     └ <module 'sys' (built-in)>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/app/wsgiapp.py", line 67, in run
opal_client_1        |     WSGIApplication("%(prog)s [OPTIONS] [APP_MODULE]").run()
opal_client_1        |     └ <class 'gunicorn.app.wsgiapp.WSGIApplication'>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/app/base.py", line 231, in run
opal_client_1        |     super().run()
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/app/base.py", line 72, in run
opal_client_1        |     Arbiter(self).run()
opal_client_1        |     │       └ <gunicorn.app.wsgiapp.WSGIApplication object at 0x7f4ef93ed7f0>
opal_client_1        |     └ <class 'gunicorn.arbiter.Arbiter'>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 202, in run
opal_client_1        |     self.manage_workers()
opal_client_1        |     │    └ <function Arbiter.manage_workers at 0x7f4ef8d22160>
opal_client_1        |     └ <gunicorn.arbiter.Arbiter object at 0x7f4ef93ed910>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 551, in manage_workers
opal_client_1        |     self.spawn_workers()
opal_client_1        |     │    └ <function Arbiter.spawn_workers at 0x7f4ef8d22280>
opal_client_1        |     └ <gunicorn.arbiter.Arbiter object at 0x7f4ef93ed910>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 622, in spawn_workers
opal_client_1        |     self.spawn_worker()
opal_client_1        |     │    └ <function Arbiter.spawn_worker at 0x7f4ef8d221f0>
opal_client_1        |     └ <gunicorn.arbiter.Arbiter object at 0x7f4ef93ed910>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/arbiter.py", line 589, in spawn_worker
opal_client_1        |     worker.init_process()
opal_client_1        |     │      └ <function UvicornWorker.init_process at 0x7f4ef83fdca0>
opal_client_1        |     └ <uvicorn.workers.UvicornWorker object at 0x7f4ef83ff130>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/uvicorn/workers.py", line 64, in init_process
opal_client_1        |     super(UvicornWorker, self).init_process()
opal_client_1        |           │              └ <uvicorn.workers.UvicornWorker object at 0x7f4ef83ff130>
opal_client_1        |           └ <class 'uvicorn.workers.UvicornWorker'>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/gunicorn/workers/base.py", line 142, in init_process
opal_client_1        |     self.run()
opal_client_1        |     │    └ <function UvicornWorker.run at 0x7f4ef83fddc0>
opal_client_1        |     └ <uvicorn.workers.UvicornWorker object at 0x7f4ef83ff130>
opal_client_1        |   File "/root/.local/lib/python3.8/site-packages/uvicorn/workers.py", line 77, in run
opal_client_1        |     loop.run_until_complete(server.serve(sockets=self.sockets))
opal_client_1        |     │    │                  │      │             │    └ [<gunicorn.sock.TCPSocket object at 0x7f4ef83eef40>]
opal_client_1        |     │    │                  │      │             └ <uvicorn.workers.UvicornWorker object at 0x7f4ef83ff130>
opal_client_1        |     │    │                  │      └ <function Server.serve at 0x7f4ef8631d30>
opal_client_1        |     │    │                  └ <uvicorn.server.Server object at 0x7f4ef88f94c0>
opal_client_1        |     │    └ <method 'run_until_complete' of 'uvloop.loop.Loop' objects>
opal_client_1        |     └ <uvloop.Loop running=True closed=False debug=False>
opal_client_1        | > 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
opal_client_1        |     response = await self._engine.handle_url(url, config=config)
opal_client_1        |                      │    │       │          │           └ {'fetcher': 'PostgresFetchProvider', 'query': 'SELECT * from city;', 'connection_params': {'password': 'postgres'}}
opal_client_1        |                      │    │       │          └ 'postgresql://postgres@example_db:5432/postgres'
opal_client_1        |                      │    │       └ <function FetchingEngine.handle_url at 0x7f4ef736f310>
opal_client_1        |                      │    └ <opal_common.fetcher.engine.fetching_engine.FetchingEngine object at 0x7f4ef88ed8e0>
opal_client_1        |                      └ <opal_client.data.fetcher.DataFetcher object at 0x7f4ef72fce20>
opal_client_1        |   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
opal_client_1        |     await asyncio.wait_for(wait_event.wait(), timeout)
opal_client_1        |           │       │        │          │       └ 10
opal_client_1        |           │       │        │          └ <function Event.wait at 0x7f4ef8760040>
opal_client_1        |           │       │        └ <asyncio.locks.Event object at 0x7f4ef6f09460 [unset]>
opal_client_1        |           │       └ <function wait_for at 0x7f4ef8769940>
opal_client_1        |           └ <module 'asyncio' from '/usr/local/lib/python3.8/asyncio/__init__.py'>
opal_client_1        |   File "/usr/local/lib/python3.8/asyncio/tasks.py", line 501, in wait_for
opal_client_1        |     raise exceptions.TimeoutError()
opal_client_1        |           │          └ <class 'asyncio.exceptions.TimeoutError'>
opal_client_1        |           └ <module 'asyncio.exceptions' from '/usr/local/lib/python3.8/asyncio/exceptions.py'>
opal_client_1        |
opal_client_1        | asyncio.exceptions.TimeoutError
opal_client_1        | 2021-09-09T17:30:33.949107+0000 |opal_client.data.updater                |ERROR  | Failed to fetch url postgresql://postgres@example_db:5432/postgres, got exception:
example_db_1         | 2021-09-09 17:30:35.103 UTC [35] ERROR:  current transaction is aborted, commands ignored until end of transaction block
example_db_1         | 2021-09-09 17:30:35.103 UTC [35] STATEMENT:  SELECT * from city;
example_db_1         | 2021-09-09 17:30:37.384 UTC [35] ERROR:  current transaction is aborted, commands ignored until end of transaction block
example_db_1         | 2021-09-09 17:30:37.384 UTC [35] STATEMENT:  SELECT * from city;
opal_server_1        | 2021-09-09T17:30:53.428806+0000 |opal_common.git.repo_watcher            | INFO  | Pulling changes from remote: 'origin'
opal_server_1        | 2021-09-09T17:30:55.551686+0000 |opal_common.git.repo_watcher            | INFO  | No new commits: HEAD is at '6d849b1ce92bae05c31146470e66e07c3c41b164'
example_db_1         | 2021-09-09 17:31:08.056 UTC [35] ERROR:  current transaction is aborted, commands ignored until end of transaction block
example_db_1         | 2021-09-09 17:31:08.056 UTC [35] STATEMENT:  SELECT * from city;
opal_server_1        | 2021-09-09T17:31:25.531347+0000 |opal_common.git.repo_watcher            | INFO  | Pulling changes from remote: 'origin'
opal_server_1        | 2021-09-09T17:31:27.180727+0000 |opal_common.git.repo_watcher            | INFO  | No new commits: HEAD is at '6d849b1ce92bae05c31146470e66e07c3c41b164'
opal_client_1        | 2021-09-09T17:31:32.875584+0000 |opal_client.opa.logger                  | INFO  | Received request.    GET /v1/data
opal_client_1        | 2021-09-09T17:31:32.876693+0000 |opal_client.opa.logger                  | INFO  | Sent response.       GET /v1/data -> 200
example_db_1         | 2021-09-09 17:31:45.503 UTC [35] ERROR:  current transaction is aborted, commands ignored until end of transaction block
example_db_1         | 2021-09-09 17:31:45.503 UTC [35] STATEMENT:  SELECT * from city;
opal_server_1        | 2021-09-09T17:31:57.159742+0000 |opal_common.git.repo_watcher            | INFO  | Pulling changes from remote: 'origin'
opal_server_1        | 2021-09-09T17:31:58.816467+0000 |opal_common.git.repo_watcher            | INFO  | No new commits: HEAD is at '6d849b1ce92bae05c31146470e66e07c3c41b164'
hongbo-miao commented 2 years ago

Seems the database got polluted by my previous experiment, manually dropped all tables and created again solves the issue!

asafc commented 2 years ago

@Hongbo-Miao For some reason the default behavior for docker compose is to reuse existing containers, even when not using volumes. This is not very intuitive, because the db is not recreated every time you run compose - and indeed the db can be polluted.

The best way to circumnavigate this, is to run docker compose with --force-recreate.

this command will recreate all containers (from the docker image) and give you clean state on load:

docker compose up --force-recreate
asafc commented 2 years ago

@Hongbo-Miao

also, you can see in the output which containers are recreated and which ones are reused:

[+] Running 4/4
 ⠿ Container opal-fetcher-postgres_broadcast_channel_1  Created                                                                                                                                                                                          0.0s
 ⠿ Container opal-fetcher-postgres_example_db_1         Created                                                                                                                                                                                          0.0s
 ⠿ Container opal-fetcher-postgres_opal_server_1        Created                                                                                                                                                                                          0.0s
 ⠿ Container opal-fetcher-postgres_opal_client_1        Recreated
hongbo-miao commented 2 years ago

I was using docker compose --build -V, and not work. It is --force-recreate. Thanks for sharing!