policy: implement policy logging via progress printer

Signed-off-by: Tonis Tiigi <tonistiigi@gmail.com>

build/build.go

@@ -132,7 +132,7 @@ type policyOpt struct {
 	Files    []policy.File
 	FS       func() (fs.StatFS, func() error, error)
 	Strict   bool
-	LogLevel logrus.Level
+	LogLevel *logrus.Level
 }
 
 func withPolicyConfig(defaultPolicy policyOpt, configs []PolicyConfig) ([]policyOpt, error) {
@@ -177,7 +177,7 @@ func withPolicyConfig(defaultPolicy policyOpt, configs []PolicyConfig) ([]policy
 					last.Strict = *cfg.Strict
 				}
 				if cfg.LogLevel != nil {
-					last.LogLevel = *cfg.LogLevel
+					last.LogLevel = cfg.LogLevel
 				}
 			}
 			continue
@@ -190,13 +190,13 @@ func withPolicyConfig(defaultPolicy policyOpt, configs []PolicyConfig) ([]policy
 			opt.Strict = *last.Strict
 		}
 		if last.LogLevel != nil {
-			opt.LogLevel = *last.LogLevel
+			opt.LogLevel = last.LogLevel
 		}
 		if cfg.Strict != nil {
 			opt.Strict = *cfg.Strict
 		}
 		if cfg.LogLevel != nil {
-			opt.LogLevel = *cfg.LogLevel
+			opt.LogLevel = cfg.LogLevel
 		}
 		opt.FS = defaultPolicy.FS
 		out = append(out, opt)

build/opt.go

