Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

OPAL Agent does not receive data source configuration after scope update #779

Open
dadrus opened this issue Mar 13, 2025 · 1 comment
Open

OPAL Agent does not receive data source configuration after scope update #779

dadrus opened this issue Mar 13, 2025 · 1 comment
Labels
bug Something isn't working

Comments

@dadrus
Copy link

dadrus commented Mar 13, 2025

Describe the bug

When an OPAL Agent is configured to use scopes and connects to an OPAL Server without any scopes being configured, it receives the default data and policy source configuration, which is expected but not useful. However, after configuring a scope via the OPAL Server /scopes endpoint - including both policy and data source configurations - the OPAL Agent only receives the policy source configuration for its scope, the data source configuration is however not propagated, causing all OPA authorization requests to fail due to missing data.

To Reproduce

  1. Start an OPAL Server and an OPAL Agent configured to use scopes.
  2. Ensure no scopes are initially configured on the OPAL Server.
  3. Configure a scope via the /scopes endpoint, including both a policy source and a data source.
  4. Observe that the OPAL Agent makes use of the configured policy source but does not receive the new data source configuration.
  5. Make an authorization request to the OPA instance managed by the Agent and note that it results in an unauthorized response due to missing data. Alternatively one can call the /v1/data endpoint of OPA and observe, that there are no entries related to data which should actually have been fetched from the above said data sources.

Here the excerpt forom the docker compose yaml file related to agent and server config:

  opal_server:
    image: permitio/opal-server:0.8.0
    environment:
      - OPAL_BROADCAST_URI=redis://redis:6379
      - OPAL_REDIS_URL=redis://redis:6379
      - UVICORN_NUM_WORKERS=1
      - OPAL_LOG_FORMAT_INCLUDE_PID=true
      - OPAL_LOG_LEVEL=DEBUG
      - OPAL_SCOPES=1
      - OPAL_POLICY_REFRESH_INTERVAL=30
      - UVICORN_LOG_LEVEL=debug
    ports:
      - "7002:7002"

  opal_client:
    build:
      context: ./opal
      dockerfile: ./Dockerfile # uses permitio/opal-client:0.8.0 and adds postgres fetcher
    environment:
      - OPAL_SERVER_URL=http://opal_server:7002
      - OPAL_LOG_FORMAT_INCLUDE_PID=true
      - OPAL_LOG_LEVEL=DEBUG
      - OPAL_INLINE_OPA_LOG_FORMAT=http
      - OPAL_SCOPE_ID=documents
      - OPAL_DATA_TOPICS=data
      - OPAL_FETCH_PROVIDER_MODULES=opal_common.fetcher.providers,opal_fetcher_postgres.provider

And here the document sent to the /scopes endpoint after both, the agent and the server are started:

{
  "scope_id": "documents",
  "policy": {
    "source_type": "git",
    "url": "https://<edited>/poc_testenvironment",
    "auth": {
      "auth_type": "github_token",
      "token": "<edited>"
    },
    "directories": [ "policies" ],
    "extensions": [ ".rego" ],
    "bundle_ignore": [ "*_test.rego" ],
    "poll_updates": true,
    "branch": "<edited>"
  },
  "data": {
    "entries": [
      {
        "periodic_update_interval": 30,
        "url":"http://caddy:8080/users.json",
        "topics": ["documents:data:data"],
        "dst_path":"/users"
      },
      {
        "periodic_update_interval": 30,
        "url":"http://caddy:8080/organizations.json",
        "topics": ["documents:data:data"],
        "dst_path":"/organizations"
      },
      {
        "periodic_update_interval": 30,
        "url":"http://caddy:8080/departments.json",
        "topics": ["documents:data:data"],
        "dst_path":"/departments"
      },
      {
        "url": "postgresql://documents@db:5432/documents",
        "config": {
            "fetcher": "PostgresFetchProvider",
            "query": "select id::text, concat('ip:', ip) as parent_id from document;",
            "connection_params": {
                "password": "documents"
            },
            "fetch_key": "id"
        },
        "topics": ["documents:data:data"],
        "dst_path": "documents"
      }
    ]
  }
}

Expected behavior

When a scope is configured via the /scopes endpoint, the OPAL Agent should receive both the policy source and data source configurations.

OPAL version

  • Version: 0.8.0
@dadrus dadrus added the bug Something isn't working label Mar 13, 2025
@dadrus
Copy link
Author

dadrus commented Mar 13, 2025 •
edited
Loading

Here the entire log (was too long for a single message):

