diff --git a/cli/app.go b/cli/app.go index 11f0c08..4dd9658 100644 --- a/cli/app.go +++ b/cli/app.go @@ -9,6 +9,7 @@ import ( "os" "reflect" "strings" + "time" "github.com/aws/aws-sdk-go-v2/aws/external" "github.com/func/func/cloudformation" @@ -20,22 +21,38 @@ import ( "golang.org/x/sync/errgroup" ) +// A Logger is used for logging activity to the user. +type Logger interface { + Errorf(format string, args ...interface{}) + Warningf(format string, args ...interface{}) + Infof(format string, args ...interface{}) + Debugf(format string, args ...interface{}) + Tracef(format string, args ...interface{}) + + Writer(level LogLevel) io.Writer +} + +// PrefixLogger allows creating sub loggers with a prefix. +type PrefixLogger interface { + Logger + WithPrefix(name string) PrefixLogger +} + // App encapsulates all cli business logic. type App struct { - *logger + Log Logger Stdout io.Writer - Stderr io.Writer } // NewApp creates a new App with the given log level. -func NewApp(logLevel LogLevel) *App { +func NewApp(verbosity int) *App { + logger := &StdLogger{ + Output: os.Stderr, + Level: LogLevel(verbosity), + } return &App{ - logger: &logger{ - Level: logLevel, - Output: os.Stderr, - }, + Log: logger, Stdout: os.Stdout, - Stderr: os.Stderr, } } @@ -50,13 +67,14 @@ func (a *App) loadResources(dir string) (resource.List, diagPrinter, hcl.Diagnos Registry: reg, } - a.Verbosef("Loading config from %s\n", dir) + a.Log.Debugf("Loading config from %s", dir) list, diags := loader.LoadDir(dir) printer := func(diags hcl.Diagnostics) { - loader.PrintDiagnostics(a.Stderr, diags) + out := a.Log.Writer(allLevels) + loader.PrintDiagnostics(out, diags) } - a.Tracef("Loaded %d resources\n", len(list)) + a.Log.Tracef("Loaded %d resources", len(list)) return list, printer, diags } @@ -73,12 +91,16 @@ func (a *App) sources(resources resource.List) ([]sourcecode, error) { for i, res := range sources { i, res := i, res g.Go(func() error { - a.Verbosef(" %s: Computing source checksum\n", res.Name) + log := a.Log + if pfx, ok := log.(PrefixLogger); ok { + log = pfx.WithPrefix(fmt.Sprintf(" [%s] ", res.Name)) + } + log.Tracef("Computing source checksum") sum, err := res.SourceCode.Checksum() if err != nil { - return fmt.Errorf(" %s: compute source checksum: %v", res.Name, err) + return fmt.Errorf("%s: compute source checksum: %v", res.Name, err) } - a.Tracef(" %s: Source checksum = %s\n", res.Name, sum) + log.Tracef("Source checksum = %s", sum) out[i] = sourcecode{ Resource: res.Name, Source: res.SourceCode, @@ -94,60 +116,86 @@ func (a *App) sources(resources resource.List) ([]sourcecode, error) { } func (a *App) ensureSource(ctx context.Context, src sourcecode, s3 *source.S3) error { - name := src.Resource - a.Verbosef(" %s: Checking if source exists\n", name) + log := a.Log + if pfx, ok := log.(PrefixLogger); ok { + log = pfx.WithPrefix(fmt.Sprintf(" %s ", src.Resource)) + } + log.Tracef("Checking if source exists") exists, err := s3.Has(ctx, src.Key) if err != nil { - return fmt.Errorf("%s: check existing source: %w", name, err) + return fmt.Errorf("check existing source: %w", err) } if exists { - a.Verbosef(" %s: Source ok\n", name) + log.Tracef("Source ok") return nil } files := src.Source.Files if len(src.Source.Build) > 0 { - tmp, err := ioutil.TempDir("", "func-build") + log.Infof("Building") + buildDir, err := ioutil.TempDir("", "func-build") if err != nil { return err } + log.Tracef("Build dir: %s", buildDir) defer func() { - _ = os.RemoveAll(tmp) + log.Tracef("Removing temporary build dir %s", buildDir) + _ = os.RemoveAll(buildDir) }() - - if err := files.Copy(tmp); err != nil { + log.Tracef("Copying source %d files to build dir", len(files.Files)) + if err := files.Copy(buildDir); err != nil { return err } - buildContext := &source.BuildContext{ - Dir: tmp, - Stdout: os.Stdout, - Stderr: os.Stderr, - } - if err := src.Source.Build.Exec(ctx, buildContext); err != nil { - return err + log.Tracef("Executing build") + + buildTime := time.Now() + n := len(src.Source.Build) + for i, s := range src.Source.Build { + line, stdout, stderr := log, log, log + if pfx, ok := line.(PrefixLogger); ok { + indexPrefix := pfx.WithPrefix(fmt.Sprintf(" %d/%d ", i+1, n)) + line = indexPrefix + stdout = indexPrefix.WithPrefix("| ") + stderr = indexPrefix.WithPrefix("| ") + } + buildContext := &source.BuildContext{ + Dir: buildDir, + Stdout: stdout.Writer(Info), + Stderr: stderr.Writer(allLevels), + } + line.Debugf("$ %s", s) + stepTime := time.Now() + if err := s.Exec(ctx, buildContext); err != nil { + return fmt.Errorf("exec step %d: %s: %w", i, s, err) + } + line.Tracef("Done in %s", time.Since(stepTime).Round(time.Millisecond)) } + log.Debugf("Build completed in %s", time.Since(buildTime).Round(time.Millisecond)) - output, err := source.Collect(tmp) + log.Tracef("Collecting build artifacts") + output, err := source.Collect(buildDir) if err != nil { return err } + log.Tracef("Got %d build artifacts", len(output.Files)) files = output } - a.Verbosef(" %s: Creating source zip\n", name) - f, err := ioutil.TempFile("", src.Key) + log.Debugf("Creating source zip") + zipfile := strings.Replace(src.Key, ".", "-*.", 1) + f, err := ioutil.TempFile("", zipfile) if err != nil { - return fmt.Errorf("%s: create source file: %w", name, err) + return fmt.Errorf("create source file: %w", err) } defer func() { _ = os.Remove(f.Name()) }() if err := files.Zip(f); err != nil { - return fmt.Errorf("%s: zip: %w", name, err) + return fmt.Errorf("zip: %w", err) } if err := f.Sync(); err != nil { return err @@ -156,14 +204,12 @@ func (a *App) ensureSource(ctx context.Context, src sourcecode, s3 *source.S3) e return err } - a.Infof(" %s: Uploading\n", name) - + log.Infof("Uploading") err = s3.Upload(ctx, src.Key, f) if err != nil { - return fmt.Errorf("%s: upload: %w", name, err) + return fmt.Errorf("upload: %w", err) } - - a.Verbosef(" %s: Upload complete\n", name) + log.Debugf("Upload complete") return nil } @@ -197,18 +243,18 @@ func (a *App) GenerateCloudFormation(ctx context.Context, dir string, opts Gener srcs, err := a.sources(resources) if err != nil { - a.Errorf("Could not collect source files: %v\n", err) + a.Log.Errorf("Could not collect source files: %v", err) return 1 } if len(srcs) > 0 && opts.SourceBucket == "" { - a.Errorln("Source bucket not set") + a.Log.Errorf("Source bucket not set") return 2 } if opts.ProcessSource { cfg, err := external.LoadDefaultAWSConfig() if err != nil { - a.Errorf("Could not load aws config: %v\n", err) + a.Log.Errorf("Could not load aws config: %v", err) } s3 := source.NewS3(cfg, opts.SourceBucket) @@ -216,12 +262,15 @@ func (a *App) GenerateCloudFormation(ctx context.Context, dir string, opts Gener for _, src := range srcs { src := src g.Go(func() error { - return a.ensureSource(gctx, src, s3) + if err := a.ensureSource(gctx, src, s3); err != nil { + return fmt.Errorf("%s: %w", src.Resource, err) + } + return nil }) } if err := g.Wait(); err != nil { - a.Errorf("Could not process source: %v", err) + a.Log.Errorf("Could not process source: %v", err) return 1 } } @@ -233,37 +282,30 @@ func (a *App) GenerateCloudFormation(ctx context.Context, dir string, opts Gener os.Exit(1) } + var out []byte switch strings.ToLower(opts.Format) { case "json": - out, err := json.MarshalIndent(tmpl, "", " ") - if err != nil { - a.Errorln(err) - return 1 - } - fmt.Fprintln(a.Stdout, string(out)) + out, err = json.MarshalIndent(tmpl, "", " ") case "json-compact": - out, err := json.Marshal(tmpl) - if err != nil { - a.Errorln(err) - return 1 - } - fmt.Fprintln(a.Stdout, string(out)) + out, err = json.Marshal(tmpl) case "yaml", "yml": - j, err := json.Marshal(tmpl) - if err != nil { - a.Errorln(err) - return 1 - } - y, err := yaml.JSONToYAML(j) - if err != nil { - a.Errorln(err) - return 1 + out, err = json.Marshal(tmpl) + if err == nil { + out, err = yaml.JSONToYAML(out) } - fmt.Fprint(a.Stdout, string(y)) // Output already has trailing newline default: - a.Errorf("Unsupported output format %q. Supported: [json, json-compact, yaml, yml]", opts.Format) + a.Log.Errorf("Unsupported output format %q. Supported: [json, json-compact, yaml, yml]", opts.Format) return 2 } + if err != nil { + a.Log.Errorf(err.Error()) + return 1 + } + outstr := string(out) + if !strings.HasSuffix(outstr, "\n") { + outstr += "\n" + } + fmt.Fprint(a.Stdout, outstr) return 0 } @@ -275,9 +317,9 @@ type DeploymentOpts struct { } // DeployCloudFormation deploys the project using CloudFormation. -func (a *App) DeployCloudFormation(ctx context.Context, dir string, opts DeploymentOpts) int { // nolint: gocyclo +func (a *App) DeployCloudFormation(ctx context.Context, dir string, opts DeploymentOpts) int { if opts.StackName == "" { - a.Errorln("Stack name not set") + a.Log.Errorf("Stack name not set") return 2 } @@ -287,21 +329,21 @@ func (a *App) DeployCloudFormation(ctx context.Context, dir string, opts Deploym return 1 } - a.Infoln("Processing source files") + a.Log.Debugf("Processing source files") srcs, err := a.sources(resources) if err != nil { - a.Errorf("Could not collect source files: %v\n", err) + a.Log.Errorf("Could not collect source files: %v", err) return 1 } if len(srcs) > 0 && opts.SourceBucket == "" { - a.Errorln("Source bucket not set") + a.Log.Errorf("Source bucket not set") return 2 } cfg, err := external.LoadDefaultAWSConfig() if err != nil { - a.Errorf("Could not load aws config: %v\n", err) + a.Log.Errorf("Could not load aws config: %v", err) } cf := cloudformation.NewClient(cfg) s3 := source.NewS3(cfg, opts.SourceBucket) @@ -315,11 +357,14 @@ func (a *App) DeployCloudFormation(ctx context.Context, dir string, opts Deploym for _, src := range srcs { src := src g.Go(func() error { - return a.ensureSource(gctx, src, s3) + if err := a.ensureSource(gctx, src, s3); err != nil { + return fmt.Errorf("%s: %w", src.Resource, err) + } + return nil }) } - a.Infoln("Generating CloudFormation template") + a.Log.Debugf("Generating CloudFormation template") locs := sourceLocations(srcs, opts.SourceBucket) tmpl, diags := cloudformation.Generate(resources, locs) @@ -331,71 +376,79 @@ func (a *App) DeployCloudFormation(ctx context.Context, dir string, opts Deploym // 2/2: Change set var changeset *cloudformation.ChangeSet g.Go(func() error { - a.Infoln("Creating CloudFormation change set") + a.Log.Debugf("Creating CloudFormation change set") - a.Verboseln("Getting CloudFormation stack") + a.Log.Tracef("Getting CloudFormation stack") stack, err := cf.StackByName(gctx, opts.StackName) if err != nil { return fmt.Errorf("get stack: %w", err) } if stack.ID == "" { - a.Traceln("Stack does not exist") + a.Log.Tracef("Stack does not exist") } else { - a.Tracef("Got CloudFormation stack: %s\n", stack.ID) + a.Log.Tracef("Got CloudFormation stack: %s", stack.ID) } cs, err := cf.CreateChangeSet(gctx, stack, tmpl) if err != nil { return fmt.Errorf("create change set: %w", err) } - a.Tracef("Created CloudFormation change set %s\n", cs.ID) + a.Log.Tracef("Created CloudFormation change set %s\n", cs.ID) changeset = cs return nil }) if err := g.Wait(); err != nil { - a.Errorln(err) + a.Log.Errorf("Error: %v", err) return 1 } if len(changeset.Changes) == 0 { - a.Infoln("No changes") + a.Log.Infof("No changes") if err := cf.DeleteChangeSet(ctx, changeset); err != nil { // Safe to ignore - a.Errorf("Error cleaning up change set: %v\n", err) + a.Log.Errorf("Error cleaning up change set: %v\n", err) return 3 } return 0 } - a.Verboseln("Deploying") + a.Log.Debugf("Deploying") deployment, err := cf.ExecuteChangeSet(ctx, changeset) if err != nil { - a.Errorf("Could not execute change set: %v", err) + a.Log.Errorf("Could not execute change set: %v", err) return 1 } for ev := range cf.Events(ctx, deployment) { switch e := ev.(type) { case cloudformation.ErrorEvent: - a.Errorf("Deployment error: %v", e.Error) + a.Log.Errorf("Deployment error: %v", e.Error) return 1 case cloudformation.ResourceEvent: name := tmpl.LookupResource(e.LogicalID) - a.Verbosef(" %s: %s %s %s\n", name, e.Operation, e.State, e.Reason) + if name == "" { + // No mapping for resources that are being deleted + name = e.LogicalID + } + line := a.Log + if pfx, ok := line.(PrefixLogger); ok { + line = pfx.WithPrefix(fmt.Sprintf(" [%s] ", name)) + } + line.Debugf("%s %s %s", e.Operation, e.State, e.Reason) case cloudformation.StackEvent: if e.State == cloudformation.StateComplete { if e.Operation == cloudformation.StackRollback { - a.Errorf("Deployment failed: %s\n", e.Reason) + a.Log.Errorf("Deployment failed: %s", e.Reason) return 1 } } } } - a.Infoln("Done") + a.Log.Infof("Done") return 0 } diff --git a/cli/logger.go b/cli/logger.go index ed0f7d4..a6b9729 100644 --- a/cli/logger.go +++ b/cli/logger.go @@ -3,8 +3,8 @@ package cli import ( "fmt" "io" - "sync" - "time" + "io/ioutil" + "strings" ) // LogLevel defines the log level to use. @@ -12,68 +12,75 @@ type LogLevel int // Log levels: const ( - Error LogLevel = iota - Info - Verbose + Info LogLevel = iota + Debug Trace ) -// logger writes user-facing log messages. -type logger struct { - Level LogLevel +var allLevels LogLevel = -1 - mu sync.Mutex +// StdLogger is a logger that writes to the given output without ANSI movement +// escape codes. +type StdLogger struct { Output io.Writer + Level LogLevel } -var startTime = time.Now() - -func (l *logger) printDeltaTime() { - d := time.Since(startTime) - sec := int(d.Seconds()) - ms := int(d.Milliseconds()) % 1000 - fmt.Fprintf(l.Output, "%d.%03d ", sec, ms) -} - -func (l *logger) log(level LogLevel, a ...interface{}) { - if l == nil || l.Output == nil || level > l.Level { +func (l *StdLogger) output(level LogLevel, format string, args []interface{}) { + if l.Level < level { return } - l.mu.Lock() - l.printDeltaTime() - fmt.Fprint(l.Output, a...) - l.mu.Unlock() + msg := fmt.Sprintf(format, args...) + if !strings.HasSuffix(msg, "\n") { + msg += "\n" + } + if _, err := fmt.Fprint(l.Output, msg); err != nil { + panic(err) + } } -func (l *logger) logln(level LogLevel, a ...interface{}) { - if l == nil || l.Output == nil || level > l.Level { - return +// Errorf writes an error level log message. +func (l *StdLogger) Errorf(format string, args ...interface{}) { l.output(allLevels, format, args) } + +// Warningf writes a warning level log message. +func (l *StdLogger) Warningf(format string, args ...interface{}) { l.output(allLevels, format, args) } + +// Infof writes an info level log message. +func (l *StdLogger) Infof(format string, args ...interface{}) { l.output(Info, format, args) } + +// Debugf writes a debug level log message. +func (l *StdLogger) Debugf(format string, args ...interface{}) { l.output(Debug, format, args) } + +// Tracef writes a trace level log message. +func (l *StdLogger) Tracef(format string, args ...interface{}) { l.output(Trace, format, args) } + +// WithPrefix creates a new logger that prefixes every log line with the given +// prefix. In case the output is already prefixed, the parent prefix appears +// first in the output. +func (l *StdLogger) WithPrefix(prefix string) PrefixLogger { + out := l.Output + for { + pw, ok := out.(*PrefixWriter) + if !ok { + break + } + out = pw.Output + prefix = string(pw.Prefix) + prefix + } + return &StdLogger{ + Level: l.Level, + Output: &PrefixWriter{ + Output: out, + Prefix: []byte(prefix), + }, } - l.mu.Lock() - l.printDeltaTime() - fmt.Fprintln(l.Output, a...) - l.mu.Unlock() } -func (l *logger) logf(level LogLevel, format string, args ...interface{}) { - if l == nil || l.Output == nil || level > l.Level { - return +// Writer returns an io.Writer for the given log level. If the log level is not +// exceeded, any data written is discarded. +func (l *StdLogger) Writer(level LogLevel) io.Writer { + if l.Level < level { + return ioutil.Discard } - l.mu.Lock() - l.printDeltaTime() - fmt.Fprintf(l.Output, format, args...) - l.mu.Unlock() + return l.Output } - -func (l *logger) Error(a ...interface{}) { l.log(Error, a...) } -func (l *logger) Errorln(a ...interface{}) { l.logln(Error, a...) } -func (l *logger) Errorf(format string, args ...interface{}) { l.logf(Error, format, args...) } -func (l *logger) Info(a ...interface{}) { l.log(Info, a...) } -func (l *logger) Infoln(a ...interface{}) { l.logln(Info, a...) } -func (l *logger) Infof(format string, args ...interface{}) { l.logf(Info, format, args...) } -func (l *logger) Verbose(a ...interface{}) { l.log(Verbose, a...) } -func (l *logger) Verboseln(a ...interface{}) { l.logln(Verbose, a...) } -func (l *logger) Verbosef(format string, args ...interface{}) { l.logf(Verbose, format, args...) } -func (l *logger) Trace(a ...interface{}) { l.log(Trace, a...) } -func (l *logger) Traceln(a ...interface{}) { l.logln(Trace, a...) } -func (l *logger) Tracef(format string, args ...interface{}) { l.logf(Trace, format, args...) } diff --git a/cli/prefix.go b/cli/prefix.go new file mode 100644 index 0000000..ef8ab34 --- /dev/null +++ b/cli/prefix.go @@ -0,0 +1,51 @@ +package cli + +import ( + "bytes" + "io" +) + +// PrefixWriter wraps an io.Writer with a writer that prefixes every line +// with the given prefix. +type PrefixWriter struct { + Output io.Writer + Prefix []byte + + buf bytes.Buffer +} + +// Write writes the given p to the underlying writer, prefixing every line +// separated by \n with the prefix. The output will never end with only the +// prefix. +func (pw *PrefixWriter) Write(p []byte) (int, error) { + n := 0 + for { + i := bytes.IndexByte(p, '\n') + last := i < 0 + if last { + i = len(p) + } else { + i++ + } + line := p[:i] + p = p[i:] + if len(line) > 0 { + if _, err := pw.buf.Write(pw.Prefix); err != nil { + return n, err + } + } + m, err := pw.buf.Write(line) + n += m + if err != nil { + return n, err + } + if last { + break + } + } + if _, err := pw.buf.WriteTo(pw.Output); err != nil { + return 0, err + } + pw.buf.Reset() + return n, nil +} diff --git a/cli/prefix_test.go b/cli/prefix_test.go new file mode 100644 index 0000000..efa8d81 --- /dev/null +++ b/cli/prefix_test.go @@ -0,0 +1,71 @@ +package cli + +import ( + "bytes" + "testing" + + "github.com/google/go-cmp/cmp" +) + +func TestPrefixLineWriter(t *testing.T) { + tests := []struct { + name string + prefix string + input string + want string + }{ + { + name: "NoInput", + prefix: "", + input: "", + want: "", + }, + { + name: "NoPrefix", + prefix: "", + input: "foo", + want: "foo", + }, + { + name: "Prefix", + prefix: ">", + input: "foo", + want: ">foo", + }, + { + name: "NoTrailingNewline", + prefix: ">", + input: "foo\nbar", + want: ">foo\n>bar", + }, + { + name: "TrailingNewline", + prefix: ">", + input: "foo\nbar\n", + want: ">foo\n>bar\n", + }, + { + name: "EmptyLines", + prefix: ">", + input: "foo\n\nbar\n\nbaz\n\n", + want: ">foo\n>\n>bar\n>\n>baz\n>\n", + }, + } + + for _, tc := range tests { + t.Run(tc.name, func(t *testing.T) { + var buf bytes.Buffer + pw := &PrefixWriter{Output: &buf, Prefix: []byte(tc.prefix)} + n, err := pw.Write([]byte(tc.input)) + if err != nil { + t.Fatal(err) + } + if n != len(tc.input) { + t.Fatalf("Write returned %d, want %d", n, len(tc.input)) + } + if diff := cmp.Diff(buf.String(), tc.want); diff != "" { + t.Errorf("Diff (-got +want)\n%s", diff) + } + }) + } +} diff --git a/cmd/deploy.go b/cmd/deploy.go index 3be4e1a..8264268 100644 --- a/cmd/deploy.go +++ b/cmd/deploy.go @@ -29,7 +29,7 @@ func deployCommand() *cobra.Command { os.Exit(1) } - app := cli.NewApp(cli.LogLevel(*logLevel)) + app := cli.NewApp(*logLevel) ctx := context.Background() code := app.DeployCloudFormation(ctx, dir, opts) diff --git a/cmd/generate.go b/cmd/generate.go index 79a6732..d56a92c 100644 --- a/cmd/generate.go +++ b/cmd/generate.go @@ -30,7 +30,7 @@ func generateCommand() *cobra.Command { os.Exit(1) } - app := cli.NewApp(cli.LogLevel(*logLevel)) + app := cli.NewApp(*logLevel) ctx := context.Background() code := app.GenerateCloudFormation(ctx, dir, opts)