Bundle fails to load

[AleksanderBrzozowski]

Hi! We use OPA in production, in a few different k8s clusters.

Here is the config that we use:

config:
  default_decision: /authz

  services:
    - name: policy-service
      url: http://policy-service.namespace:8080

  bundles:
    authz:
      service: policy-service
      resource: authz
      persist: true
      polling:
        min_delay_seconds: 10
        max_delay_seconds: 20

  persistence_directory: /var/opa

  decision_logs:
    console: true

  status:
    prometheus: true

  plugins:
    envoy_ext_authz_grpc:
      addr: :9191
      path: /authz
      dry-run: false
      enable-reflection: true

Basically, the bundle is fetched from policy-service, and persisted under /var/opa.

This is a mechanism that allows us to have a fallback in case there is a problem to fetch bundle from policy-service (network issue, or a service is down).

The /var/opa dir is a mounted volume, and is shared between multiple pods:

apiVersion: v1
kind: PersistentVolumeClaim
metadata:
  name: ...
spec:
  accessModes:
    - ReadWriteMany
  resources:
    requests:
      storage: 1Gi
  storageClassName: efs-dynamic-sc-a # AWS Elastic File System

The problem we are encountering is that OPA deployment in one of our k8s clusters fails to load bundle in most cases with such an error:

Bundle load failed: bundle read failed: failed to copy file x/data.json: unexpected EOF

From time to time bundle is loaded successfully, but in most cases it fails (based on thebundle_failed_load_counter and bundle_loaded_counter).

I wonder if you can help to find what might be the reason of this failure? The bundle is pretty big, it contains a lot of data. However, in four different kubernetes clusters, which use the same bundle, we don't have this issue.

[AleksanderBrzozowski]

I've restarted the service, and changed log level to "info", and found out that the bundle is not refreshed according to the polling settings. I waited a few minutes and it wasn't refreshed at all - I haven't found any logs about failures, and the counters were equal to 0.

[AleksanderBrzozowski]

So, I am filtering logs by plugin=bundle, here is what I found (one of the pods):

(logs are sorted from newest to oldest)

{"level":"error","msg":"Bundle load failed: bundle read failed: failed to copy file project-billing-state/data.json: unexpected EOF","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:44Z"}{"level":"info","msg":"Starting bundle loader.","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:49Z"}
{"level":"debug","msg":"Bundle loaded from disk and activated successfully.","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:49Z"}
{"level":"debug","msg":"Closing storage transaction (2).","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:49Z"}
{"level":"debug","msg":"Opened storage transaction (2).","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:49Z"}
{"level":"debug","msg":"Bundle activation in progress (d7563971-2616-48f6-9589-d53928842db3). Opening storage transaction.","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:49Z"}

Note that it took 16 minutes from Starting bundle loader. to failed to copy file. Before, the bundle was successfully loaded from disc:

Bundle loaded from disk and activated successfully.

However, another pod works ok, and updates bundle regularly without troubles:

{"level":"info","msg":"Bundle loaded and activated successfully.","name":"authz","plugin":"bundle","time":"2025-01-17T15:14:00Z"}
{"level":"debug","msg":"Bundle persisted to disk successfully at path /var/opa/bundles/authz.","name":"authz","plugin":"bundle","time":"2025-01-17T15:14:00Z"}
{"level":"debug","msg":"Persisting bundle to disk in progress.","name":"authz","plugin":"bundle","time":"2025-01-17T15:14:00Z"}
{"level":"debug","msg":"Closing storage transaction (279).","name":"authz","plugin":"bundle","time":"2025-01-17T15:14:00Z"}
{"level":"debug","msg":"Opened storage transaction (279).","name":"authz","plugin":"bundle","time":"2025-01-17T15:13:59Z"}
{"level":"debug","msg":"Bundle activation in progress (12d2f23e-894a-42e8-b26d-111aa106f581). Opening storage transaction.","name":"authz","plugin":"bundle","time":"2025-01-17T15:13:59Z"}

The setup is that we run 4 pods of OPA, and only one of the pods is able to refresh bundle, and the rest three get stuck in Starting bundle loader.

[ashutosh-narkar]

Feel free to file an issue and please provide us the steps to reproduce it. I'm not sure if this is an OPA issue or something specific to your setup.

[AleksanderBrzozowski]

@ashutosh-narkar

Do you feel that it is fine to use one shared volume for OPA deployment? I mean, is it fine to share a directory that multiple OPA instances use to write bundle?

