Log every authorization decision from the authorizer

Denials were invisible in the audit trail and evaluator explainability
(policy_id, reason) was discarded before reaching logs. Emit a structured
authz decision line on every evaluation in evaluateMultiInTx — allow,
deny, no_match, and assumption errors — using the existing authorizer
logger with opaque IDs only.

Add decision_log.go with DecisionRecord and logDecision. Surface
PolicyID and Reason on EvaluationResult for logging. Audit log
behavior is unchanged (allow-only). Document the convention in
authorization.md.

Signed-off-by: Ludovic Vielle <ludovic@probo.com>
This commit is contained in:
Ludovic Vielle
2026-06-15 16:00:04 +02:00
parent c8de75cc03
commit 71e8d662bc
6 changed files with 388 additions and 1 deletions

View File

@@ -292,6 +292,20 @@ When adding a new entity that needs authorization:
4. **Entity type registry** — register in `pkg/coredata/entity_type_reg.go` and `NewEntityFromID` so the authorizer can construct the entity from its GID
5. **Resolver calls** — add `scope, err := r.authorize(ctx, id, probo.ActionEntityGet)` in GraphQL resolvers and `scope, err := r.Authorize(ctx, id, probo.ActionEntityGet)` in MCP resolvers, then pass `scope` to services
## Decision logging
Every authorization evaluation (allow and deny) emits a structured `authz decision`
log line through the authorizer logger with opaque IDs only:
- `effect``allow`, `deny`, `no_match`, or `error`
- `action`, `principal_id`, `resource_id`
- `policy_id` — statement SID when available
- `reason` — human-readable explanation for operators (never returned to clients)
- `latency` — PDP evaluation duration
Audit log entries remain **allow-only**. Denials are visible in application logs,
not the product audit trail.
## Key patterns
- **Always use `organization_id` condition** — most policies scope access to the principal's organization

View File

@@ -445,6 +445,17 @@ func (a *Authorizer) evaluateMultiInTx(
if assumptionErr != nil && !item.SkipAssumptionCheck {
decisions[i] = assumptionErr
a.logDecision(
ctx,
DecisionRecord{
Effect: effectError,
Action: item.Action,
ResourceID: item.Resource,
Principal: params.Principal,
Reason: assumptionErr.Error(),
},
)
continue
}
@@ -458,7 +469,22 @@ func (a *Authorizer) evaluateMultiInTx(
},
}
if !a.evaluator.Evaluate(req, policies).IsAllowed() {
startedAt := time.Now()
result := a.evaluator.Evaluate(req, policies)
a.logDecision(
ctx,
newDecisionRecord(
result,
params.Principal,
item.Resource,
item.Action,
role,
time.Since(startedAt),
),
)
if !result.IsAllowed() {
decisions[i] = NewInsufficientPermissionsError(params.Principal, item.Resource, item.Action)
}
}

View File

