diff --git a/build/build.go b/build/build.go index 09638f4c5..5211be5b8 100644 --- a/build/build.go +++ b/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) diff --git a/build/opt.go b/build/opt.go index ddf9d2911..a1c48a837 100644 --- a/build/opt.go +++ b/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, - Env: env, - Log: func(msg string) { - log.Printf("[policy] %s", msg) - }, + Files: popt.Files, + Env: env, + Log: logf, FS: opt.Inputs.policy.FS, VerifierProvider: policy.SignatureVerifier(cfg), }) diff --git a/build/policy_test.go b/build/policy_test.go index 66fdd39e3..9a6cd0103 100644 --- a/build/policy_test.go +++ b/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.Nil(t, out) + require.Error(t, err) _, 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) diff --git a/commands/policy/eval.go b/commands/policy/eval.go index f56e8938c..201fefc54 100644 --- a/commands/policy/eval.go +++ b/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", - Short: "Evaluate policy for a source", - Args: cobra.ExactArgs(1), + Use: "eval [OPTIONS] source", + Short: "Evaluate policy for a source", + 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://") { - refstr := strings.TrimPrefix(input, "docker-image://") + if refstr, ok := strings.CutPrefix(input, "docker-image://"); ok { ref, err := reference.ParseNormalizedNamed(refstr) if err != nil { return nil, errors.Wrapf(err, "failed to parse image source reference") diff --git a/commands/policy/json_schema.go b/commands/policy/json_schema.go index ebfac1e17..8292f9e62 100644 --- a/commands/policy/json_schema.go +++ b/commands/policy/json_schema.go @@ -7,9 +7,10 @@ import ( func jsonSchemaCmd() *cobra.Command { cmd := &cobra.Command{ - Use: "json-schema", - Short: "Print policy JSON schema", - Args: cobra.NoArgs, + Use: "json-schema", + Short: "Print policy JSON schema", + Args: cobra.NoArgs, + DisableFlagsInUseLine: true, RunE: func(cmd *cobra.Command, args []string) error { return runJSONSchema() }, diff --git a/commands/policy/root.go b/commands/policy/root.go index e88eae4f1..d29529040 100644 --- a/commands/policy/root.go +++ b/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", - Short: "Commands for working with build policies", + Use: "policy", + Short: "Commands for working with build policies", + DisableFlagsInUseLine: true, } cmd.AddCommand( diff --git a/commands/policy/test.go b/commands/policy/test.go index b099a5a41..c9598d739 100644 --- a/commands/policy/test.go +++ b/commands/policy/test.go @@ -7,9 +7,10 @@ import ( func testCmd() *cobra.Command { cmd := &cobra.Command{ - Use: "test ", - Short: "Run policy tests", - Args: cobra.ExactArgs(1), + Use: "test ", + Short: "Run policy tests", + Args: cobra.ExactArgs(1), + DisableFlagsInUseLine: true, RunE: func(cmd *cobra.Command, args []string) error { return runTest(args[0]) }, diff --git a/policy/validate.go b/policy/validate.go index 3a7f56f60..48b2519b9 100644 --- a/policy/validate.go +++ b/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 = '.'