Standalone Envoy logging

[3goats]

Hi - I've just followed the standalone envoy which works as per the documentation. However, I can't seem to find anywhere that logs the policy processing. i.e. How do see in some logs where a policy passes or fails and the reason its failing ?

[charlieegan3]

Hey, I think you're looking for https://www.openpolicyagent.org/docs/latest/management-decision-logs/

You can log these to the console with:

decision_logs:
    console: true

It's also possible to ship the logs to a remote endpoint if need be too over http.

[3goats]

Thanks for this. Where in the tutorial would this be configured ?

I see in the app.yaml that --set=decision_logs.console=true is already configured as one of the arguments.

[charlieegan3]

Ahh, I'd missed that. Do you not see {"decision_id":"xxx"... logs in the console for the OPA container?

[3goats]

OK - I think I've found the decision logs. The logs for the "openpolicyagent/opa:latest-envoy" service is very noisy and they were buried in a continuous stream of health info logs.

[charlieegan3]

👍 generally it'd be recommended to send the decision logs to some audit logging sink.

[3goats]

OK so I see the {"decision_id":"xxx"... in the logs. I don't see anything particularly meaningful other than a result=false. Is there a way to see what is causing the policy to fail ?

[charlieegan3]

Here's an example log from my local OPA. It's not running the Envoy example, but it works for a comparison.

{
  "decision_id": "3b948ce8-2706-4691-96a3-544ece2c25cd",
  "input": {},
  "labels": {
    "id": "0d05df96-08b3-49f2-894a-b26b8b6b89f0",
    "version": "0.56.0"
  },
  "level": "info",
  "metrics": {
    "counter_server_query_cache_hit": 1,
    "timer_rego_input_parse_ns": 113875,
    "timer_rego_query_eval_ns": 327500,
    "timer_server_handler_ns": 613917
  },
  "msg": "Decision Log",
  "path": "example/allow",
  "req_id": 2,
  "requested_by": "127.0.0.1:51783",
  "result": true,
  "time": "2023-10-03T10:20:36+01:00",
  "timestamp": "2023-10-03T09:20:36.792634Z",
  "type": "openpolicyagent.org/decision_logs"
}

I can see what the input was - {} in my case. I can see the policy used "example/allow" and what the result of the policy was true (the request was allowed). This is enough for me to replicate the issue and, if the result is unexpected, debug the result.

I can test this out on a local opa by running:

curl -X "POST" "http://localhost:8181/v1/data/example/allow" \
     -H 'Content-Type: text/plain; charset=utf-8' \
     -d "{\"input\":{}}"

The ops-envoy plugin implements the external auth API: https://www.envoyproxy.io/docs/envoy/latest/api-v3/service/auth/v3/external_auth.proto

You can see how the response from the policy evaluation is fashioned into a response here: https://github.com/open-policy-agent/opa-envoy-plugin/blob/761f94d87f3ea237fa76e6322aa3bf50c1f5bae2/internal/internal.go#L349

Basically, you have three options:

• return a bool for allow or deny
• return a map with allowed as false, and http_status and body.
• return a map with allowed as true, optional headers to add / remove etc
  Hope that helps. Not sure if you looking for info in just the decision logs or the response itself too.

[anderseknert]

Adding to @charlieegan3's great points above: OPA is not aware of what constitutes "success" or "failure" to you — it's just data in, data out based on the policy you've provided. Changing a rule name from "allow" to "deny" obviously changes the semantics entirely for us, but it's just a rule like any other to OPA. If you want to use decision logs for debugging, copying the input and running it offline against your policy, using opa eval, the Rego Playground, or whatever you prefer, is often the best way to do it. You can enable coverage to see which lines got evaluated. For opa eval, that'd be the --coverage flag, and in the Rego Playground that's a toggle under "Options". There are also more advanced options for tracing, or more simple ones like sprinkling some print statements around your policy to see what's getting printed.