@@ -0,0 +1,163 @@
// Copyright (c) 2026 Probo Inc <hello@probo.com>.
//
// Permission to use, copy, modify, and/or distribute this software for any
// purpose with or without fee is hereby granted, provided that the above
// copyright notice and this permission notice appear in all copies.
//
// THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES WITH
// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
// AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY SPECIAL, DIRECT,
// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE OR
// OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
// PERFORMANCE OF THIS SOFTWARE.
package iam_test
import (
"bytes"
"context"
"strings"
"testing"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"go.gearno.de/kit/log"
"go.gearno.de/kit/pg"
"go.probo.inc/probo/internal/test"
"go.probo.inc/probo/pkg/coredata"
"go.probo.inc/probo/pkg/gid"
"go.probo.inc/probo/pkg/iam"
"go.probo.inc/probo/pkg/iam/policy"
)
func TestAuthorizer_DecisionLogging(t *testing.T) {
t.Parallel()
t.Run("allow writes audit and decision log", func(t *testing.T) {
t.Parallel()
client := test.PGClient(t)
fixture := seedBatchAuthorizeFixture(t, context.Background(), client)
action := newBatchTestAction()
var logOutput bytes.Buffer
authorizer := newTestAuthorizerWithLogger(client, action, nil, &logOutput)
_, err := authorizer.AuthorizeBatch(
context.Background(),
iam.AuthorizeBatchParams{
Principal: fixture.identityID,
Action: action,
Resources: []gid.GID{fixture.frameworkID1},
},
)
require.NoError(t, err)
output := logOutput.String()
assert.Contains(t, output, "authz decision")
assert.Contains(t, output, "allow")
assert.Contains(t, output, action)
assert.Contains(t, output, fixture.identityID.String())
assert.Contains(t, output, fixture.frameworkID1.String())
assert.Contains(t, output, "allow-test-action")
assert.Equal(t, 1, countAuditLogsForAction(t, context.Background(), client, action))
})
t.Run("deny writes decision log without audit row", func(t *testing.T) {
t.Parallel()
client := test.PGClient(t)
fixture := seedBatchAuthorizeFixture(t, context.Background(), client)
action := newBatchTestAction()
var logOutput bytes.Buffer
authorizer := newTestAuthorizerWithLogger(
client,
action,
nil,
&logOutput,
policy.Deny(action).WithSID("deny-test-action"),
)
_, err := authorizer.AuthorizeBatch(
context.Background(),
iam.AuthorizeBatchParams{
Principal: fixture.identityID,
Action: action,
Resources: []gid.GID{fixture.frameworkID1},
},
)
require.Error(t, err)
output := logOutput.String()
assert.Contains(t, output, "authz decision")
assert.Contains(t, output, "deny")
assert.Contains(t, output, "deny-test-action")
assert.Contains(t, output, "explicit deny by statement deny-test-action")
assert.Equal(t, 0, countAuditLogsForAction(t, context.Background(), client, action))
})
t.Run("implicit deny logs no_match without policy id", func(t *testing.T) {
t.Parallel()
client := test.PGClient(t)
fixture := seedBatchAuthorizeFixture(t, context.Background(), client)
action := newBatchTestAction()
var logOutput bytes.Buffer
authorizer := newTestAuthorizerWithLogger(
client,
"core:other:action",
nil,
&logOutput,
)
_, err := authorizer.AuthorizeBatch(
context.Background(),
iam.AuthorizeBatchParams{
Principal: fixture.identityID,
Action: action,
Resources: []gid.GID{fixture.frameworkID1},
},
)
require.Error(t, err)
output := logOutput.String()
assert.Contains(t, output, "authz decision")
assert.Contains(t, output, "no_match")
assert.NotContains(t, output, "policy_id")
assert.True(t, strings.Contains(output, "implicit deny"))
})
}
func newTestAuthorizerWithLogger(
client *pg.Client,
action string,
allowResourceID *gid.GID,
logOutput *bytes.Buffer,
extraStatements ...policy.Statement,
) *iam.Authorizer {
statements := []policy.Statement{
policy.Allow(action).WithSID("allow-test-action"),
}
if allowResourceID != nil {
statements[0] = statements[0].When(policy.Equals("resource.id", allowResourceID.String()))
}
statements = append(statements, extraStatements...)
authorizer := iam.NewAuthorizer(client, log.NewLogger(log.WithOutput(logOutput)))
authorizer.RegisterPolicySet(
iam.NewPolicySet().AddRolePolicy(
string(coredata.MembershipRoleOwner),
policy.NewPolicy("batch-authorize-test", "Batch Authorize Test", statements...),
),
)
return authorizer
}

89
pkg/iam/decision_log.go Normal file
View File

