Decouple decision_logs.console from general log level

[anderseknert]

Expected Behavior

Setting decision_logs.console=true intuitively means "I want my decisions printed to console", and this is what I would expect regardless of the "application" log level setting.

Actual Behavior

decision_logs.console=true currently works only if --log-level is set to INFO or DEBUG.

Steps to Reproduce the Problem

Start server with decision_logs.console=true and --log-level=error.

Additional Info

I've seen mentions of this here and there but could not find a ticket for tracking this.

One thing I'll want to note here is that I think the question of the "access logs" currently printed on INFO is a separate issue - if decision_logs.console=true is set it should be respected regardless of --log-level IMO.

[patrick-east]

It would be kind of cool if we had the option to set them at their own level, sort of to your point that if they are enabled they should show up regardless of overall log level setting. Unfortunately it doesn't seem like Logrus supports that :(

One pretty easy approach would be to make it configurable, something like:

decision_logs:
    console: true
    console_log_level: warn

(or something like that)

That way we don't have to try and pick a level automatically (or make deployers try and figure out where they would go, they can set it and be confident in what level they'll show up at)

[tsandall]

I think we should be able to create a new logrus.Logger inside the decision logging plugin and set the level on it to DEBUG or TRACE or whatever so that the log messages are always emitted (https://godoc.org/github.com/sirupsen/logrus#Logger.SetLevel).

We'll need some way to plumb the log format (and any other log options we introduce in the future) into the decision logger implementation.

I prefer this approach because then we don't have to introduce another configuration option that users need to be aware of.

[anderseknert]

Agreed - if setting decision_logs.console=true then having them printed is obviously the intended behavior, or at least I can't see from here why one would want something else, like that to be conditional on the log level.

[tsandall]

We should probably do the same for the status plugin (which also supports console logging). This way users could just run OPA with --log-level=error (since the INFO messages are not particularly important).

[tsandall]

It looks we have a regression in v0.29.4.

W/ v0.28.0 this works fine:

$ docker run -it --rm -p 8181:8181 openpolicyagent/opa:0.28.0 run --server --log-level=error --set=decision_logs.console=true

In another terminal run curl localhost:8181/v1/data/system/version. Observe the log below:

{"decision_id":"0d542d8f-a073-4f1c-a3c8-bbea4b39e284","labels":{"id":"f337a30d-d38b-4d7a-97ad-80660d40ee13","version":"0.28.0"},"level":"info","metrics":{"counter_server_query_cache_hit":0,"timer_rego_external_resolve_ns":300,"timer_rego_input_parse_ns":200,"timer_rego_query_compile_ns":59400,"timer_rego_query_eval_ns":17900,"timer_rego_query_parse_ns":226700,"timer_server_handler_ns":390100},"msg":"Decision Log","path":"system/version","requested_by":"172.17.0.1:42380","result":{"build_commit":"3fbcd71","build_hostname":"5c684f011e1a","build_timestamp":"2021-04-27T13:52:19Z","version":"0.28.0"},"time":"2021-07-15T18:15:27Z","timestamp":"2021-07-15T18:15:27.2753534Z","type":"openpolicyagent.org/decision_logs"}

With v0.29.4 no log gets emitted. I'm guessing the SDK changes are to blame.

[tsandall]

I'm going to open a new issue to track the bug.