opal_server-1        | [2025-03-13 13:00:20 +0000] [7] [INFO] Starting gunicorn 22.0.0
opal_server-1        | [2025-03-13 13:00:20 +0000] [7] [INFO] Listening at: http://0.0.0.0:7002 (7)
opal_server-1        | [2025-03-13 13:00:20 +0000] [7] [INFO] Using worker: uvicorn.workers.UvicornWorker
opal_server-1        | 2025-03-13 13:00:20.779 | INFO     | opal_server.scopes.task:preload_scopes:82 - Preloading repo clones for scopes
opal_server-1        | 2025-03-13 13:00:20.779 | DEBUG    | opal_server.redis_utils:__init__:13 - Connecting to Redis: redis://redis:6379
opal_server-1        | 2025-03-13 13:00:20.779 | DEBUG    | opal_server.scopes.service:sync_scopes:191 - Syncing scopes (only_poll_updates=False, notify_on_changes=False)
opal_server-1        | 2025-03-13 13:00:20.782 | INFO     | opal_server.scopes.service:sync_scopes:199 - OPAL Scopes: syncing 0 scopes in the background (polling updates: False)
opal_server-1        | 2025-03-13 13:00:20.795 | WARNING  | opal_server.scopes.task:preload_scopes:91 - Finished preloading repo clones for scopes.
opal_server-1        | 2025-03-13 13:00:20.795 | WARNING  | __config__:when_ready:17 - Finished pre loading scopes...
opal_server-1        | [2025-03-13 13:00:20 +0000] [16] [INFO] Booting worker with pid: 16
opal_server-1        | 2025-03-13T13:00:20.900696+0000 | 16 | opal_common.monitoring.apm              | INFO  | DataDog APM disabled
opal_server-1        | 2025-03-13T13:00:20.900992+0000 | 16 | opal_common.monitoring.metrics          | INFO  | DogStatsD metrics disabled
opal_server-1        | 2025-03-13T13:00:20.901076+0000 | 16 | datadog.dogstatsd.base                  |DEBUG  | Connecting to localhost:8125
opal_server-1        | 2025-03-13T13:00:20.901365+0000 | 16 | datadog.dogstatsd.base                  |DEBUG  | Connected to: ('127.0.0.1', 8125)
opal_server-1        | 2025-03-13T13:00:20.901464+0000 | 16 | opal_server.server                      | INFO  | OPAL was not provided with JWT encryption keys, cannot verify api requests!
opal_server-1        | 2025-03-13T13:00:20.901533+0000 | 16 | opal_server.pubsub                      | INFO  | Initializing broadcaster for server<->server communication
opal_server-1        | 2025-03-13T13:00:20.903287+0000 | 16 | opal_server.redis_utils                 |DEBUG  | Connecting to Redis: redis://redis:6379
opal_server-1        | 2025-03-13T13:00:20.903462+0000 | 16 | opal_server.server                      | INFO  | OPAL Scopes: server is connected to scopes repository
opal_server-1        | 2025-03-13T13:00:20.903699+0000 | 16 | opal_server.data.data_update_publisher  |DEBUG  | DataUpdatePublisher initialized <opal_common.topics.publisher.ServerSideTopicPublisher object at 0x79a61b650a00>
opal_server-1        | 2025-03-13T13:00:20.931112+0000 | 16 | opal_server.server                      | INFO  | *** OPAL Server Startup ***
opal_server-1        | 2025-03-13T13:00:20.931176+0000 | 16 | opal_common.topics.publisher            |DEBUG  | started topic publisher
opal_server-1        | 2025-03-13T13:00:20.931206+0000 | 16 | opal_common.synchronization.named_lock  |DEBUG  | [16] trying to acquire lock (lock=/tmp/opal_server_leader.lock)
opal_server-1        | 2025-03-13T13:00:20.931255+0000 | 16 | opal_common.synchronization.named_lock  |DEBUG  | [16] lock acquired! (lock=/tmp/opal_server_leader.lock)
opal_server-1        | 2025-03-13T13:00:20.931273+0000 | 16 | opal_server.server                      | INFO  | leadership lock acquired, leader pid: 16
opal_server-1        | 2025-03-13T13:00:20.931290+0000 | 16 | opal_server.scopes.loader               | INFO  | Server is primary, loading default scope.
opal_server-1        | 2025-03-13T13:00:20.931309+0000 | 16 | opal_common.topics.publisher            | INFO  | started broadcaster keepalive task: topic is '__broadcast_session_keepalive__', interval is 3600 seconds
opal_server-1        | 2025-03-13T13:00:20.931352+0000 | 16 | opal_server.redis_utils                 |DEBUG  | Connecting to Redis: redis://redis:6379
opal_server-1        | 2025-03-13T13:00:20.931686+0000 | 16 | opal_server.scopes.task                 |DEBUG  | ScopesPolicyWatcherTask initialized with <opal_server.scopes.service.ScopesService object at 0x79a6223b0fa0>
opal_server-1        | 2025-03-13T13:00:20.931720+0000 | 16 | opal_server.scopes.task                 |DEBUG  | ScopesPolicyWatcherTask started
opal_server-1        | 2025-03-13T13:00:20.931752+0000 | 16 | opal_server.policy.watcher.task         | INFO  | Launching policy watcher
opal_server-1        | 2025-03-13T13:00:20.931953+0000 | 16 | fastapi_websocket_pubsub.event_broadc...| INFO  | Listening for incoming events from broadcast channel (first listener started)
opal_server-1        | 2025-03-13T13:00:20.931999+0000 | 16 | fastapi_websocket_pubsub.event_broadc...|DEBUG  | Spawning broadcast listen task
opal_server-1        | 2025-03-13T13:00:20.932030+0000 | 16 | opal_server.policy.watcher.task         | INFO  | listening on webhook topic: 'webhook'
opal_server-1        | 2025-03-13T13:00:20.932136+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | New subscription {'id': 'c9a682aad21741818f0aa601c4660b51', 'subscriber_id': 'c7ed60f45f81405bb1d981c657a71f0c', 'topic': 'webhook', 'callback': <bound method BasePolicyWatcherTask._on_webhook of <opal_server.scopes.task.ScopesPolicyWatcherTask object at 0x79a6223b00d0>>, 'notifier_id': None}
opal_server-1        | 2025-03-13T13:00:20.932192+0000 | 16 | opal_server.scopes.service              |DEBUG  | Syncing scopes (only_poll_updates=False, notify_on_changes=True)
opal_server-1        | 2025-03-13T13:00:20.932563+0000 | 16 | fastapi_websocket_pubsub.event_broadc...| INFO  | Starting broadcaster listener
opal_server-1        | 2025-03-13T13:00:20.944344+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_server-1        | 2025-03-13T13:00:20.944859+0000 | 16 | opal_server.scopes.service              | INFO  | OPAL Scopes: syncing 0 scopes in the background (polling updates: False)
opal_server-1        | 2025-03-13T13:00:20.945022+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_server-1        | 2025-03-13T13:00:20.945099+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_server-1        | 2025-03-13T13:00:20.945479+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_client-1        | + exec gunicorn -b 0.0.0.0:7000 -k uvicorn.workers.UvicornWorker --workers=1 -c ./gunicorn_conf.py opal_client.main:app -t 30 --keep-alive 5
opal_client-1        | [2025-03-13 13:00:21 +0000] [17] [INFO] Starting gunicorn 22.0.0
opal_client-1        | [2025-03-13 13:00:21 +0000] [17] [INFO] Listening at: http://0.0.0.0:7000 (17)
opal_client-1        | [2025-03-13 13:00:21 +0000] [17] [INFO] Using worker: uvicorn.workers.UvicornWorker
opal_client-1        | [2025-03-13 13:00:21 +0000] [19] [INFO] Booting worker with pid: 19
opal_server-1        | failed to send, dropping 1 traces to intake at http://localhost:8126/v0.5/traces after 3 retries
opal_client-1        | 2025-03-13T13:00:21.903141+0000 | 19 | opal_client.policy_store.opa_client     | INFO  | Authentication mode for policy store: PolicyStoreAuth.NONE
opal_client-1        | 2025-03-13T13:00:21.903359+0000 | 19 | opal_client.callbacks.register          | INFO  | Callbacks register loaded
opal_client-1        | 2025-03-13T13:00:21.904373+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.904434+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.915405+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'PostgresFetchProvider' found at: <class 'opal_fetcher_postgres.provider.PostgresFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.915475+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Fetcher Register loaded
opal_client-1        | 2025-03-13T13:00:21.915590+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.915629+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.915848+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'PostgresFetchProvider' found at: <class 'opal_fetcher_postgres.provider.PostgresFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.915890+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Fetcher Register loaded
opal_client-1        | 2025-03-13T13:00:21.916017+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.916056+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.916256+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'PostgresFetchProvider' found at: <class 'opal_fetcher_postgres.provider.PostgresFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.916290+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Fetcher Register loaded
opal_client-1        | 2025-03-13T13:00:21.916380+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'FastApiRpcFetchProvider' found at: <class 'opal_common.fetcher.providers.fastapi_rpc_fetch_provider.FastApiRpcFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.916415+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'HttpFetchProvider' found at: <class 'opal_common.fetcher.providers.http_fetch_provider.HttpFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.916611+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Loading FetcherProvider 'PostgresFetchProvider' found at: <class 'opal_fetcher_postgres.provider.PostgresFetchProvider'>
opal_client-1        | 2025-03-13T13:00:21.916642+0000 | 19 | opal_common.fetcher.fetcher_register    | INFO  | Fetcher Register loaded
opal_client-1        | 2025-03-13T13:00:21.916699+0000 | 19 | opal_client.data.updater                |DEBUG  | DataUpdater configured with <opal_client.data.updater.DataUpdater object at 0x6ffeb61cd990>
opal_client-1        | 2025-03-13T13:00:21.916774+0000 | 19 | opal_client.client                      |DEBUG  | Configured data updater <opal_client.data.updater.DataUpdater object at 0x6ffeb61cd990>
opal_client-1        | 2025-03-13T13:00:21.916797+0000 | 19 | opal_client.client                      |DEBUG  | Initializing engine runner
opal_client-1        | 2025-03-13T13:00:21.916818+0000 | 19 | opal_client.engine.runner               |DEBUG  | Initializing OpaRunner with options: addr=':8181' authentication=<AuthenticationScheme.off: 'off'> authorization=<AuthorizationScheme.off: 'off'> config_file=None tls_ca_cert_file=None tls_cert_file=None tls_private_key_file=None tls_cert_refresh_period=None log_level=<LogLevel.info: 'info'> files=None v0_compatible=False
opal_client-1        | 2025-03-13T13:00:21.916854+0000 | 19 | opal_client.engine.runner               |DEBUG  | Initial start callbacks: None
opal_client-1        | 2025-03-13T13:00:21.916871+0000 | 19 | opal_client.engine.runner               |DEBUG  | Rehydration callbacks: [functools.partial(<bound method PolicyUpdater.trigger_update_policy of <opal_client.policy.updater.PolicyUpdater object at 0x6ffeb6303940>>, force_full_update=True), functools.partial(<bound method DataUpdater.get_base_policy_data of <opal_client.data.updater.DataUpdater object at 0x6ffeb61cd990>>, data_fetch_reason='policy store rehydration')]
opal_client-1        | 2025-03-13T13:00:21.916904+0000 | 19 | opal_client.client                      | INFO  | API authentication disabled (public encryption key was not provided)
opal_client-1        | 2025-03-13T13:00:21.933741+0000 | 19 | opal_client.engine.runner               | INFO  | Launching engine runner
opal_client-1        | 2025-03-13T13:00:21.934122+0000 | 19 | opal_client.engine.runner               | INFO  | Running policy engine inline: /opal/opa run --server --addr=:8181 --authentication=off --authorization=off --log-level=info --v0-compatible=False
opal_client-1        | 2025-03-13T13:00:21.946244+0000 | 19 | opal_client.engine.logger               | INFO  | Initializing server. {"addrs": [":8181"], "diagnostic-addrs": [], "time": "2025-03-13T13:00:21Z"}
opal_client-1        | 2025-03-13T13:00:22.940286+0000 | 19 | opal_client.engine.runner               | INFO  | Running policy engine initial start callbacks
opal_client-1        | 2025-03-13T13:00:22.941092+0000 | 19 | opal_client.data.updater                | INFO  | Launching data updater
opal_client-1        | 2025-03-13T13:00:22.941332+0000 | 19 | opal_client.data.fetcher                |DEBUG  | Starting data fetcher
opal_client-1        | 2025-03-13T13:00:22.941572+0000 | 19 | opal_client.data.fetcher                |DEBUG  | Starting data fetcher
opal_client-1        | 2025-03-13T13:00:22.941826+0000 | 19 | opal_client.policy.updater              | INFO  | Launching policy updater
opal_client-1        | 2025-03-13T13:00:22.941963+0000 | 19 | opal_client.data.fetcher                |DEBUG  | Starting data fetcher
opal_client-1        | 2025-03-13T13:00:22.942137+0000 | 19 | opal_client.data.fetcher                |DEBUG  | Starting data fetcher
opal_client-1        | 2025-03-13T13:00:22.942341+0000 | 19 | opal_client.data.updater                | INFO  | Subscribing to topics: ['documents:data:data']
opal_client-1        | 2025-03-13T13:00:22.942834+0000 | 19 | opal_client.policy.updater              | INFO  | Subscribing to topics: ['documents:policy:.']
opal_client-1        | 2025-03-13T13:00:22.943514+0000 | 19 | fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - ws://opal_server:7002/ws
opal_client-1        | 2025-03-13T13:00:22.944459+0000 | 19 | fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - ws://opal_server:7002/ws
opal_client-1        | 2025-03-13T13:00:22.949385+0000 | 19 | fastapi_websocket_pubsub.pub_sub_client | INFO  | Trying to connect to Pub/Sub server - ws://opal_server:7002/ws
opal_client-1        | 2025-03-13T13:00:22.949808+0000 | 19 | fastapi_websocket_rpc.websocket_rpc_c...| INFO  | Trying server - ws://opal_server:7002/ws
opal_client-1        | 2025-03-13T13:00:22.950321+0000 | 19 | websockets.legacy.protocol              |DEBUG  | = connection is CONNECTING
opal_client-1        | 2025-03-13T13:00:22.952243+0000 | 19 | websockets.legacy.protocol              |DEBUG  | = connection is CONNECTING
opal_client-1        | 2025-03-13T13:00:22.952896+0000 | 19 | websockets.legacy.client                |DEBUG  | > GET /ws HTTP/1.1
opal_client-1        | 2025-03-13T13:00:22.952973+0000 | 19 | websockets.legacy.client                |DEBUG  | > Host: opal_server:7002
opal_client-1        | 2025-03-13T13:00:22.953017+0000 | 19 | websockets.legacy.client                |DEBUG  | > Upgrade: websocket
opal_client-1        | 2025-03-13T13:00:22.953052+0000 | 19 | websockets.legacy.client                |DEBUG  | > Connection: Upgrade
opal_client-1        | 2025-03-13T13:00:22.953091+0000 | 19 | websockets.legacy.client                |DEBUG  | > Sec-WebSocket-Key: GqruCqdcWPjH8D34kSOVRg==
opal_client-1        | 2025-03-13T13:00:22.953121+0000 | 19 | websockets.legacy.client                |DEBUG  | > Sec-WebSocket-Version: 13
opal_client-1        | 2025-03-13T13:00:22.953150+0000 | 19 | websockets.legacy.client                |DEBUG  | > Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
opal_client-1        | 2025-03-13T13:00:22.953185+0000 | 19 | websockets.legacy.client                |DEBUG  | > Authorization: Bearer THIS_IS_A_DEV_SECRET
opal_client-1        | 2025-03-13T13:00:22.953215+0000 | 19 | websockets.legacy.client                |DEBUG  | > User-Agent: Python/3.10 websockets/10.4
opal_client-1        | 2025-03-13T13:00:22.953365+0000 | 19 | websockets.legacy.client                |DEBUG  | > GET /ws HTTP/1.1
opal_client-1        | 2025-03-13T13:00:22.953409+0000 | 19 | websockets.legacy.client                |DEBUG  | > Host: opal_server:7002
opal_client-1        | 2025-03-13T13:00:22.953446+0000 | 19 | websockets.legacy.client                |DEBUG  | > Upgrade: websocket
opal_client-1        | 2025-03-13T13:00:22.953480+0000 | 19 | websockets.legacy.client                |DEBUG  | > Connection: Upgrade
opal_client-1        | 2025-03-13T13:00:22.953515+0000 | 19 | websockets.legacy.client                |DEBUG  | > Sec-WebSocket-Key: bnwK6NErGVUNpQmIsOgEXw==
opal_client-1        | 2025-03-13T13:00:22.953554+0000 | 19 | websockets.legacy.client                |DEBUG  | > Sec-WebSocket-Version: 13
opal_client-1        | 2025-03-13T13:00:22.953588+0000 | 19 | websockets.legacy.client                |DEBUG  | > Sec-WebSocket-Extensions: permessage-deflate; client_max_window_bits
opal_client-1        | 2025-03-13T13:00:22.953619+0000 | 19 | websockets.legacy.client                |DEBUG  | > Authorization: Bearer THIS_IS_A_DEV_SECRET
opal_client-1        | 2025-03-13T13:00:22.953659+0000 | 19 | websockets.legacy.client                |DEBUG  | > User-Agent: Python/3.10 websockets/10.4
opal_server-1        | 2025-03-13T13:00:22.957738+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_server-1        | 2025-03-13T13:00:22.957960+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_server-1        | 2025-03-13T13:00:22.958188+0000 | 16 | fastapi_websocket_pubsub.event_broadc...|DEBUG  | Subscribing to ALL_TOPICS, and sharing messages with broadcast channel
opal_server-1        | 2025-03-13T13:00:22.958303+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | New subscription {'id': '7144b987f0dc43dd97298c59a81fb67b', 'subscriber_id': '9ff04c77d0a5481c88a320d88518aca9', 'topic': '__EventNotifier_ALL_TOPICS__', 'callback': <bound method EventBroadcaster.__broadcast_notifications__ of <fastapi_websocket_pubsub.event_broadcaster.EventBroadcaster object at 0x79a61b6507c0>>, 'notifier_id': None}
opal_server-1        | 2025-03-13T13:00:22.958435+0000 | 16 | fastapi_websocket_pubsub.pub_sub_server |DEBUG  | Entering endpoint's main loop with broadcaster
opal_server-1        | 2025-03-13T13:00:22.958518+0000 | 16 | fastapi_websocket_pubsub.event_broadc...|DEBUG  | Did not subscribe to ALL_TOPICS: share count == 2
opal_server-1        | 2025-03-13T13:00:22.958558+0000 | 16 | fastapi_websocket_pubsub.pub_sub_server |DEBUG  | Entering endpoint's main loop with broadcaster
opal_server-1        | 2025-03-13T13:00:22.958776+0000 | 16 | fastapi_websocket_rpc.websocket_rpc_e...| INFO  | Client connected
opal_server-1        | 2025-03-13T13:00:22.958924+0000 | 16 | fastapi_websocket_rpc.websocket_rpc_e...| INFO  | Client connected
opal_server-1        | 2025-03-13T13:00:22.959580+0000 | 16 | websockets.legacy.server                | INFO  | connection open
opal_client-1        | 2025-03-13T13:00:22.960188+0000 | 19 | websockets.legacy.client                |DEBUG  | < HTTP/1.1 101 Switching Protocols
opal_server-1        | 2025-03-13T13:00:22.960209+0000 | 16 | websockets.legacy.server                | INFO  | connection open
opal_client-1        | 2025-03-13T13:00:22.960507+0000 | 19 | websockets.legacy.client                |DEBUG  | < Upgrade: websocket
opal_client-1        | 2025-03-13T13:00:22.960814+0000 | 19 | websockets.legacy.client                |DEBUG  | < Connection: Upgrade
opal_client-1        | 2025-03-13T13:00:22.961010+0000 | 19 | websockets.legacy.client                |DEBUG  | < Sec-WebSocket-Accept: vA/XDKHBGf/bT5ebqbgtJTlbWzs=
opal_client-1        | 2025-03-13T13:00:22.961193+0000 | 19 | websockets.legacy.client                |DEBUG  | < Sec-WebSocket-Extensions: permessage-deflate
opal_client-1        | 2025-03-13T13:00:22.961354+0000 | 19 | websockets.legacy.client                |DEBUG  | < date: Thu, 13 Mar 2025 13:00:22 GMT
opal_client-1        | 2025-03-13T13:00:22.961509+0000 | 19 | websockets.legacy.client                |DEBUG  | < server: uvicorn
opal_client-1        | 2025-03-13T13:00:22.962016+0000 | 19 | websockets.legacy.protocol              |DEBUG  | = connection is OPEN
opal_client-1        | 2025-03-13T13:00:22.962681+0000 | 19 | websockets.legacy.client                |DEBUG  | < HTTP/1.1 101 Switching Protocols
opal_client-1        | 2025-03-13T13:00:22.962920+0000 | 19 | websockets.legacy.client                |DEBUG  | < Upgrade: websocket
opal_client-1        | 2025-03-13T13:00:22.963109+0000 | 19 | websockets.legacy.client                |DEBUG  | < Connection: Upgrade
opal_client-1        | 2025-03-13T13:00:22.963291+0000 | 19 | websockets.legacy.client                |DEBUG  | < Sec-WebSocket-Accept: TKCWshUV9yfSvdds7ziqGinkOxw=
opal_server-1        | 2025-03-13T13:00:22.967044+0000 | 16 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC request - {'request': RpcRequest(method='_ping_', arguments={}, call_id='99bf7df09cdc44b1b1712abb8879794e'), 'channel': '64fa15f0954d46e193c8fc340cd3e9fc'}
opal_client-1        | 2025-03-13T13:00:22.963470+0000 | 19 | websockets.legacy.client                |DEBUG  | < Sec-WebSocket-Extensions: permessage-deflate
opal_client-1        | 2025-03-13T13:00:22.963646+0000 | 19 | websockets.legacy.client                |DEBUG  | < date: Thu, 13 Mar 2025 13:00:22 GMT
opal_client-1        | 2025-03-13T13:00:22.963854+0000 | 19 | websockets.legacy.client                |DEBUG  | < server: uvicorn
opal_client-1        | 2025-03-13T13:00:22.964172+0000 | 19 | websockets.legacy.protocol              |DEBUG  | = connection is OPEN
opal_server-1        | 2025-03-13T13:00:22.968471+0000 | 16 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC request - {'request': RpcRequest(method='_ping_', arguments={}, call_id='7fc9211ed19748f39d2e10999a539760'), 'channel': '940fd9d1d83c426eacf7e77c74d511b4'}
opal_client-1        | 2025-03-13T13:00:22.964960+0000 | 19 | fastapi_websocket_rpc.websocket_rpc_c...|DEBUG  | Pinging server
opal_client-1        | 2025-03-13T13:00:22.965511+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Calling RPC method - {'message': RpcMessage(request=RpcRequest(method='_ping_', arguments={}, call_id='99bf7df09cdc44b1b1712abb8879794e'), response=None)}
opal_server-1        | 2025-03-13T13:00:22.969256+0000 | 16 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC request - {'request': RpcRequest(method='subscribe', arguments={'topics': ['documents:data:data']}, call_id='a6f0563187f0419e9949138b0e19654c'), 'channel': '64fa15f0954d46e193c8fc340cd3e9fc'}
opal_client-1        | 2025-03-13T13:00:22.966302+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > TEXT '{"request": {"method": "_ping_", "arguments": {...4e"}, "response": null}' [115 bytes]
opal_server-1        | 2025-03-13T13:00:22.969376+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | New subscription {'id': '3c86ff3be161403fbd15e20b388b81ff', 'subscriber_id': '64fa15f0954d46e193c8fc340cd3e9fc', 'topic': 'documents:data:data', 'callback': <function RpcEventServerMethods.subscribe.<locals>.callback at 0x79a622300d30>, 'notifier_id': None}
opal_client-1        | 2025-03-13T13:00:22.966774+0000 | 19 | fastapi_websocket_rpc.websocket_rpc_c...|DEBUG  | Pinging server
opal_client-1        | 2025-03-13T13:00:22.966931+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Calling RPC method - {'message': RpcMessage(request=RpcRequest(method='_ping_', arguments={}, call_id='7fc9211ed19748f39d2e10999a539760'), response=None)}
opal_client-1        | 2025-03-13T13:00:22.967076+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > TEXT '{"request": {"method": "_ping_", "arguments": {...60"}, "response": null}' [115 bytes]
opal_client-1        | 2025-03-13T13:00:22.968419+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < TEXT '{"request": null, "response": {"result": "pong"...44b1b1712abb8879794e"}}' [118 bytes]
opal_server-1        | 2025-03-13T13:00:22.970636+0000 | 16 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC request - {'request': RpcRequest(method='subscribe', arguments={'topics': ['documents:policy:.']}, call_id='487f691da5bc4814b4730f4ae7f5c274'), 'channel': '940fd9d1d83c426eacf7e77c74d511b4'}
opal_client-1        | 2025-03-13T13:00:22.968550+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC response - {'response': RpcResponse(result='pong', result_type='str', call_id='99bf7df09cdc44b1b1712abb8879794e')}
opal_server-1        | 2025-03-13T13:00:22.970883+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | New subscription {'id': 'edd0f3a86ba14147980ed50c137a851c', 'subscriber_id': '940fd9d1d83c426eacf7e77c74d511b4', 'topic': 'documents:policy:.', 'callback': <function RpcEventServerMethods.subscribe.<locals>.callback at 0x79a622300ca0>, 'notifier_id': None}
opal_client-1        | 2025-03-13T13:00:22.968693+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Calling RPC method - {'message': RpcMessage(request=RpcRequest(method='subscribe', arguments={'topics': ['documents:data:data']}, call_id='a6f0563187f0419e9949138b0e19654c'), response=None)}
opal_client-1        | 2025-03-13T13:00:22.968852+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > TEXT '{"request": {"method": "subscribe", "arguments"...4c"}, "response": null}' [151 bytes]
opal_client-1        | 2025-03-13T13:00:22.969002+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < TEXT '{"request": null, "response": {"result": "pong"...48f39d2e10999a539760"}}' [118 bytes]
opal_client-1        | 2025-03-13T13:00:22.969102+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC response - {'response': RpcResponse(result='pong', result_type='str', call_id='7fc9211ed19748f39d2e10999a539760')}
opal_client-1        | 2025-03-13T13:00:22.969218+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Calling RPC method - {'message': RpcMessage(request=RpcRequest(method='subscribe', arguments={'topics': ['documents:policy:.']}, call_id='487f691da5bc4814b4730f4ae7f5c274'), response=None)}
opal_client-1        | 2025-03-13T13:00:22.969315+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > TEXT '{"request": {"method": "subscribe", "arguments"...74"}, "response": null}' [150 bytes]
opal_client-1        | 2025-03-13T13:00:22.971250+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < TEXT '{"request": null, "response": {"result": true, ...419e9949138b0e19654c"}}' [117 bytes]
opal_client-1        | 2025-03-13T13:00:22.971533+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC response - {'response': RpcResponse(result=True, result_type='bool', call_id='a6f0563187f0419e9949138b0e19654c')}
opal_client-1        | 2025-03-13T13:00:22.971749+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < TEXT '{"request": null, "response": {"result": true, ...4814b4730f4ae7f5c274"}}' [117 bytes]
opal_client-1        | 2025-03-13T13:00:22.971989+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC response - {'response': RpcResponse(result=True, result_type='bool', call_id='487f691da5bc4814b4730f4ae7f5c274')}
opal_server-1        | 2025-03-13T13:00:22.974216+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_client-1        | 2025-03-13T13:00:22.972088+0000 | 19 | opal_client.data.updater                | INFO  | Connected to server
opal_server-1        | 2025-03-13T13:00:22.974308+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_client-1        | 2025-03-13T13:00:22.972143+0000 | 19 | opal_client.data.updater                | INFO  | Performing data configuration, reason: Initial load
opal_server-1        | 2025-03-13T13:00:22.974568+0000 | 16 | opal_server.scopes.api                  | INFO  | Serving source configuration for scope documents
opal_client-1        | 2025-03-13T13:00:22.972198+0000 | 19 | opal_client.data.updater                | INFO  | Getting data-sources configuration from 'http://opal_server:7002/scopes/documents/data'
opal_server-1        | 2025-03-13T13:00:22.975413+0000 | 16 | opal_server.scopes.api                  |WARNING | Requested scope documents not found, returning OPAL_DATA_CONFIG_SOURCES
opal_client-1        | 2025-03-13T13:00:22.972570+0000 | 19 | opal_client.policy.updater              | INFO  | Connected to server
opal_server-1        | 2025-03-13T13:00:22.975800+0000 | 16 | uvicorn.protocols.http.httptools_impl   | INFO  | 172.18.0.7:55280 - "GET /scopes/documents/data HTTP/1.1" 200
opal_client-1        | 2025-03-13T13:00:22.972690+0000 | 19 | opal_client.policy.updater              | INFO  | Refetching policy code (full bundle)
opal_server-1        | 2025-03-13T13:00:22.975973+0000 | 16 | opal_server.scopes.api                  |DEBUG  | Known scopes [], requested scope is documents
opal_client-1        | 2025-03-13T13:00:22.972823+0000 | 19 | opal_client.policy.fetcher              | INFO  | Fetching policy bundle from http://opal_server:7002/scopes/documents/policy
opal_server-1        | 2025-03-13T13:00:22.976133+0000 | 16 | opal_server.scopes.api                  |WARNING | Requested scope documents not found, returning default scope
opal_client-1        | 2025-03-13T13:00:22.973109+0000 | 19 | fastapi_websocket_pubsub.pub_sub_client | INFO  | Connected to PubSub server ws://opal_server:7002/ws
opal_server-1        | 2025-03-13T13:00:22.976305+0000 | 16 | datadog.dogstatsd.base                  |WARNING | Error submitting packet: [Errno 111] Connection refused, dropping the packet and closing the socket
opal_client-1        | 2025-03-13T13:00:22.976271+0000 | 19 | opal_client.data.updater                |DEBUG  | Sources config: entries=[DataSourceEntryWithPollingInterval(url='http://host.docker.internal:7002/policy-data', config=None, topics=['policy_data'], dst_path='', save_method='PUT', data=None, periodic_update_interval=None)]
opal_client-1        | 2025-03-13T13:00:22.976378+0000 | 19 | opal_client.data.updater                |DEBUG  | Initial entries: [DataSourceEntryWithPollingInterval(url='http://host.docker.internal:7002/policy-data', config=None, topics=['policy_data'], dst_path='', save_method='PUT', data=None, periodic_update_interval=None)]
opal_server-1        | 2025-03-13T13:00:22.976576+0000 | 16 | opal_common.middleware                  |ERROR  | Uncaught server exception: Scope documents not found
opal_client-1        | 2025-03-13T13:00:22.976411+0000 | 19 | opal_client.data.updater                |DEBUG  | Periodic entries: []
opal_server-1        | Traceback (most recent call last):
opal_client-1        | 2025-03-13T13:00:22.976522+0000 | 19 | opal_client.data.updater                | INFO  | Triggering data update with id: 36f9b3cc028a4ee1a6831da3fbe4d6ff
opal_server-1        | 
opal_client-1        | 2025-03-13T13:00:22.976577+0000 | 19 | opal_client.data.updater                |DEBUG  | Updating policy data using id='36f9b3cc028a4ee1a6831da3fbe4d6ff' entries=[DataSourceEntryWithPollingInterval(url='http://host.docker.internal:7002/policy-data', config=None, topics=['policy_data'], dst_path='', save_method='PUT', data=None, periodic_update_interval=None)] reason='Initial load' callback=UpdateCallback(callbacks=[])
opal_server-1        |   File "/usr/local/lib/python3.10/site-packages/opal_server-0.0.0-py3.10.egg/opal_server/scopes/api.py", line 253, in get_scope_policy
opal_client-1        | 2025-03-13T13:00:22.976614+0000 | 19 | opal_client.data.updater                |DEBUG  | Processing url='http://host.docker.internal:7002/policy-data' config=None topics=['policy_data'] dst_path='' save_method='PUT' data=None periodic_update_interval=None
opal_server-1        |     scope = await scopes.get(scope_id)
opal_client-1        | 2025-03-13T13:00:22.976639+0000 | 19 | opal_client.data.updater                |DEBUG  | Configured data topics: ['documents:data:data']
opal_server-1        |                   │      │   └ 'documents'
opal_client-1        | 2025-03-13T13:00:22.976668+0000 | 19 | opal_client.data.updater                |DEBUG  | Data entry url='http://host.docker.internal:7002/policy-data' config=None topics=['policy_data'] dst_path='' save_method='PUT' data=None periodic_update_interval=None has no topics matching the data topics, skipping
opal_server-1        |                   │      └ <function ScopeRepository.get at 0x79a623433010>
opal_client-1        | 2025-03-13T13:00:22.976796+0000 | 19 | fastapi_websocket_pubsub.pub_sub_client | INFO  | Connected to PubSub server ws://opal_server:7002/ws
opal_server-1        |                   └ <opal_server.scopes.scope_repository.ScopeRepository object at 0x79a61b650dc0>
opal_client-1        | 2025-03-13T13:00:22.984804+0000 | 19 | opal_common.utils                       |WARNING | Unexpected response code 500: {'error': 'Uncaught server exception'}
opal_server-1        | opal_server.scopes.scope_repository.ScopeNotFoundError: Scope documents not found
opal_server-1        | 2025-03-13T13:00:22.982129+0000 | 16 | uvicorn.protocols.http.httptools_impl   | INFO  | 172.18.0.7:55290 - "GET /scopes/documents/policy?path=. HTTP/1.1" 500
opal_server-1        | 2025-03-13T13:00:22.982235+0000 | 16 | uvicorn.protocols.http.httptools_impl   |ERROR  | Exception in ASGI application