@@ -0,0 +1,89 @@
// Copyright (c) 2026 Probo Inc <hello@probo.com>.
//
// Permission to use, copy, modify, and/or distribute this software for any
// purpose with or without fee is hereby granted, provided that the above
// copyright notice and this permission notice appear in all copies.
//
// THE SOFTWARE IS PROVIDED "AS IS" AND THE AUTHOR DISCLAIMS ALL WARRANTIES WITH
// REGARD TO THIS SOFTWARE INCLUDING ALL IMPLIED WARRANTIES OF MERCHANTABILITY
// AND FITNESS. IN NO EVENT SHALL THE AUTHOR BE LIABLE FOR ANY SPECIAL, DIRECT,
// INDIRECT, OR CONSEQUENTIAL DAMAGES OR ANY DAMAGES WHATSOEVER RESULTING FROM
// LOSS OF USE, DATA OR PROFITS, WHETHER IN AN ACTION OF CONTRACT, NEGLIGENCE OR
// OTHER TORTIOUS ACTION, ARISING OUT OF OR IN CONNECTION WITH THE USE OR
// PERFORMANCE OF THIS SOFTWARE.
package iam
import (
"context"
"time"
"go.gearno.de/kit/log"
"go.probo.inc/probo/pkg/gid"
"go.probo.inc/probo/pkg/iam/policy"
)
const effectError = "error"
// DecisionRecord is a structured authorization decision for logging.
type DecisionRecord struct {
Effect string
Action string
ResourceID gid.GID
Principal gid.GID
PolicyID string
Reason string
Latency time.Duration
}
func newDecisionRecord(
result policy.EvaluationResult,
principal gid.GID,
resourceID gid.GID,
action string,
role string,
latency time.Duration,
) DecisionRecord {
return DecisionRecord{
Effect: string(result.Decision),
Action: action,
ResourceID: resourceID,
Principal: principal,
PolicyID: result.PolicyID(),
Reason: result.Reason(role),
Latency: latency,
}
}
func (a *Authorizer) logDecision(ctx context.Context, rec DecisionRecord) {
if a.logger == nil {
return
}
if rec.PolicyID != "" {
a.logger.InfoCtx(
ctx,
"authz decision",
log.String("effect", rec.Effect),
log.String("action", rec.Action),
log.String("principal_id", rec.Principal.String()),
log.String("resource_id", rec.ResourceID.String()),
log.String("policy_id", rec.PolicyID),
log.String("reason", rec.Reason),
log.Duration("latency", rec.Latency),
)
return
}
a.logger.InfoCtx(
ctx,
"authz decision",
log.String("effect", rec.Effect),
log.String("action", rec.Action),
log.String("principal_id", rec.Principal.String()),
log.String("resource_id", rec.ResourceID.String()),
log.String("reason", rec.Reason),
log.Duration("latency", rec.Latency),
)
}

View File

@@ -47,6 +47,52 @@ func (r EvaluationResult) IsAllowed() bool {
return r.Decision == DecisionAllow
}
func (r EvaluationResult) statementSID() string {
if r.MatchedStatement != nil {
return r.MatchedStatement.SID
}
return ""
}
// PolicyID returns the statement SID or matched policy ID for logging.
func (r EvaluationResult) PolicyID() string {
if sid := r.statementSID(); sid != "" {
return sid
}
if r.MatchedPolicy != nil {
return r.MatchedPolicy.ID
}
return ""
}
// Reason returns a human-readable explanation for logging.
func (r EvaluationResult) Reason(role string) string {
if sid := r.statementSID(); sid != "" {
switch r.Decision {
case DecisionAllow:
return "allowed by statement " + sid
case DecisionDeny:
return "explicit deny by statement " + sid
}
}
switch r.Decision {
case DecisionAllow:
return "allowed"
case DecisionDeny:
return "explicit deny"
default:
if role != "" {
return "implicit deny: no matching allow for role " + role
}
return "implicit deny: no matching allow"
}
}
// AuthorizationRequest contains all information needed to evaluate access.
type AuthorizationRequest struct {
// Principal is the actor requesting access.

View File

@@ -462,3 +462,52 @@ func TestEvaluationResult_IsAllowed(t *testing.T) {
})
}
}
func TestEvaluationResult_PolicyID(t *testing.T) {
t.Parallel()
result := EvaluationResult{
Decision: DecisionAllow,
MatchedStatement: &Statement{
SID: "read-thirdParties",
},
MatchedPolicy: &Policy{
ID: "probo:viewer",
},
}
if got := result.PolicyID(); got != "read-thirdParties" {
t.Errorf("PolicyID() = %q, want read-thirdParties", got)
}
}
func TestEvaluationResult_Reason(t *testing.T) {
t.Parallel()
t.Run("implicit deny includes role", func(t *testing.T) {
t.Parallel()
result := EvaluationResult{Decision: DecisionNoMatch}
want := "implicit deny: no matching allow for role VIEWER"
if got := result.Reason("VIEWER"); got != want {
t.Errorf("Reason() = %q, want %q", got, want)
}
})
t.Run("explicit deny uses statement sid", func(t *testing.T) {
t.Parallel()
result := EvaluationResult{
Decision: DecisionDeny,
MatchedStatement: &Statement{
SID: "deny-delete",
},
}
want := "explicit deny by statement deny-delete"
if got := result.Reason("ADMIN"); got != want {
t.Errorf("Reason() = %q, want %q", got, want)
}
})
}