Log level set to debug changes behavior in 0.16.11

[julianhille]

Preflight checklist

• I agree to follow this project's Code of Conduct.
• I have read and am following this repository's Contribution Guidelines."
• I could not find a solution in the existing issues, docs, nor discussions.

Describe the bug

If the log level is set to debug the apps behavior for loading rule sets changes.

How can the bug be reproduced

Have 0.16.11 installed
Have log level set to debug
Have two conflicting rule sets.

Set A:

apiVersion: heimdall.dadrus.github.com/v1alpha4
kind: RuleSet
metadata:
  name: access-rule-A
spec:
  rules:
    - id: restrict-A
      match:
        routes:
          - path: /**
      execute:
        - authenticator: app_jwt
        - authorizer: allow_preflight
        - finalizer: noop

Set B:

apiVersion: heimdall.dadrus.github.com/v1alpha4
kind: RuleSet
metadata:
  name: access-rule-B
spec:
  rules:
    - id: restrict-B
      match:
        routes:
          - path: /**
      execute:
        - authenticator: other_app_jwt
        - authorizer: allow_preflight
        - finalizer: noop

of course you need the authenticators configured to be working otherwise this would be pointless :>

If the debug log level is set:

• i see logs about
  • loading /merging rulesets
  • conflicting rules, as expected
• the secured endpoint does work as expected (403 if no auth, 200 if auth is valid)

if the debug log level is not set:

• i see not logs about loading and merging rules (Startup logs missing if not log level set to debug even though its a warn / info log #3160 )
• the secured endpoint das ALWAYS give 403, no matter if request is valid or not

My guess: order of loading rules / merging rules somehow differs, but just a gut feeling and a bit of assumptions

Relevant log output

Relevant configuration

log:
  level: debug

Version

0.16.11

On which operating system are you observing this issue?

None

In which environment are you deploying?

None

Additional Context

Even though 0.16.11 is already out of date i post this as this is very unexpected that the outcome of merging rulesets works differently. And maybe there is somehow any underlying bug.

Tested version:

• 0.16.11
• 0.16.2
• 0.16.8
• 0.16.10

None showed that behaviour

[dadrus]

Thank you for that report @julianhille.

I'm struggling with the following two sentences from you:

... to not including the log level debug, it does not validate.
With setting it to debug the rule set logs conflicts and then it will work.

I don't understand what you mean by "it does not validate" and by "the rule set logs conflicts and then it will work". Could you please elaborate more on that please?

[julianhille]

Thank you for that report @julianhille.

I'm struggling with the following two sentences from you:

... to not including the log level debug, it does not validate.
With setting it to debug the rule set logs conflicts and then it will work.

I don't understand what you mean by "it does not validate" and by "the rule set logs conflicts and then it will work". Could you please elaborate more on that please?

The line started above the code block :>

Tried to rephrase and removed the codeblock about the log level.

[dadrus]

That's strange. Could you please share your config file for heimdal (you can omit the definition section of the mechanisms)? And which kubernetes version are you using?

Since the two issues, you've created and linked seem to be related, you don't need to share the configuration in both tickets

[dadrus]

I think I can explain the behavior you observe:

1. The two RuleSets are conflicting (/** in both), so they cannot be active at the same time.
2. During loading, one RuleSet is accepted and the other one is rejected with conflicting rules.
3. Which one “wins” depends on a) Kubernetes event ordering and b) timing during startup/reconcile. With other words it is not predictable in this conflict scenario.
4. This is independent from the auth logic itself; debug mainly makes the sequence visible and timing differences can make it look like log level changes behavior.

This also explains the 403 result: if the rule from the RuleSet that does not match your token is active, requests will be denied.

You can always verify a RuleSet status (status.activeIn + Conditions), for example via kubectl get rulesets -A -o yaml or kubectl describe ruleset <name> -n <ns>.

[dadrus]

Btw. Rule sets were never merged. A rule set is kind of a security closure around rules. This is done by intention to ensure rules from one rule set cannot override the behavior of rules defined in another rule set. This was the case from the very beginning of the project. V0.15.0 introduced some additional measures to make it even more strict.

Therefore, I really wonder what was working in the past. Given your example rules, it must always be the case, that either the one or the other was active in your setup, but not both

[julianhille]

Btw. Rule sets were never merged. A rule set is kind of a security closure around rules. This is done by intention to ensure rules from one rule set cannot override the behavior of rules defined in another rule set. This was the case from the very beginning of the project. V0.15.0 introduced some additional measures to make it even more strict.

Therefore, I really wonder what was working in the past. Given your example rules, it must always be the case, that either the one or the other was active in your setup, but not both

It was Not Working in the past. I introduced the bug of conflicting Rules and changing the Version at the Same time. But it was unseen as IT somehow works with 0.16.11 and the debug Log Set.

It is very reliably odd.
When using 0.16.11 and the debug Log Set. Vs any other Version.
I mean of course i fixed the conflicting Rules but Just wanted to make Sure you know and IT.might be a Bug in the Setup somehow/somewhere

[dadrus]

Thanks @julianhille, and I really appreciate you taking the time to clarify this.

From what I understand, there are two separate topics here:

1. missing logs when log level is not set to debug
2. functional behavior difference

I’d like to treat them separately.

1. Logging visibility
   As mentioned in Startup logs missing if not log level set to debug even though its a warn / info log #3160: if log.level is not set, the default is error. That is why info and warn logs are not visible.

   Also, higher verbosity includes lower levels. For example:

   • info includes warn, error, fatal, panic
   • error includes error, fatal, panic

   Access/audit logs are always emitted at info, regardless of the configured log level.

   I intentionally set the default to error for performance reasons, but I agree this may be confusing. If you think the default should be warn or info, I’d appreciate you discussing that with the community.

2. Functional behavior difference
   Even though I shared my current speculation, I want to understand what is actually happening in your setup.

   Since you described it as reliably reproducible (at least this is my understanding of your “reliably odd” statement), could you please run both scenarios (with debug and without debug) and share the results of kubectl get rulesets -A -o yaml.

   I’m specifically interested in status.activeIn and status.conditions for the relevant RuleSet resources. Without that, we can’t determine whether the 403 is caused by different active RuleSet selection.

   Also, I want to confirm your latest statement:

   I mean of course i fixed the conflicting Rules but Just wanted to make Sure you know and IT.might be a Bug in the Setup somehow/somewhere

   Do you mean you now have a fixed (non-conflicting) setup and still see different behavior depending on log level?
   If yes, that would indeed indicate a serious issue.

   I really want to nail this down, but I need that status data to proceed. Thank you again for your time and for your help