Find out matching policy

In the service I'm implementing, I'd like to log which policy allowed the request.

From the following comment, I understand that it is currently not possible:

Lines 27 to 30 in 4223d97

    
           // Although the manager is responsible of matching the policies, it might decide to just scan for 
        
           // subjects, it might return all policies, or it might have a different pattern matching than Golang. 
        
           // Thus, we need to make sure that we actually matched the right policies. 
        
           return l.DoPoliciesAllow(r, policies)

Would you agree if I contribute a FindMatchingPolicy() on the manager interface? Or do you have a better idea?

Thanks!

If you just want log which policy did that, why not just add logging capabilities to DoPoliciesAllow?

If you just want log which policy did that, why not just add logging capabilities to DoPoliciesAllow?

I'd like to log to a particular format (structured log in JSON) with additional information that will be processed for metrics, anomaly detection, etc.

Maybe, now that DoPoliciesAllow() is exposed (#77), the best would be to make it return the matching policy. It would be a breaking change though (/cc @pnegahdar)

I'd like to log to a particular format (structured log in JSON) with additional information that will be processed for metrics, anomaly detection, etc.

So why aren't you doing that here?

So why aren't you doing that here?

I'm sorry, I don't know what you mean or how I could do that 😓

https://github.com/ory/ladon/blob/master/ladon.go#L79

allowed = true
logger.Printf("Found matching policy: %+v", p)

Do you mean that I should fork and add the lines I need there?

It won't just be a simple call to logger.Printf() but something very specific like that would look like this:

import (
	log "github.com/sirupsen/logrus"
)

...

log.WithFields(
	log.Fields{
		"subject":  r.Subject,
		"action":   r.Action,
		"resource": r.Resource,
		"policy":   {
			"id":          p.GetID(),
			"description": p.GetDescription(),
		},
	},
).Info("request.authorization")

Using global logging is definitely considered bad practice, one possibility would be to have a logrus.FieldLogger field in the matcher (or any other struct that makes sense) and check if the logger is != nil and if it is, in fact, not nil, log that stuff.

It would however restrict how logging would be layouted as well as what loggers one may use, so I'm not 100% on this and open to alternatives (preferable without breaking BC)

It would however restrict how logging would be layouted as well as what loggers one may use, so I'm not 100% on this and open to alternatives (preferable without breaking BC)

Since the exposure of DoPoliciesAllow() is only 30 days old, and not documented, we could revisit its signature IMO. But that's your call.

Otherwise, we could imagine having some kind of callback function (or similar concept for go)

ladon.Matcher.OnPolicyMatched := func (policy *Policy) {
      // custom log here
}

I think the current interface is low-level enough to allow you to do the logging you need.

@leplatrem have you considered doing something like the following:

policiesToCheck := []policies{...}
allowed = false
for _, p := range(policiesToCheck) {
      err := ladon.DoPoliciesAllow(r, []policies{p})
      if err != nil {
          allowed = true
          logger.InfoF("Allowed with policy %+v", p)
          break
       }
}

I do think the interface would be nicer and imply single policy usage if it was variadic though.

@leplatrem have you considered doing something like the following:

Thanks, this would work indeed. I would have preferred to avoid additional iterations of course, but if there is a strong resistance against changing the signature of DoPoliciesAllow(), I'll stop insisting.

What would be wrong with changing from:

func (l *Ladon) DoPoliciesAllow(r *Request, policies []Policy) (err error) {

to

func (l *Ladon) DoPoliciesAllow(r *Request, policies []Policy) (matched Policy, err error) {

?

(appart from breaking changes of low-level users obviously)

Note: By the way, I couldn't find any usage of DoPoliciesAllow() in Github public repos :)

You will not receive just one matched policy, it will be 0...n. Please note though that any additional run of DoPoliciesAllow on every request will significantly increase runtime complexity, as we need to range over a potential large candidate set with usually one or more regular expressions. Thus I'm still not entirely convinced that that's a good way to solve it.

I would have preferred to avoid additional iterations of course

I don't think the perf cost is high here (the go compiler is pretty good).

+1 on the not returning the matched policy since it would be implying first match. I dont think a change is needed but if anything I'd suggest:

Edit note by @arekkas: DO NOT use HasAllowedPolicy as it contains a severe security issue

// Checks if policy is allowed
func (l *Ladon) DoesPolicyAllow(r *Request, policy Policy) (err error) {}

// Returns when first matching policies allows
func (l *Ladon) HasAllowedPolicy(r *Request, policies ...Policy) (bool) {
        allowed = false
        for _, policy := range(policiesToCheck) {
               err := l.DoesPolicyAllow(r, p)
               if err != nil {
                    allowed = true
                    break
              }
        }
        return allowed
}

This is a style choice but the method names are clear and it gives you a low and somewhat higher level API to wrap logging, etc around.

I don't think the perf cost is high here (the go compiler is pretty good).

This was not an assumption but something that I've tested extensively with benchmarks while trying to improve the runtime complexity of Ladon ;) Since policy checking is such a crucial part in the request lifecycle it's important to be as fast as possible. Of course, these effects start showing at 10k-100k policies, below that it's not a problem usually. But be aware that, the more duplication you put in there, the less policies you'll be able to process.

Regarding HasAllowedPolicy, it actually contains a severe security flaw as the order of Deny > Allow > Default is not kept since we're breaking once we found something that is allowed. Please do not use that function production. I edited your post so nobody comes to the idea to use this function when searching through the GitHub issues. I hope that's ok.

Having slept over this issue a couple of nights I think we have these possibilities going forward:

Adding logging capabilities to DoPoliciesAllow through logrus
- + We just solved logging for everyone
- + We are not introducing any BC breaks
- - If we go with a FieldLogger, only logrus can be used
Returning policies in DoPoliciesAllow:
- + It's actually nice to have the matched policies as a return value. Could be useful in a couple of ways
- - We're breaking a part of the API, but it's also not a big break since it's not really part of the public API and more or less considered an internal function.
- - I don't like the implications of iterating twice over these just to get some logging done. The work ratio does not look good to me here.

Adding logging capabilities to DoPoliciesAllow but with a custom interface such as (don't like the naming yet, open for ideas here)

type LadonLogger interface {
  // request = the access request
  // candidates = the set of policies passed to DoPoliciesAllow
  // allowed = the set of policies that allowed / denied the request
  LogAllowed(request Request, candidates, allowed Policies)
  LogDenied(request Request, candidates, denied Policy)
}

we could probably even build a more sophisticated logging chain here, such as Access request X allowed by policy Y and Access request X denied by policy Y which overrides policy Z, and so on.

Seeing what I wrote, I like the third option the most. Opinions?

This was not an assumption but something that I've tested extensively

Ah cool I was referring specifically passing a single item list to the DoPoliciesAllow instead of a full list.

Please do not use that function production.

Ah good point, forgot about that!

Thanks for dedicating some time to this.
I like both 2. and 3. But there's something I don't get:

I don't like the implications of iterating twice over these just to get some logging done.

Why returning the policies would imply iterating twice? Wouldn't it just be an array along the current allowed boolean that would be populated during the main iteration?

(don't like the naming yet, open for ideas here)

Seeing the interface, it does not have to be about logging. Could be like callback, observer, ...

Why returning the policies would imply iterating twice? Wouldn't it just be an array along the current allowed boolean that would be populated during the main iteration?

I understood that one call will be IsAllowed and the second one to DoesPolicyAllow to make this happen. Maybe I misunderstood.

Seeing the interface, it does not have to be about logging. Could be like callback, observer, ...

How about (marking it explicitly as a way to do auditing/controlling/compliance)

type Comptroller interface {
  RegisterDeniedAuthorization(request Request, pool, deciders Policies)
  RegisterGrantedAuthorization(request Request, pool, deciders Policies)
}

I understood that one call will be IsAllowed and the second one to DoesPolicyAllow to make this happen. Maybe I misunderstood.

Oh yes indeed I'm sorry. In my particular case I would probably have skipped the call to IsAllowed() and duplicated its few lines.

How about (marking it explicitly as a way to do auditing/controlling/compliance)

I'm starting to prefer the 3. now :)

Controller is a common term usually referring to executing actions that change state (e.g. MVC).
What about watcher/listener?

type Listener interface {
  OnDeniedAuthorization(request Request, pool, deciders Policies)
  OnGrantedAuthorization(request Request, pool, deciders Policies)
}

type Watcher interface {
  HandleDeniedAuthorization(request Request, pool, deciders Policies)
  HandleGrantedAuthorization(request Request, pool, deciders Policies)
}

My 2 cents, your call anyway :)

Oh yes indeed I'm sorry. In my particular case I would probably have skipped the call to IsAllowed() and duplicated its few lines.

Ah right, in that case you are of course correct!

I'm starting to prefer the 3. now :)

Nice! Me too!

Controller is a common term usually referring

I know it's hard to spot, but it's actually Comptroller! Might be a bit weird though as it's not a general auditor but more in the sense of financial. I think that Listener is maybe too "eventy", but I like Watcher more. Another idea could be AuditLogger or Auditor. Maybe making it explicitly about appending something to an audit log (which is the idea here) as in AuditLogger makes it un-ambiguous and straight forward.

+1 for AuditLogger!

I would be glad to contribute this enhancement. But since I'm not super experienced, it might require some review cycles... Let me know if you prefer to do it or if you're willing to spend some time on guiding me :)

I would be glad to contribute this enhancement. But since I'm not super experienced, it might require some review cycles... Let me know if you prefer to do it or if you're willing to spend some time on guiding me :)

Please do! Making PRs to public libraries is the best way to improve code skills, and I enjoy helping people improving their code skills, especially if it brings libraries forward :)

	// Although the manager is responsible of matching the policies, it might decide to just scan for
	// subjects, it might return all policies, or it might have a different pattern matching than Golang.
	// Thus, we need to make sure that we actually matched the right policies.
	return l.DoPoliciesAllow(r, policies)