Btw. I exported more logs from the service:

  {"level":"debug","msg":"Download in progress.","time":"2025-01-17T15:20:09Z"},
  {"headers":{"Content-Type":["application/gzip"],"Date":["Fri, 17 Jan 2025 15:20:09 GMT"],"Server":["istio-envoy"],"X-Envoy-Upstream-Service-Time":["1917"]},"level":"debug","method":"GET","msg":"Received response.","status":"200 OK","time":"2025-01-17T15:20:09Z","url":"https://bundle-service.example.com/authz"},
  {"headers":{"Authorization":["REDACTED"],"Prefer":["modes=snapshot,delta"],"User-Agent":["Open Policy Agent/0.70.0-envoy-5 (linux, amd64)"]},"level":"debug","method":"GET","msg":"Sending request.","time":"2025-01-17T15:20:07Z","url":"https://bundle-service.example.com/authz"},
  {"level":"debug","msg":"Download starting.","time":"2025-01-17T15:20:07Z"},
  {"level":"debug","msg":"Waiting 18.178450923s before next download/retry.","time":"2025-01-17T15:19:49Z"},
{"level":"info","msg":"Bundle loaded and activated successfully.","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:49Z"},
  {"level":"debug","msg":"Bundle persisted to disk successfully at path /var/opa/bundles/authz.","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:49Z"},
  {"level":"debug","msg":"Persisting bundle to disk in progress.","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:48Z"},
  {"level":"debug","msg":"Closing storage transaction (390).","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:48Z"},
  {"level":"debug","msg":"Opened storage transaction (390).","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:47Z"},
  {"level":"debug","msg":"Bundle activation in progress (12d2f23e-894a-42e8-b26d-111aa106f581). Opening storage transaction.","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:47Z"},
  {"level":"debug","msg":"Download in progress.","time":"2025-01-17T15:19:46Z"},
  {"headers":{"Content-Type":["application/gzip"],"Date":["Fri, 17 Jan 2025 15:19:45 GMT"],"Server":["istio-envoy"],"X-Envoy-Upstream-Service-Time":["1840"]},"level":"debug","method":"GET","msg":"Received response.","status":"200 OK","time":"2025-01-17T15:19:46Z","url":"https://bundle-service.example.com/authz"},
  {"headers":{"Authorization":["REDACTED"],"Prefer":["modes=snapshot,delta"],"User-Agent":["Open Policy Agent/0.70.0-envoy-5 (linux, amd64)"]},"level":"debug","method":"GET","msg":"Sending request.","time":"2025-01-17T15:19:43Z","url":"https://bundle-service.example.com/authz"},
  {"level":"debug","msg":"Download starting.","time":"2025-01-17T15:19:43Z"},
  {"level":"debug","msg":"Waiting 0s before next download/retry.","time":"2025-01-17T15:19:43Z"},
{"level":"error","msg":"Bundle load failed: bundle read failed: failed to copy file projects/data.json: unexpected EOF","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:43Z"},
  {"level":"debug","msg":"Download in progress.","time":"2025-01-17T15:03:56Z"},
  {"headers":{"Content-Type":["application/gzip"],"Date":["Fri, 17 Jan 2025 15:03:56 GMT"],"Server":["istio-envoy"],"X-Envoy-Upstream-Service-Time":["2272"]},"level":"debug","method":"GET","msg":"Received response.","status":"200 OK","time":"2025-01-17T15:03:56Z","url":"https://bundle-service.example.com/authz"},
  {"level":"debug","msg":"Server initialized.","time":"2025-01-17T15:03:53Z"},
  {"headers":{"Authorization":["REDACTED"],"Prefer":["modes=snapshot,delta"],"User-Agent":["Open Policy Agent/0.70.0-envoy-5 (linux, amd64)"]},"level":"debug","method":"GET","msg":"Sending request.","time":"2025-01-17T15:03:53Z","url":"https://bundle-service.example.com/authz"},
  {"level":"debug","msg":"Download starting.","time":"2025-01-17T15:03:53Z"},
  {"level":"debug","msg":"Bundle loaded from disk and activated successfully.","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:53Z"},
  {"level":"debug","msg":"Closing storage transaction (2).","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:53Z"},
  {"level":"debug","msg":"Opened storage transaction (2).","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:53Z"},
  {"level":"debug","msg":"Bundle activation in progress (d7563971-2616-48f6-9589-d53928842db3). Opening storage transaction.","name":"authz","plugin":"bundle","time":"2025-01-17T15:03:53Z"}

I am not sure if I read logs correctly, but to me it seems that the response is successful, or at least the headers part is success (takes 3 seconds to respond with bundle):

  {"headers":{"Content-Type":["application/gzip"],"Date":["Fri, 17 Jan 2025 15:03:56 GMT"],"Server":["istio-envoy"],"X-Envoy-Upstream-Service-Time":["2272"]},"level":"debug","method":"GET","msg":"Received response.","status":"200 OK","time":"2025-01-17T15:03:56Z","url":"https://bundle-service.example.com/authz"},

Then, the body (gzip file with bundle?) is being downloaded:

  {"level":"debug","msg":"Download in progress.","time":"2025-01-17T15:03:56Z"},

Which all of the sudden fails, after almost 16 minutes (!):

{"level":"error","msg":"Bundle load failed: bundle read failed: failed to copy file projects/data.json: unexpected EOF","name":"authz","plugin":"bundle","time":"2025-01-17T15:19:43Z"}

This seem to be a network issue, WDYT?

[ashutosh-narkar]

Seems like a network issue.

Do you feel that it is fine to use one shared volume for OPA deployment? I mean, is it fine to share a directory that multiple OPA instances use to write bundle?

Are you configuring OPA to write in specific locations?

[AleksanderBrzozowski]

Yup. I am mounting a volume under /var/opa/bundles, and multiple instances are sharing one volume.

I tried to downscale to one instance in order to check if this can be causing the issue, but it didn't help.

Anyways, I will try to investigate network traffic.