Longer stacktraces telling the documents and the default scopes are not found

opal_client-1        | 2025-03-13T13:00:23.051753+0000 | 19 | opal_client.policy.fetcher              | INFO  | Fetching policy bundle from http://opal_server:7002/scopes/documents/policy
opal_client-1        | 2025-03-13T13:00:23.061285+0000 | 19 | opal_common.utils                       |WARNING | Unexpected response code 500: {'error': 'Uncaught server exception'}
opal_server-1        | opal_server.scopes.scope_repository.ScopeNotFoundError: Scope documents not found
opal_server-1        | 2025-03-13T13:00:23.053358+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_server-1        | 2025-03-13T13:00:23.053887+0000 | 16 | opal_server.scopes.api                  |DEBUG  | Known scopes [], requested scope is documents
opal_server-1        | 2025-03-13T13:00:23.054097+0000 | 16 | opal_server.scopes.api                  |WARNING | Requested scope documents not found, returning default scope
opal_server-1        | 2025-03-13T13:00:23.054245+0000 | 16 | datadog.dogstatsd.base                  |DEBUG  | Connecting to localhost:8125
opal_server-1        | 2025-03-13T13:00:23.054470+0000 | 16 | datadog.dogstatsd.base                  |DEBUG  | Connected to: ('127.0.0.1', 8125)
opal_server-1        | 2025-03-13T13:00:23.054841+0000 | 16 | opal_common.middleware                  |ERROR  | Uncaught server exception: Scope documents not found
opal_server-1        | Traceback (most recent call last):