@@ -3,9 +3,9 @@ package build
 import (
 	"bytes"
 	"context"
+	"fmt"
 	"io"
 	"io/fs"
-	"log"
 	"maps"
 	"os"
 	"path"
@@ -15,6 +15,7 @@ import (
 	"strings"
 	"sync"
 	"syscall"
+	"time"
 
 	awsconfig "github.com/aws/aws-sdk-go-v2/config"
 	"github.com/containerd/console"
@@ -48,6 +49,7 @@ import (
 	"github.com/moby/buildkit/util/gitutil"
 	"github.com/opencontainers/go-digest"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 	"github.com/tonistiigi/fsutil"
 )
 
@@ -60,6 +62,79 @@ var sendGitQueryAsInput = sync.OnceValue(func() bool {
 	return false
 })
 
+type policyProgressLogger struct {
+	ch      chan *client.SolveStatus
+	done    chan struct{}
+	dgst    digest.Digest
+	started time.Time
+	name    string
+}
+
+func newPolicyProgressLogger(pw progress.Writer, name string) *policyProgressLogger {
+	if pw == nil {
+		return nil
+	}
+	ch, done := progress.NewChannel(pw)
+	dgst := digest.FromBytes([]byte(identity.NewID()))
+	tm := time.Now()
+	vtx := client.Vertex{
+		Digest:  dgst,
+		Name:    name,
+		Started: &tm,
+	}
+	ch <- &client.SolveStatus{Vertexes: []*client.Vertex{&vtx}}
+	return &policyProgressLogger{
+		ch:      ch,
+		done:    done,
+		dgst:    dgst,
+		started: tm,
+		name:    name,
+	}
+}
+
+func (l *policyProgressLogger) Log(msg string) {
+	if l == nil || msg == "" {
+		return
+	}
+	if !strings.HasSuffix(msg, "\n") {
+		msg += "\n"
+	}
+	l.ch <- &client.SolveStatus{
+		Logs: []*client.VertexLog{{
+			Vertex:    l.dgst,
+			Stream:    1,
+			Data:      []byte(msg),
+			Timestamp: time.Now(),
+		}},
+	}
+}
+
+func (l *policyProgressLogger) Write(p []byte) (int, error) {
+	if len(p) > 0 {
+		l.Log(string(p))
+	}
+	return len(p), nil
+}
+
+func (l *policyProgressLogger) Close(err error) {
+	if l == nil {
+		return
+	}
+	tm := time.Now()
+	vtx := client.Vertex{
+		Digest:    l.dgst,
+		Name:      l.name,
+		Started:   &l.started,
+		Completed: &tm,
+	}
+	if err != nil {
+		vtx.Error = err.Error()
+	}
+	l.ch <- &client.SolveStatus{Vertexes: []*client.Vertex{&vtx}}
+	close(l.ch)
+	<-l.done
+}
+
 func toSolveOpt(ctx context.Context, node builder.Node, multiDriver bool, opt *Options, bopts gateway.BuildOpts, cfg *confutil.Config, pw progress.Writer, docker *dockerutil.Client) (_ *client.SolveOpt, release func(), err error) {
 	nodeDriver := node.Driver
 	defers := make([]func(), 0, 2)
@@ -347,14 +422,39 @@ func toSolveOpt(ctx context.Context, node builder.Node, multiDriver bool, opt *O
 		if err != nil {
 			return nil, nil, err
 		}
+		var policyFiles []string
+		for _, popt := range popts {
+			for _, f := range popt.Files {
+				if f.Filename != "" {
+					policyFiles = append(policyFiles, f.Filename)
+				}
+			}
+		}
+		var policyLogger *policyProgressLogger
+		if len(policyFiles) > 0 {
+			policyLogger = newPolicyProgressLogger(pw, fmt.Sprintf("loading policies %s", strings.Join(policyFiles, ", ")))
+		}
+		if policyLogger != nil {
+			defers = append(defers, func() {
+				policyLogger.Close(nil)
+			})
+		}
 		var cbs []policysession.PolicyCallback
 		for _, popt := range popts {
+			policyLevel := logrus.GetLevel()
+			if popt.LogLevel != nil {
+				policyLevel = *popt.LogLevel
+			}
+			logf := func(level logrus.Level, msg string) {
+				if policyLogger == nil || level > policyLevel {
+					return
+				}
+				policyLogger.Log(msg)
+			}
 			p := policy.NewPolicy(policy.Opt{
-				Files: popt.Files,
+				Files:            popt.Files,
-				Env:   env,
+				Env:              env,
-				Log: func(msg string) {
+				Log:              logf,
-					log.Printf("[policy] %s", msg)
-				},
 				FS:               opt.Inputs.policy.FS,
 				VerifierProvider: policy.SignatureVerifier(cfg),
 			})

build/policy_test.go

@@ -33,7 +33,7 @@ func TestWithPolicyConfigDefaults(t *testing.T) {
 	require.Len(t, out, 1)
 	require.Equal(t, defaultPolicy.Files, out[0].Files)
 	require.False(t, out[0].Strict)
-	require.Equal(t, logrus.Level(0), out[0].LogLevel)
+	require.Nil(t, out[0].LogLevel)
 	require.NotNil(t, out[0].FS)
 }
 
@@ -54,11 +54,10 @@ func TestWithPolicyConfigDisabled(t *testing.T) {
 	})
 	require.Error(t, err)
 
-	out, err := withPolicyConfig(policyOpt{}, []PolicyConfig{
+	_, err = withPolicyConfig(policyOpt{}, []PolicyConfig{
 		{Disabled: true, LogLevel: levelPtr(logrus.WarnLevel)},
 	})
-	require.NoError(t, err)
+	require.Error(t, err)
-	require.Nil(t, out)
 
 	_, err = withPolicyConfig(policyOpt{}, []PolicyConfig{
 		{Disabled: true},
@@ -66,7 +65,7 @@ func TestWithPolicyConfigDisabled(t *testing.T) {
 	})
 	require.Error(t, err)
 
-	out, err = withPolicyConfig(policyOpt{}, []PolicyConfig{
+	out, err := withPolicyConfig(policyOpt{}, []PolicyConfig{
 		{Disabled: true},
 	})
 	require.NoError(t, err)
@@ -104,7 +103,8 @@ func TestWithPolicyConfigStrictAndLogLevel(t *testing.T) {
 	require.NoError(t, err)
 	require.Len(t, out, 1)
 	require.True(t, out[0].Strict)
-	require.Equal(t, logrus.WarnLevel, out[0].LogLevel)
+	require.NotNil(t, out[0].LogLevel)
+	require.Equal(t, logrus.WarnLevel, *out[0].LogLevel)
 }
 
 // TestWithPolicyConfigStrictIgnoredWithoutPolicy ensures strict without any policy produces no entries.
@@ -135,7 +135,8 @@ func TestWithPolicyConfigMultipleFilesAndOverrides(t *testing.T) {
 	require.Equal(t, "default.rego", out[0].Files[0].Filename)
 	require.Equal(t, "a.rego", out[1].Files[0].Filename)
 	require.True(t, out[1].Strict)
-	require.Equal(t, logrus.WarnLevel, out[1].LogLevel)
+	require.NotNil(t, out[1].LogLevel)
+	require.Equal(t, logrus.WarnLevel, *out[1].LogLevel)
 	require.Equal(t, "b.rego", out[2].Files[0].Filename)
 	require.True(t, out[2].Strict)
 	require.NotNil(t, out[1].FS)

commands/policy/eval.go

@@ -39,9 +39,10 @@ func evalCmd(dockerCli command.Cli, rootOpts RootOptions) *cobra.Command {
 	var opts evalOpts
 
 	cmd := &cobra.Command{
-		Use:   "eval source",
+		Use:                   "eval [OPTIONS] source",
-		Short: "Evaluate policy for a source",
+		Short:                 "Evaluate policy for a source",
-		Args:  cobra.ExactArgs(1),
+		Args:                  cobra.ExactArgs(1),
+		DisableFlagsInUseLine: true,
 		RunE: func(cmd *cobra.Command, args []string) error {
 			opts.builder = rootOpts.Builder
 			return runEval(cmd.Context(), dockerCli, args[0], opts)
@@ -380,8 +381,7 @@ func evalDecisionError(decision *policysession.DecisionResponse) error {
 }
 
 func parseSource(input string) (*pb.SourceOp, error) {
-	if strings.HasPrefix(input, "docker-image://") {
+	if refstr, ok := strings.CutPrefix(input, "docker-image://"); ok {
-		refstr := strings.TrimPrefix(input, "docker-image://")
 		ref, err := reference.ParseNormalizedNamed(refstr)
 		if err != nil {
 			return nil, errors.Wrapf(err, "failed to parse image source reference")

commands/policy/json_schema.go

@@ -7,9 +7,10 @@ import (
 
 func jsonSchemaCmd() *cobra.Command {
 	cmd := &cobra.Command{
-		Use:   "json-schema",
+		Use:                   "json-schema",
-		Short: "Print policy JSON schema",
+		Short:                 "Print policy JSON schema",
-		Args:  cobra.NoArgs,
+		Args:                  cobra.NoArgs,
+		DisableFlagsInUseLine: true,
 		RunE: func(cmd *cobra.Command, args []string) error {
 			return runJSONSchema()
 		},

commands/policy/root.go

@@ -12,8 +12,9 @@ type RootOptions struct {
 // RootCmd creates the policy command tree.
 func RootCmd(rootcmd *cobra.Command, dockerCli command.Cli, rootOpts RootOptions) *cobra.Command {
 	cmd := &cobra.Command{
-		Use:   "policy",
+		Use:                   "policy",
-		Short: "Commands for working with build policies",
+		Short:                 "Commands for working with build policies",
+		DisableFlagsInUseLine: true,
 	}
 
 	cmd.AddCommand(

commands/policy/test.go

@@ -7,9 +7,10 @@ import (
 
 func testCmd() *cobra.Command {
 	cmd := &cobra.Command{
-		Use:   "test <path>",
+		Use:                   "test <path>",
-		Short: "Run policy tests",
+		Short:                 "Run policy tests",
-		Args:  cobra.ExactArgs(1),
+		Args:                  cobra.ExactArgs(1),
+		DisableFlagsInUseLine: true,
 		RunE: func(cmd *cobra.Command, args []string) error {
 			return runTest(args[0])
 		},

policy/validate.go

@@ -3,16 +3,13 @@ package policy
 import (
 	"context"
 	"encoding/json"
+	"fmt"
 	"io/fs"
-	"log"
 	"maps"
 	"net/url"
-	"os"
 	"path"
 	"slices"
-	"strconv"
 	"strings"
-	"sync"
 	"time"
 
 	"github.com/containerd/platforms"
@@ -29,23 +26,9 @@ import (
 	"github.com/opencontainers/go-digest"
 	ocispecs "github.com/opencontainers/image-spec/specs-go/v1"
 	"github.com/pkg/errors"
+	"github.com/sirupsen/logrus"
 )
 
-// this is tempory debug, to be replaced with progressbar logging later
-var isDebug = sync.OnceValue(func() bool {
-	if v, ok := os.LookupEnv("BUILDX_POLICY_DEBUG"); ok {
-		b, _ := strconv.ParseBool(v)
-		return b
-	}
-	return false
-})
-
-func debugf(format string, v ...any) {
-	if isDebug() {
-		log.Printf(format, v...)
-	}
-}
-
 type Policy struct {
 	opt   Opt
 	funcs []fun
@@ -73,7 +56,7 @@ type fun struct {
 type Opt struct {
 	Files            []File
 	Env              Env
-	Log              func(string)
+	Log              func(logrus.Level, string)
 	FS               func() (fs.StatFS, func() error, error)
 	VerifierProvider PolicyVerifierProvider
 }
@@ -93,6 +76,13 @@ func NewPolicy(opt Opt) *Policy {
 	return p
 }
 
+func (p *Policy) log(level logrus.Level, format string, v ...any) {
+	if p == nil || p.opt.Log == nil {
+		return
+	}
+	p.opt.Log(level, fmt.Sprintf(format, v...))
+}
+
 func (p *Policy) CheckPolicy(ctx context.Context, req *policysession.CheckPolicyRequest) (*policysession.DecisionResponse, *gwpb.ResolveSourceMetaRequest, error) {
 	if req.Source == nil || req.Source.Source == nil {
 		return nil, nil, errors.Errorf("no source info in request")
@@ -112,7 +102,7 @@ func (p *Policy) CheckPolicy(ctx context.Context, req *policysession.CheckPolicy
 		platform = &pl
 	}
 
-	inp, unknowns, err := SourceToInput(ctx, p.opt.VerifierProvider, src, platform)
+	inp, unknowns, err := SourceToInputWithLogger(ctx, p.opt.VerifierProvider, src, platform, p.opt.Log)
 	if err != nil {
 		return nil, nil, errors.Wrapf(err, "failed to convert source to policy input")
 	}
@@ -220,10 +210,11 @@ func (p *Policy) CheckPolicy(ctx context.Context, req *policysession.CheckPolicy
 	if err != nil {
 		return nil, nil, errors.Wrapf(err, "failed to marshal policy input")
 	}
-	debugf("policy input: %s", dt)
+	p.log(logrus.InfoLevel, "checking policy for source %s", src.Source.Identifier)
+	p.log(logrus.DebugLevel, "policy input: %s", dt)
 
 	if len(unknowns) > 0 {
-		debugf("unknowns for policy evaluation: %+v", unknowns)
+		p.log(logrus.DebugLevel, "unknowns for policy evaluation: %+v", unknowns)
 		opts = append(opts, rego.Unknowns(unknowns))
 	}
 	r := rego.New(opts...)
@@ -242,11 +233,11 @@ func (p *Policy) CheckPolicy(ctx context.Context, req *policysession.CheckPolicy
 				Source:   req.Source.Source,
 				Platform: req.Platform,
 			}
-			if err := AddUnknowns(next, unk); err != nil {
+			if err := AddUnknownsWithLogger(p.opt.Log, next, unk); err != nil {
 				return nil, nil, err
 			}
 			if next.Image != nil || next.Git != nil {
-				debugf("next resolve meta request: %+v", next)
+				p.log(logrus.InfoLevel, "policy decision for source %s: resolve missing fields %+v", src.Source.Identifier, summarizeUnknownsForLog(unk))
 				return nil, next, nil
 			}
 		}
@@ -274,7 +265,7 @@ func (p *Policy) CheckPolicy(ctx context.Context, req *policysession.CheckPolicy
 	resp := &policysession.DecisionResponse{
 		Action: moby_buildkit_v1_sourcepolicy.PolicyAction_DENY,
 	}
-	debugf("policy response: %+v", vt)
+	p.log(logrus.DebugLevel, "policy response: %+v", vt)
 
 	if v, ok := vt["allow"]; ok {
 		if vv, ok := v.(bool); !ok {
@@ -305,6 +296,8 @@ func (p *Policy) CheckPolicy(ctx context.Context, req *policysession.CheckPolicy
 			if err != nil {
 				return nil, nil, errors.Wrapf(err, "failed to add image pin to source")
 			}
+			p.log(logrus.InfoLevel, "policy decision for source %s: convert to %s", src.Source.Identifier, newSrc.Identifier)
+
 			return &policysession.DecisionResponse{
 				Action: moby_buildkit_v1_sourcepolicy.PolicyAction_CONVERT,
 				Update: newSrc,
@@ -312,19 +305,23 @@ func (p *Policy) CheckPolicy(ctx context.Context, req *policysession.CheckPolicy
 		}
 	}
 
-	debugf("policy decision: %s %v", resp.Action, resp.DenyMessages)
+	p.log(logrus.InfoLevel, "policy decision for source %s: %s %v", src.Source.Identifier, resp.Action, resp.DenyMessages)
 
 	return resp, nil, nil
 }
 
 func (p *Policy) Print(ctx print.Context, msg string) error {
 	if p.opt.Log != nil {
-		p.opt.Log(ctx.Location.Format("%s", msg))
+		p.opt.Log(logrus.InfoLevel, ctx.Location.Format("%s", msg))
 	}
 	return nil
 }
 
 func SourceToInput(ctx context.Context, getVerifier PolicyVerifierProvider, src *gwpb.ResolveSourceMetaResponse, platform *ocispecs.Platform) (Input, []string, error) {
+	return SourceToInputWithLogger(ctx, getVerifier, src, platform, nil)
+}
+
+func SourceToInputWithLogger(ctx context.Context, getVerifier PolicyVerifierProvider, src *gwpb.ResolveSourceMetaResponse, platform *ocispecs.Platform, logf func(logrus.Level, string)) (Input, []string, error) {
 	var inp Input
 	var unknowns []string
 
@@ -558,7 +555,9 @@ func SourceToInput(ctx context.Context, getVerifier PolicyVerifierProvider, src
 				if getVerifier != nil {
 					signatures, err := parseSignatures(ctx, getVerifier, ac, platform)
 					if err != nil {
-						debugf("failed to parse image signatures: %v", err)
+						if logf != nil {
+							logf(logrus.DebugLevel, fmt.Sprintf("failed to parse image signatures: %v", err))
+						}
 					} else {
 						inp.Image.Signatures = signatures
 					}
@@ -588,6 +587,10 @@ func withPrefix(arr []string, prefix string) []string {
 }
 
 func AddUnknowns(req *gwpb.ResolveSourceMetaRequest, unk []string) error {
+	return AddUnknownsWithLogger(nil, req, unk)
+}
+
+func AddUnknownsWithLogger(logf func(logrus.Level, string), req *gwpb.ResolveSourceMetaRequest, unk []string) error {
 	unk2 := make([]string, 0, len(unk))
 	for _, u := range unk {
 		k := strings.TrimPrefix(u, "input.")
@@ -604,7 +607,9 @@ func AddUnknowns(req *gwpb.ResolveSourceMetaRequest, unk []string) error {
 		return nil
 	}
 
-	debugf("collected unknowns: %+v", unk2)
+	if logf != nil {
+		logf(logrus.DebugLevel, fmt.Sprintf("collected unknowns: %+v", unk2))
+	}
 	for _, u := range unk2 {
 		switch u {
 		case "image.checksum", "image.labels", "image.user", "image.volumes", "image.workingDir", "image.env":
@@ -654,6 +659,25 @@ func collectUnknowns(mods []*ast.Module) []string {
 	return out
 }
 
+func summarizeUnknownsForLog(unk []string) []string {
+	out := make([]string, 0, len(unk))
+	seen := map[string]struct{}{}
+	for _, u := range unk {
+		if strings.HasPrefix(u, "input.image.signatures") {
+			u = "input.image.signatures"
+		}
+		if u == "input.image" {
+			continue
+		}
+		if _, ok := seen[u]; ok {
+			continue
+		}
+		seen[u] = struct{}{}
+		out = append(out, u)
+	}
+	return out
+}
+
 func trimKey(s string) string {
 	const (
 		dot = '.'