feat: Refactoring to make log output more intelligible. (#39)

Co-authored-by: Fritz Durchardt <[email protected]>

cmd/all.go

@@ -19,7 +19,6 @@ func init() {
 				log.Fatal().Err(err).Msg("Unable to initialize myks's globe")
 			}
 
-			log.Info().Msg("Syncing and rendering environments")
 			if err := g.SyncAndRender(); err != nil {
 				log.Fatal().Err(err).Msg("Unable to sync vendir configs")
 			}

cmd/render.go

@@ -13,7 +13,6 @@ func init() {
 		Short: "Render manifests",
 		Long:  "Render manifests",
 		Run: func(cmd *cobra.Command, args []string) {
-			log.Info().Msg("Rendering manifests")
 
 			g := myks.New(".")
 

cmd/root.go

@@ -67,7 +67,6 @@ var rootCmd = &cobra.Command{
 
 func init() {
 	cobra.OnInitialize(initConfig)
-
 	rootCmd.PersistentFlags().StringP("log-level", "l", "info", "Set the logging level")
 
 	if err := viper.BindPFlags(rootCmd.PersistentFlags()); err != nil {

go.mod

@@ -16,7 +16,7 @@ require (
 	github.com/inconshreveable/mousetrap v1.1.0 // indirect
 	github.com/magiconair/properties v1.8.7 // indirect
 	github.com/mattn/go-colorable v0.1.12 // indirect
-	github.com/mattn/go-isatty v0.0.14 // indirect
+	github.com/mattn/go-isatty v0.0.19 // indirect
 	github.com/mitchellh/mapstructure v1.5.0 // indirect
 	github.com/pelletier/go-toml/v2 v2.0.8 // indirect
 	github.com/spf13/afero v1.9.5 // indirect

go.sum

@@ -142,8 +142,9 @@ github.com/magiconair/properties v1.8.7 h1:IeQXZAiQcpL9mgcAe1Nu6cX9LLw6ExEHKjN0V
 github.com/magiconair/properties v1.8.7/go.mod h1:Dhd985XPs7jluiymwWYZ0G4Z61jb3vdS329zhj2hYo0=
 github.com/mattn/go-colorable v0.1.12 h1:jF+Du6AlPIjs2BiUiQlKOX0rt3SujHxPnksPKZbaA40=
 github.com/mattn/go-colorable v0.1.12/go.mod h1:u5H1YNBxpqRaxsYJYSkiCWKzEfiAb1Gb520KVy5xxl4=
-github.com/mattn/go-isatty v0.0.14 h1:yVuAays6BHfxijgZPzw+3Zlu5yQgKGP2/hcQbHb7S9Y=
 github.com/mattn/go-isatty v0.0.14/go.mod h1:7GGIvUiUoEMVVmxf/4nioHXj79iQHKdU27kJ6hsGG94=
+github.com/mattn/go-isatty v0.0.19 h1:JITubQf0MOLdlGRuRq+jtsDlekdYPia9ZFsB8h/APPA=
+github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y=
 github.com/mitchellh/mapstructure v1.5.0 h1:jeMsZIYE/09sWLaz43PL7Gy6RuMjD2eJVyuac5Z2hdY=
 github.com/mitchellh/mapstructure v1.5.0/go.mod h1:bFUtVrKA4DC2yAKiSyO/QUcy7e+RRV2QTWOzhPopBRo=
 github.com/pelletier/go-toml/v2 v2.0.8 h1:0ctb6s9mE31h0/lhu+J6OPmVeDxJn+kYnJc2jZR9tGQ=
@@ -323,6 +324,7 @@ golang.org/x/sys v0.0.0-20210615035016-665e8c7367d1/go.mod h1:oPkhp1MJrh7nUepCBc
 golang.org/x/sys v0.0.0-20210630005230-0f9fa26af87c/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20210927094055-39ccf1dd6fa6/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.0.0-20220908164124-27713097b956/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
+golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.10.0 h1:SqMFp9UcQJZa+pmYuAKjd9xq1f0j5rLcDIk0mj4qAsA=
 golang.org/x/sys v0.10.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/term v0.0.0-20201126162022-7de9c90e9dd1/go.mod h1:bj7SfCRtBDWHUb9snDiAeCFNEtKQo2Wmx5Cou7ajbmo=

internal/myks/application.go

@@ -2,10 +2,23 @@ package myks
 
 import (
 	"errors"
+	"fmt"
+	"github.com/rs/zerolog/log"
+	yaml "gopkg.in/yaml.v3"
+	"io"
 	"os"
 	"path/filepath"
+)
 
-	yaml "gopkg.in/yaml.v3"
+const (
+	renderStepName    = "render"
+	syncStepName      = "sync"
+	globalYttStepName = "global-ytt"
+	yttStepName       = "ytt"
+	yttPkgStepName    = "ytt-pkg"
+	helmStepName      = "helm"
+	sliceStepName     = "slice"
+	initStepName      = "init"
 )
 
 type Application struct {
@@ -28,6 +41,7 @@ type HelmConfig struct {
 }
 
 var ErrNoVendirConfig = errors.New("no vendir config found")
+var ApplicationLogFormat = "\033[1m[%s > %s > %s]\033[0m %s"
 
 func NewApplication(e *Environment, name string, prototypeName string) (*Application, error) {
 	if prototypeName == "" {
@@ -61,7 +75,7 @@ func (a *Application) Init() error {
 
 	a.collectDataFiles()
 
-	dataYaml, err := renderDataYaml(a.Name, append(a.e.g.extraYttPaths, a.yttDataFiles...))
+	dataYaml, err := a.renderDataYaml(append(a.e.g.extraYttPaths, a.yttDataFiles...))
 	if err != nil {
 		return err
 	}
@@ -122,3 +136,49 @@ func (a *Application) collectDataFiles() {
 	overrideDataFiles := a.e.collectBySubpath(filepath.Join("_apps", a.Name, a.e.g.ApplicationDataFileName))
 	a.yttDataFiles = append(a.yttDataFiles, overrideDataFiles...)
 }
+
+func (a *Application) Msg(step string, msg string) string {
+	formattedMessage := fmt.Sprintf(ApplicationLogFormat, a.e.Id, a.Name, step, msg)
+	return formattedMessage
+}
+
+func (a *Application) runCmd(purpose string, cmd string, stdin io.Reader, args []string) (CmdResult, error) {
+	return runCmd(cmd, stdin, args, func(cmd string, args []string) {
+		log.Debug().Msg(msgRunCmd(purpose, cmd, args))
+	})
+}
+
+func (a *Application) renderDataYaml(dataFiles []string) ([]byte, error) {
+	if len(dataFiles) == 0 {
+		return nil, errors.New("No data files found")
+	}
+	res, err := runYttWithFilesAndStdin(dataFiles, nil, func(name string, args []string) {
+		log.Debug().Msg(a.Msg("init", msgRunCmd("render application data values file", name, args)))
+	}, "--data-values-inspect")
+	if err != nil {
+		log.Error().Err(err).Str("stderr", res.Stderr).Msg(a.Msg("init", "Unable to render data"))
+		return nil, err
+	}
+	if res.Stdout == "" {
+		return nil, errors.New("Empty output from ytt")
+	}
+
+	dataYaml := []byte(res.Stdout)
+	return dataYaml, nil
+}
+
+func (a *Application) mergeValuesYaml(valueFilesYaml string) (CmdResult, error) {
+	return runYttWithFilesAndStdin(nil, nil, func(name string, args []string) {
+		log.Debug().Msg(msgRunCmd("merge data values file", name, args))
+	}, "--data-values-file="+valueFilesYaml, "--data-values-inspect")
+}
+
+func (a *Application) ytt(step string, purpose string, paths []string, args ...string) (CmdResult, error) {
+	return a.yttS(step, purpose, paths, nil, args...)
+}
+
+func (a *Application) yttS(step string, purpose string, paths []string, stdin io.Reader, args ...string) (CmdResult, error) {
+	return runYttWithFilesAndStdin(append(a.e.g.extraYttPaths, paths...), stdin, func(name string, args []string) {
+		log.Debug().Msg(a.Msg(step, msgRunCmd(purpose, name, args)))
+	}, args...)
+}

internal/myks/application_test.go

@@ -0,0 +1,36 @@
+package myks
+
+import (
+	"os"
+	"reflect"
+	"testing"
+)
+
+func TestApplication_renderDataYaml(t *testing.T) {
+	if os.Getenv("CI") == "true" {
+		t.Skip("Skipping in pipeline since ytt is not installed")
+	}
+	type args struct {
+		dataFiles []string
+	}
+	tests := []struct {
+		name    string
+		args    args
+		want    string
+		wantErr bool
+	}{
+		{"happy path", args{[]string{"../../testData/ytt/data-file-schema.yaml", "../../testData/ytt/data-file-schema-2.yaml", "../../testData/ytt/data-file-values.yaml"}}, "application:\n  cache:\n    enabled: true\n  name: cert-manager\n", false},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			got, err := testApp.renderDataYaml(tt.args.dataFiles)
+			if (err != nil) != tt.wantErr {
+				t.Errorf("renderDataYaml() error = %v, wantErr %v", err, tt.wantErr)
+				return
+			}
+			if !reflect.DeepEqual(string(got), tt.want) {
+				t.Errorf("renderDataYaml() got = %v, want %v", got, tt.want)
+			}
+		})
+	}
+}

internal/myks/environment.go

@@ -3,6 +3,7 @@ package myks
 import (
 	"errors"
 	"fmt"
+	"io"
 	"os"
 	"path/filepath"
 	"strings"
@@ -11,6 +12,8 @@ import (
 	yaml "gopkg.in/yaml.v3"
 )
 
+var EnvLogFormat = "\033[1m[%s > %s]\033[0m %s"
+
 type ManifestApplication struct {
 	Name      string
 	Prototype string
@@ -63,11 +66,15 @@ func NewEnvironment(g *Globe, dir string) *Environment {
 
 func (e *Environment) Init(applicationNames []string) error {
 	if err := e.initEnvData(); err != nil {
-		log.Warn().Err(err).Str("dir", e.Dir).Msg("Unable to initialize environment data")
+		log.Warn().Err(err).Str("dir", e.Dir).Msg(e.Msg("Unable to initialize environment data"))
 		return err
 	}
 
-	e.initApplications(applicationNames)
+	err := e.initApplications(applicationNames)
+	if err != nil {
+		log.Error().Err(err).Msg(e.Msg("Unable to initialize applications"))
+		return err
+	}
 
 	return nil
 }
@@ -120,7 +127,7 @@ func (e *Environment) SyncAndRender() error {
 func (e *Environment) setId() error {
 	yamlBytes, err := os.ReadFile(e.EnvironmentDataFile)
 	if err != nil {
-		log.Debug().Err(err).Msg("Unable to read environment data file")
+		log.Debug().Err(err).Msg(e.Msg("Unable to read environment data file"))
 		return err
 	}
 
@@ -131,12 +138,10 @@ func (e *Environment) setId() error {
 	}
 	err = yaml.Unmarshal(yamlBytes, &envData)
 	if err != nil {
-		log.Debug().Err(err).Msg("Unable to unmarshal environment data file")
+		log.Debug().Err(err).Msg(e.Msg("Unable to unmarshal environment data file"))
 		return err
 	}
 
-	log.Debug().Interface("envData", envData).Msg("Environment data")
-
 	if envData.Environment.Id == "" {
 		err = errors.New("Environment data file missing id")
 		log.Debug().Err(err).Str("file", e.EnvironmentDataFile).Msg("Unable to set environment id")
@@ -145,24 +150,26 @@ func (e *Environment) setId() error {
 
 	e.Id = envData.Environment.Id
 
+	log.Debug().Interface("envData", envData).Msg(e.Msg("Environment data"))
+
 	return nil
 }
 
 func (e *Environment) initEnvData() error {
 	envDataFiles := e.collectBySubpath(e.g.EnvironmentDataFileName)
 	envDataYaml, err := e.renderEnvData(envDataFiles)
 	if err != nil {
-		log.Warn().Err(err).Str("dir", e.Dir).Msg("Unable to render environment data")
+		log.Warn().Err(err).Str("dir", e.Dir).Msg(e.Msg("Unable to render environment data"))
 		return err
 	}
 	err = e.saveRenderedEnvData(envDataYaml)
 	if err != nil {
-		log.Warn().Err(err).Str("dir", e.Dir).Msg("Unable to save rendered environment data")
+		log.Warn().Err(err).Str("dir", e.Dir).Msg(e.Msg("Unable to save rendered environment data"))
 		return err
 	}
 	err = e.setEnvDataFromYaml(envDataYaml)
 	if err != nil {
-		log.Warn().Err(err).Str("dir", e.Dir).Msg("Unable to set environment data")
+		log.Warn().Err(err).Str("dir", e.Dir).Msg(e.Msg("Unable to set environment data"))
 		return err
 	}
 
@@ -173,9 +180,9 @@ func (e *Environment) renderEnvData(envDataFiles []string) ([]byte, error) {
 	if len(envDataFiles) == 0 {
 		return nil, errors.New("No environment data files found")
 	}
-	res, err := e.g.ytt(envDataFiles, "--data-values-inspect")
+	res, err := e.ytt("render environment data values file", envDataFiles, "--data-values-inspect")
 	if err != nil {
-		log.Error().Err(err).Str("stderr", res.Stderr).Msg("Unable to render environment data")
+		log.Error().Err(err).Str("stderr", res.Stderr).Msg(e.Msg("Unable to render environment data"))
 		return nil, err
 	}
 	if res.Stdout == "" {
@@ -190,15 +197,14 @@ func (e *Environment) saveRenderedEnvData(envDataYaml []byte) error {
 	dir := filepath.Dir(e.renderedEnvDataFilePath)
 	err := os.MkdirAll(dir, 0o750)
 	if err != nil {
-		log.Error().Err(err).Str("dir", dir).Msg("Unable to create directory for rendered envData file")
+		log.Error().Err(err).Str("dir", dir).Msg(e.Msg("Unable to create directory for rendered envData file"))
 		return err
 	}
 	err = os.WriteFile(e.renderedEnvDataFilePath, envDataYaml, 0o600)
 	if err != nil {
-		log.Error().Err(err).Msg("Unable to write rendered envData file")
+		log.Error().Err(err).Msg(e.Msg("Unable to write rendered envData file"))
 		return err
 	}
-	log.Debug().Str("file", e.renderedEnvDataFilePath).Msg("Wrote rendered envData file")
 	return nil
 }
 
@@ -213,14 +219,14 @@ func (e *Environment) setEnvDataFromYaml(envDataYaml []byte) error {
 	}
 	err := yaml.Unmarshal(envDataYaml, &envDataStruct)
 	if err != nil {
-		log.Error().Err(err).Msg("Unable to unmarshal environment data yaml")
+		log.Error().Err(err).Msg(e.Msg("Unable to unmarshal environment data yaml"))
 		return err
 	}
 
 	for _, app := range envDataStruct.Environment.Applications {
 		proto := app.Proto
 		if len(proto) == 0 {
-			log.Error().Interface("app", app).Msg("Application prototype is not set")
+			log.Error().Interface("app", app).Msg(e.Msg("Application prototype is not set"))
 			continue
 		}
 
@@ -230,7 +236,7 @@ func (e *Environment) setEnvDataFromYaml(envDataYaml []byte) error {
 		}
 
 		if _, ok := e.foundApplications[name]; ok {
-			log.Error().Str("app_name", name).Msg("Duplicated application")
+			log.Error().Str("app_name", name).Msg(e.Msg("Duplicated application"))
 			continue
 
 		}
@@ -241,24 +247,36 @@ func (e *Environment) setEnvDataFromYaml(envDataYaml []byte) error {
 	if len(e.foundApplications) == 0 {
 		log.Warn().Str("dir", e.Dir).Msg("No applications found")
 	} else {
-		log.Debug().Interface("apps", e.foundApplications).Msg("Found applications")
+		log.Debug().Interface("apps", e.foundApplications).Msg(e.Msg("Found applications"))
 	}
 
 	return nil
 }
 
-func (e *Environment) initApplications(applicationNames []string) {
-	for name, proto := range e.foundApplications {
-		if len(applicationNames) == 0 || contains(applicationNames, name) {
+func (e *Environment) initApplications(applicationNames []string) error {
+	if len(applicationNames) == 0 {
+		for name, proto := range e.foundApplications {
 			app, err := NewApplication(e, name, proto)
 			if err != nil {
-				log.Warn().Err(err).Str("dir", e.Dir).Interface("app", name).Msg("Unable to initialize application")
+				log.Warn().Err(err).Str("dir", e.Dir).Interface("app", name).Msg(e.Msg("Unable to initialize application"))
 			} else {
 				e.Applications = append(e.Applications, app)
 			}
 		}
 	}
-	log.Debug().Interface("applications", e.Applications).Msg("Applications")
+	for _, appName := range applicationNames {
+		proto := e.foundApplications[appName]
+		if proto == "" {
+			return errors.New("Application not found: " + appName)
+		}
+		app, err := NewApplication(e, appName, proto)
+		if err != nil {
+			log.Warn().Err(err).Str("dir", e.Dir).Interface("app", appName).Msg(e.Msg("Unable to initialize application"))
+		} else {
+			e.Applications = append(e.Applications, app)
+		}
+	}
+	return nil
 }
 
 func (e *Environment) collectBySubpath(subpath string) []string {
@@ -275,3 +293,18 @@ func (e *Environment) collectBySubpath(subpath string) []string {
 	}
 	return items
 }
+
+func (e *Environment) Msg(msg string) string {
+	formattedMessage := fmt.Sprintf(EnvLogFormat, e.Id, initStepName, msg)
+	return formattedMessage
+}
+
+func (e *Environment) ytt(purpose string, paths []string, args ...string) (CmdResult, error) {
+	return e.yttS(purpose, paths, nil, args...)
+}
+
+func (e *Environment) yttS(purpose string, paths []string, stdin io.Reader, args ...string) (CmdResult, error) {
+	return runYttWithFilesAndStdin(append(e.g.extraYttPaths, paths...), stdin, func(name string, args []string) {
+		log.Debug().Msg(e.Msg(msgRunCmd(purpose, name, args)))
+	}, args...)
+}