Longer stacktraces telling the documents and the default scopes are not found

opal_server-1        | opal_server.scopes.scope_repository.ScopeNotFoundError: Scope documents not found
opal_server-1        | 2025-03-13T13:00:23.058673+0000 | 16 | uvicorn.protocols.http.httptools_impl   | INFO  | 172.18.0.7:55302 - "GET /scopes/documents/policy?path=. HTTP/1.1" 500
opal_server-1        | 2025-03-13T13:00:23.058783+0000 | 16 | uvicorn.protocols.http.httptools_impl   |ERROR  | Exception in ASGI application

Longer stacktraces telling the documents and the default scopes are not found

opal_server-1        | opal_server.scopes.scope_repository.ScopeNotFoundError: Scope documents not found
opal_server-1        | 2025-03-13T13:00:24.137758+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_server-1        | 2025-03-13T13:00:24.139320+0000 | 16 | opal_server.scopes.api                  | INFO  | Sync scope: documents
opal_server-1        | 2025-03-13T13:00:24.139423+0000 | 16 | fastapi_websocket_pubsub.pub_sub_server |DEBUG  | Publishing message to topics: webhook
opal_server-1        | 2025-03-13T13:00:24.139465+0000 | 16 | fastapi_websocket_pubsub.pub_sub_server |DEBUG  | Acquiring broadcaster sharing context
opal_server-1        | 2025-03-13T13:00:24.139504+0000 | 16 | fastapi_websocket_pubsub.event_broadc...|DEBUG  | Did not subscribe to ALL_TOPICS: share count == 3
opal_server-1        | 2025-03-13T13:00:24.139574+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | calling subscription callbacks: topic=webhook, subscription_id=c9a682aad21741818f0aa601c4660b51, subscriber_id=c7ed60f45f81405bb1d981c657a71f0c
opal_server-1        | 2025-03-13T13:00:24.139599+0000 | 16 | opal_server.policy.watcher.task         | INFO  | Webhook listener triggered (0)
opal_server-1        | 2025-03-13T13:00:24.139663+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | calling subscription callbacks: topic=webhook (ALL_TOPICS), subscription_id=7144b987f0dc43dd97298c59a81fb67b, subscriber_id=9ff04c77d0a5481c88a320d88518aca9
opal_server-1        | 2025-03-13T13:00:24.139702+0000 | 16 | fastapi_websocket_pubsub.event_broadc...| INFO  | Broadcasting incoming event: {'topic': 'webhook', 'notifier_id': '9ff04c77d0a5481c88a320d88518aca9'}
opal_server-1        | 2025-03-13T13:00:24.139801+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_server-1        | 2025-03-13T13:00:24.139867+0000 | 16 | opal_server.scopes.task                 |DEBUG  | ScopesPolicyWatcherTask triggered on topic id='c9a682aad21741818f0aa601c4660b51' subscriber_id='c7ed60f45f81405bb1d981c657a71f0c' topic='webhook' callback=<bound method BasePolicyWatcherTask._on_webhook of <opal_server.scopes.task.ScopesPolicyWatcherTask object at 0x79a6223b00d0>> notifier_id=None with {'scope_id': 'documents', 'force_fetch': False}
opal_server-1        | 2025-03-13T13:00:24.139909+0000 | 16 | opal_server.scopes.service              |DEBUG  | Syncing (forced=False) scope documents with scope: None
opal_server-1        | 2025-03-13T13:00:24.140244+0000 | 16 | opal_server.scopes.service              |DEBUG  | Sync scope: documents (remote: https://<edited>/poc_testenvironment, branch: <edited>, req_time: 2025-03-13 13:00:24.139905)
opal_server-1        | 2025-03-13T13:00:24.140367+0000 | 16 | opal_server.git_fetcher                 |DEBUG  | Initializing git fetcher: scope_id=documents, url=https://<edited>/poc_testenvironment, branch=<edited>, path=cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0
opal_server-1        | 2025-03-13T13:00:24.140464+0000 | 16 | opal_server.git_fetcher                 | INFO  | Repo not found at //opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0
opal_server-1        | 2025-03-13T13:00:24.140494+0000 | 16 | opal_server.git_fetcher                 | INFO  | Cloning repo at 'https://<edited>/poc_testenvironment' to '//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0'
opal_server-1        | 2025-03-13T13:00:24.141284+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_server-1        | 2025-03-13T13:00:24.141391+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_server-1        | 2025-03-13T13:00:24.141774+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_server-1        | 2025-03-13T13:00:24.142083+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection lost
opal_server-1        | 2025-03-13T13:00:24.142146+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection lost
opal_server-1        | 2025-03-13T13:00:24.142253+0000 | 16 | uvicorn.protocols.http.httptools_impl   | INFO  | 172.18.0.1:46790 - "PUT /scopes HTTP/1.1" 201
opal_client-1        | 2025-03-13T13:00:24.205375+0000 | 19 | opal_client.policy.fetcher              | INFO  | Fetching policy bundle from http://opal_server:7002/scopes/documents/policy
opal_server-1        | 2025-03-13T13:00:24.208113+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_server-1        | 2025-03-13T13:00:24.210096+0000 | 16 | opal_server.scopes.api                  |DEBUG  | Known scopes [Scope(scope_id='documents', policy=GitPolicyScopeSource(source_type='git', url='https://<edited>/poc_testenvironment', auth=GitHubTokenAuthData(auth_type='github_token', token='<edited>'), directories=['policies'], extensions=['.rego'], bundle_ignore=['*_test.rego'], manifest='.manifest', poll_updates=True, branch='<edited>'), data=DataSourceConfig(entries=[DataSourceEntryWithPollingInterval(url='http://caddy:8080/users.json', config=None, topics=['documents:data:data'], dst_path='/users', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='http://caddy:8080/organizations.json', config=None, topics=['documents:data:data'], dst_path='/organizations', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='http://caddy:8080/departments.json', config=None, topics=['documents:data:data'], dst_path='/departments', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='postgresql://documents@db:5432/documents', config={'fetcher': 'PostgresFetchProvider', 'query': "select id::text, concat('ip:', ip) as parent_id from document;", 'connection_params': {'password': 'documents'}, 'fetch_key': 'id'}, topics=['documents:data:data'], dst_path='documents', save_method='PUT', data=None, periodic_update_interval=None)]))], requested scope is documents
opal_server-1        | 2025-03-13T13:00:24.211281+0000 | 16 | opal_server.git_fetcher                 |DEBUG  | Initializing git fetcher: scope_id=documents, url=https://<edited>/poc_testenvironment, branch=<edited>, path=cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0
opal_server-1        | 2025-03-13T13:00:24.216395+0000 | 16 | opal_server.git_fetcher                 |ERROR  | Could not find current branch head
opal_server-1        | 2025-03-13T13:00:24.219025+0000 | 16 | opal_server.scopes.api                  |WARNING | Requested scope documents has invalid repo, returning default scope
opal_server-1        | 2025-03-13T13:00:24.219380+0000 | 16 | datadog.dogstatsd.base                  |WARNING | Error submitting packet: [Errno 111] Connection refused, dropping the packet and closing the socket
opal_server-1        | 2025-03-13T13:00:24.219959+0000 | 16 | opal_common.middleware                  |ERROR  | Uncaught server exception: Scope documents not found
opal_server-1        | Traceback (most recent call last):

opal_client-1        | 2025-03-13T13:00:24.230687+0000 | 19 | opal_common.utils                       |WARNING | Unexpected response code 500: {'error': 'Uncaught server exception'}

opal_server-1        | 2025-03-13T13:00:24.225339+0000 | 16 | uvicorn.protocols.http.httptools_impl   | INFO  | 172.18.0.7:55314 - "GET /scopes/documents/policy?path=. HTTP/1.1" 500
opal_server-1        | 2025-03-13T13:00:24.225514+0000 | 16 | uvicorn.protocols.http.httptools_impl   |ERROR  | Exception in ASGI application

opal_server-1        | 2025-03-13T13:00:25.260166+0000 | 16 | opal_server.git_fetcher                 | INFO  | Clone completed: https://<edited>/poc_testenvironment
opal_server-1        | 2025-03-13T13:00:25.260435+0000 | 16 | opal_server.git_fetcher                 |DEBUG  | Created local branch 'scopes/documents', pointing to: 632f3747c7958f43bbb24224a64ab5c0f033e0f0
opal_server-1        | 2025-03-13T13:00:25.260631+0000 | 16 | opal_server.scopes.service              | INFO  | scope 'documents': Found new commits: old HEAD was 'None', new HEAD is '632f3747c7958f43bbb24224a64ab5c0f033e0f0'
opal_server-1        | 2025-03-13T13:00:25.261269+0000 | 16 | git.cmd                                 |DEBUG  | Popen(['git', 'cat-file', '--batch-check'], cwd=//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0, stdin=<valid stream>, shell=False, universal_newlines=False)
opal_server-1        | 2025-03-13T13:00:25.263084+0000 | 16 | git.cmd                                 |DEBUG  | Popen(['git', 'cat-file', '--batch'], cwd=//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0, stdin=<valid stream>, shell=False, universal_newlines=False)
opal_server-1        | 2025-03-13T13:00:25.267419+0000 | 16 | opal_server.policy.watcher.callbacks    | INFO  | Publishing policy update, directories: ['.', 'policies']
opal_server-1        | 2025-03-13T13:00:25.267664+0000 | 16 | opal_server.scopes.service              | INFO  | Triggering policy update for scope documents: {'update': {'old_policy_hash': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'new_policy_hash': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'changed_directories': ['.', 'policies']}, 'topics': ['policy:.', 'policy:policies']}
opal_server-1        | 2025-03-13T13:00:25.267739+0000 | 16 | opal_common.topics.publisher            |DEBUG  | started topic publisher
opal_server-1        | 2025-03-13T13:00:25.267787+0000 | 16 | opal_common.topics.publisher            | INFO  | Publishing to topics: ['documents:policy:.', 'documents:policy:policies']
opal_server-1        | 2025-03-13T13:00:25.267860+0000 | 16 | opal_common.topics.publisher            |DEBUG  | stopping topic publisher
opal_server-1        | 2025-03-13T13:00:25.268028+0000 | 16 | fastapi_websocket_pubsub.pub_sub_server |DEBUG  | Publishing message to topics: ['documents:policy:.', 'documents:policy:policies']
opal_server-1        | 2025-03-13T13:00:25.268097+0000 | 16 | fastapi_websocket_pubsub.pub_sub_server |DEBUG  | Acquiring broadcaster sharing context
opal_server-1        | 2025-03-13T13:00:25.268164+0000 | 16 | fastapi_websocket_pubsub.event_broadc...|DEBUG  | Did not subscribe to ALL_TOPICS: share count == 3
opal_server-1        | 2025-03-13T13:00:25.268276+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | calling subscription callbacks: topic=documents:policy:., subscription_id=edd0f3a86ba14147980ed50c137a851c, subscriber_id=940fd9d1d83c426eacf7e77c74d511b4
opal_server-1        | 2025-03-13T13:00:25.269609+0000 | 16 | fastapi_websocket_pubsub.rpc_event_me...| INFO  | Notifying other side: subscription={'id': 'edd0f3a86ba14147980ed50c137a851c', 'subscriber_id': '940fd9d1d83c426eacf7e77c74d511b4', 'topic': 'documents:policy:.', 'notifier_id': None}, data=old_policy_hash='632f3747c7958f43bbb24224a64ab5c0f033e0f0' new_policy_hash='632f3747c7958f43bbb24224a64ab5c0f033e0f0' changed_directories=['.', 'policies'], channel_id=940fd9d1d83c426eacf7e77c74d511b4
opal_server-1        | 2025-03-13T13:00:25.269917+0000 | 16 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Calling RPC method - {'message': RpcMessage(request=RpcRequest(method='notify', arguments={'subscription': Subscription(id='edd0f3a86ba14147980ed50c137a851c', subscriber_id='940fd9d1d83c426eacf7e77c74d511b4', topic='documents:policy:.', notifier_id=None), 'data': PolicyUpdateMessage(old_policy_hash='632f3747c7958f43bbb24224a64ab5c0f033e0f0', new_policy_hash='632f3747c7958f43bbb24224a64ab5c0f033e0f0', changed_directories=['.', 'policies'])}, call_id='544f000ef73c4d4f8d69db7148e59026'), response=None)}
opal_server-1        | 2025-03-13T13:00:25.270401+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | calling subscription callbacks: topic=documents:policy:. (ALL_TOPICS), subscription_id=7144b987f0dc43dd97298c59a81fb67b, subscriber_id=9ff04c77d0a5481c88a320d88518aca9
opal_server-1        | 2025-03-13T13:00:25.270498+0000 | 16 | fastapi_websocket_pubsub.event_broadc...| INFO  | Broadcasting incoming event: {'topic': 'documents:policy:.', 'notifier_id': '9ff04c77d0a5481c88a320d88518aca9'}
opal_server-1        | 2025-03-13T13:00:25.270683+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_server-1        | 2025-03-13T13:00:25.270845+0000 | 16 | fastapi_websocket_pubsub.event_notifier |DEBUG  | calling subscription callbacks: topic=documents:policy:policies (ALL_TOPICS), subscription_id=7144b987f0dc43dd97298c59a81fb67b, subscriber_id=9ff04c77d0a5481c88a320d88518aca9
opal_server-1        | 2025-03-13T13:00:25.270926+0000 | 16 | fastapi_websocket_pubsub.event_broadc...| INFO  | Broadcasting incoming event: {'topic': 'documents:policy:policies', 'notifier_id': '9ff04c77d0a5481c88a320d88518aca9'}
opal_server-1        | 2025-03-13T13:00:25.271068+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_client-1        | 2025-03-13T13:00:25.271406+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < TEXT '{"request": {"method": "notify", "arguments": {...26"}, "response": null}' [456 bytes]
opal_server-1        | 2025-03-13T13:00:25.271419+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_client-1        | 2025-03-13T13:00:25.271717+0000 | 19 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC request - {'request': RpcRequest(method='notify', arguments={'subscription': {'id': 'edd0f3a86ba14147980ed50c137a851c', 'subscriber_id': '940fd9d1d83c426eacf7e77c74d511b4', 'topic': 'documents:policy:.', 'notifier_id': None}, 'data': {'old_policy_hash': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'new_policy_hash': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'changed_directories': ['.', 'policies']}}, call_id='544f000ef73c4d4f8d69db7148e59026'), 'channel': '51c9112d8a3e4c68a37d23910d6e2914'}
opal_server-1        | 2025-03-13T13:00:25.271646+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_client-1        | 2025-03-13T13:00:25.271804+0000 | 19 | fastapi_websocket_pubsub.rpc_event_me...| INFO  | Received notification of event
opal_server-1        | 2025-03-13T13:00:25.271797+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_client-1        | 2025-03-13T13:00:25.271922+0000 | 19 | opal_client.policy.updater              | INFO  | Received policy update: topic=documents:policy:., message={'old_policy_hash': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'new_policy_hash': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'changed_directories': ['.', 'policies']}
opal_server-1        | 2025-03-13T13:00:25.271910+0000 | 16 | asyncio_redis.connection                | INFO  | Connecting to redis
opal_client-1        | 2025-03-13T13:00:25.273382+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > TEXT '{"request": null, "response": {"result": "None"...4d4f8d69db7148e59026"}}' [118 bytes]
opal_server-1        | 2025-03-13T13:00:25.272100+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_server-1        | 2025-03-13T13:00:25.272592+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection made
opal_server-1        | 2025-03-13T13:00:25.273005+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection lost
opal_server-1        | 2025-03-13T13:00:25.273186+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection lost
opal_server-1        | 2025-03-13T13:00:25.273730+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection lost
opal_server-1        | 2025-03-13T13:00:25.273889+0000 | 16 | asyncio_redis.protocol                  | INFO  | Redis connection lost
opal_server-1        | 2025-03-13T13:00:25.274217+0000 | 16 | fastapi_websocket_rpc.rpc_channel       |DEBUG  | Handling RPC response - {'response': RpcResponse(result='None', result_type='str', call_id='544f000ef73c4d4f8d69db7148e59026')}
opal_client-1        | 2025-03-13T13:00:28.073875+0000 | 19 | opal_client.policy.fetcher              | INFO  | Fetching policy bundle from http://opal_server:7002/scopes/documents/policy
opal_server-1        | 2025-03-13T13:00:28.079976+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_server-1        | 2025-03-13T13:00:28.082867+0000 | 16 | opal_server.scopes.api                  |DEBUG  | Known scopes [Scope(scope_id='documents', policy=GitPolicyScopeSource(source_type='git', url='https://<edited>/poc_testenvironment', auth=GitHubTokenAuthData(auth_type='github_token', token='<edited>'), directories=['policies'], extensions=['.rego'], bundle_ignore=['*_test.rego'], manifest='.manifest', poll_updates=True, branch='<edited>'), data=DataSourceConfig(entries=[DataSourceEntryWithPollingInterval(url='http://caddy:8080/users.json', config=None, topics=['documents:data:data'], dst_path='/users', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='http://caddy:8080/organizations.json', config=None, topics=['documents:data:data'], dst_path='/organizations', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='http://caddy:8080/departments.json', config=None, topics=['documents:data:data'], dst_path='/departments', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='postgresql://documents@db:5432/documents', config={'fetcher': 'PostgresFetchProvider', 'query': "select id::text, concat('ip:', ip) as parent_id from document;", 'connection_params': {'password': 'documents'}, 'fetch_key': 'id'}, topics=['documents:data:data'], dst_path='documents', save_method='PUT', data=None, periodic_update_interval=None)]))], requested scope is documents
opal_server-1        | 2025-03-13T13:00:28.084042+0000 | 16 | opal_server.git_fetcher                 |DEBUG  | Initializing git fetcher: scope_id=documents, url=https://<edited>/poc_testenvironment, branch=<edited>, path=cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0
opal_server-1        | 2025-03-13T13:00:28.086707+0000 | 16 | git.cmd                                 |DEBUG  | Popen(['git', 'cat-file', '--batch-check'], cwd=//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0, stdin=<valid stream>, shell=False, universal_newlines=False)
opal_server-1        | 2025-03-13T13:00:28.090355+0000 | 16 | git.cmd                                 |DEBUG  | Popen(['git', 'cat-file', '--batch'], cwd=//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0, stdin=<valid stream>, shell=False, universal_newlines=False)
opal_server-1        | 2025-03-13T13:00:28.100162+0000 | 16 | opal_common.git_utils.bundle_maker      | INFO  | Root manifest path doesn't exist, no explicit order would be imposed on policy bundle
opal_server-1        | 2025-03-13T13:00:28.100331+0000 | 16 | opal_common.git_utils.bundle_maker      |DEBUG  | Explicit manifest to be used: []
opal_server-1        | 2025-03-13T13:00:28.103798+0000 | 16 | uvicorn.protocols.http.httptools_impl   | INFO  | 172.18.0.7:37046 - "GET /scopes/documents/policy?path=. HTTP/1.1" 200
opal_client-1        | 2025-03-13T13:00:28.104285+0000 | 19 | opal_client.policy.fetcher              | INFO  | Fetched valid bundle, id: 632f3747c7958f43bbb24224a64ab5c0f033e0f0
opal_client-1        | 2025-03-13T13:00:28.104577+0000 | 19 | opal_client.policy.updater              | INFO  | Got policy bundle with 1 rego files, 0 data files, commit hash: '632f3747c7958f43bbb24224a64ab5c0f033e0f0'
opal_client-1        | 2025-03-13T13:00:28.105839+0000 | 19 | opal_client.engine.logger               | INFO  | Received request.    GET /v1/policies
opal_client-1        | 2025-03-13T13:00:28.106189+0000 | 19 | opal_client.engine.logger               | INFO  | Sent response.       GET /v1/policies -> 200
opal_client-1        | 2025-03-13T13:00:28.107470+0000 | 19 | opal_client.engine.logger               | INFO  | Received request.    PUT /v1/policies/policies/documents.rego
opal_client-1        | 2025-03-13T13:00:28.115557+0000 | 19 | opal_client.engine.logger               | INFO  | Sent response.       PUT /v1/policies/policies/documents.rego -> 200
opal_client-1        | 2025-03-13T13:00:28.116204+0000 | 19 | opal_client.policy_store.opa_client     |DEBUG  | processing store transaction: {'id': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'actions': ['set_policies'], 'transaction_type': <TransactionType.policy: 'policy'>, 'success': True, 'error': '', 'creation_time': '2025-03-13T13:00:28.104650', 'end_time': '2025-03-13T13:00:28.116028', 'remotes_status': [{'remote_url': 'http://opal_server:7002/scopes/documents/policy', 'succeed': True, 'error': None}]}
opal_client-1        | 2025-03-13T13:00:28.116320+0000 | 19 | opal_client.policy.updater              | INFO  | Refetching policy code (delta bundle), base hash: '632f3747c7958f43bbb24224a64ab5c0f033e0f0'
opal_client-1        | 2025-03-13T13:00:28.116427+0000 | 19 | opal_client.policy.fetcher              | INFO  | Fetching policy bundle from http://opal_server:7002/scopes/documents/policy
opal_server-1        | 2025-03-13T13:00:28.117799+0000 | 16 | opal_common.authentication.deps         |DEBUG  | JWT verification disabled, cannot verify requests!
opal_server-1        | 2025-03-13T13:00:28.118442+0000 | 16 | opal_server.scopes.api                  |DEBUG  | Known scopes [Scope(scope_id='documents', policy=GitPolicyScopeSource(source_type='git', url='https://<edited>/poc_testenvironment', auth=GitHubTokenAuthData(auth_type='github_token', token='<edited>'), directories=['policies'], extensions=['.rego'], bundle_ignore=['*_test.rego'], manifest='.manifest', poll_updates=True, branch='<edited>'), data=DataSourceConfig(entries=[DataSourceEntryWithPollingInterval(url='http://caddy:8080/users.json', config=None, topics=['documents:data:data'], dst_path='/users', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='http://caddy:8080/organizations.json', config=None, topics=['documents:data:data'], dst_path='/organizations', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='http://caddy:8080/departments.json', config=None, topics=['documents:data:data'], dst_path='/departments', save_method='PUT', data=None, periodic_update_interval=30.0), DataSourceEntryWithPollingInterval(url='postgresql://documents@db:5432/documents', config={'fetcher': 'PostgresFetchProvider', 'query': "select id::text, concat('ip:', ip) as parent_id from document;", 'connection_params': {'password': 'documents'}, 'fetch_key': 'id'}, topics=['documents:data:data'], dst_path='documents', save_method='PUT', data=None, periodic_update_interval=None)]))], requested scope is documents
opal_server-1        | 2025-03-13T13:00:28.118866+0000 | 16 | opal_server.git_fetcher                 |DEBUG  | Initializing git fetcher: scope_id=documents, url=https://<edited>/poc_testenvironment, branch=<edited>, path=cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0
opal_server-1        | 2025-03-13T13:00:28.119513+0000 | 16 | git.cmd                                 |DEBUG  | Popen(['git', 'cat-file', '--batch-check'], cwd=//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0, stdin=<valid stream>, shell=False, universal_newlines=False)
opal_server-1        | 2025-03-13T13:00:28.121144+0000 | 16 | git.cmd                                 |DEBUG  | Popen(['git', 'cat-file', '--batch'], cwd=//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0, stdin=<valid stream>, shell=False, universal_newlines=False)
opal_server-1        | 2025-03-13T13:00:28.125269+0000 | 16 | opal_common.git_utils.bundle_maker      | INFO  | Root manifest path doesn't exist, no explicit order would be imposed on policy bundle
opal_server-1        | 2025-03-13T13:00:28.125604+0000 | 16 | git.cmd                                 |DEBUG  | Popen(['git', 'diff-tree', '632f3747c7958f43bbb24224a64ab5c0f033e0f0', '632f3747c7958f43bbb24224a64ab5c0f033e0f0', '-r', '--abbrev=40', '--full-index', '-M', '--raw', '-z', '--no-color'], cwd=//opal/.local/state/opal/git_sources/cb375f4436b0c1ab9bb78791b679c9700c2531e385f242d900b1edf2afb3e87c-0, stdin=None, shell=False, universal_newlines=False)
opal_server-1        | 2025-03-13T13:00:28.127784+0000 | 16 | uvicorn.protocols.http.httptools_impl   | INFO  | 172.18.0.7:37048 - "GET /scopes/documents/policy?path=.&base_hash=632f3747c7958f43bbb24224a64ab5c0f033e0f0 HTTP/1.1" 200
opal_client-1        | 2025-03-13T13:00:28.128163+0000 | 19 | opal_client.policy.fetcher              | INFO  | Fetched valid bundle, id: 632f3747c7958f43bbb24224a64ab5c0f033e0f0
opal_client-1        | 2025-03-13T13:00:28.128428+0000 | 19 | opal_client.policy.updater              | INFO  | got policy bundle (delta): '632f3747c7958f43bbb24224a64ab5c0f033e0f0' -> '632f3747c7958f43bbb24224a64ab5c0f033e0f0', manifest: [], deleted: None
opal_client-1        | 2025-03-13T13:00:28.128674+0000 | 19 | opal_client.policy_store.opa_client     |DEBUG  | processing store transaction: {'id': '632f3747c7958f43bbb24224a64ab5c0f033e0f0', 'actions': ['set_policies'], 'transaction_type': <TransactionType.policy: 'policy'>, 'success': True, 'error': '', 'creation_time': '2025-03-13T13:00:28.128481', 'end_time': '2025-03-13T13:00:28.128562', 'remotes_status': [{'remote_url': 'http://opal_server:7002/scopes/documents/policy', 'succeed': True, 'error': None}]}
opal_client-1        | 2025-03-13T13:00:42.962565+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < PING d0 ea b7 d9 [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.963243+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > PONG d0 ea b7 d9 [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.963780+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < PING 96 77 c9 b1 [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.964068+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > PONG 96 77 c9 b1 [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.964352+0000 | 19 | websockets.legacy.protocol              |DEBUG  | % sending keepalive ping
opal_client-1        | 2025-03-13T13:00:42.964628+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > PING 1c 6d 44 b1 [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.965195+0000 | 19 | websockets.legacy.protocol              |DEBUG  | % sending keepalive ping
opal_client-1        | 2025-03-13T13:00:42.965499+0000 | 19 | websockets.legacy.protocol              |DEBUG  | > PING 46 9a db 9a [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.965979+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < PONG 1c 6d 44 b1 [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.966313+0000 | 19 | websockets.legacy.protocol              |DEBUG  | < PONG 46 9a db 9a [binary, 4 bytes]
opal_client-1        | 2025-03-13T13:00:42.966543+0000 | 19 | websockets.legacy.protocol              |DEBUG  | % received keepalive pong
opal_client-1        | 2025-03-13T13:00:42.966769+0000 | 19 | websockets.legacy.protocol              |DEBUG  | % received keepalive pong
opal_server-1        | 2025-03-13T13:00:50.932716+0000 | 16 | opal_server.scopes.task                 | INFO  | Periodic sync

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@dadrus