From 80178422db8f5cf7066199555cfd8d816353d298 Mon Sep 17 00:00:00 2001
From: James Shubin <james@shubin.ca>
Date: Tue, 6 Aug 2024 15:12:10 -0400
Subject: [PATCH] engine: graph, resources: Clean up log messages

The idea is to have a better user experience in the terminal.
---
 engine/graph/actions.go       |  8 ++++--
 engine/graph/engine.go        |  2 +-
 engine/resources/augeas.go    |  1 -
 engine/resources/aws_ec2.go   |  2 +-
 engine/resources/file.go      | 51 +++++++++++++++++++----------------
 engine/resources/group.go     |  2 --
 engine/resources/http_flag.go |  6 +----
 engine/resources/kv.go        | 12 +++++----
 engine/resources/nspawn.go    |  4 +--
 engine/resources/print.go     |  3 +--
 engine/resources/test.go      |  2 +-
 engine/resources/user.go      |  2 --
 engine/resources/value.go     |  2 +-
 13 files changed, 49 insertions(+), 48 deletions(-)

diff --git a/engine/graph/actions.go b/engine/graph/actions.go
index 80a2e48d..d1aa78f0 100644
--- a/engine/graph/actions.go
+++ b/engine/graph/actions.go
@@ -192,10 +192,14 @@ func (obj *Engine) Process(ctx context.Context, vertex pgraph.Vertex) error {
 
 	} else {
 		// run the CheckApply!
-		obj.Logf("%s: CheckApply(%t)", res, !noop)
+		if obj.Debug {
+			obj.Logf("%s: CheckApply(%t)", res, !noop)
+		}
 		// if this fails, don't UpdateTimestamp()
 		checkOK, err = res.CheckApply(ctx, !noop)
-		obj.Logf("%s: CheckApply(%t): Return(%t, %s)", res, !noop, checkOK, engineUtil.CleanError(err))
+		if !checkOK && obj.Debug { // don't log on (checkOK == true)
+			obj.Logf("%s: CheckApply(%t): Return(%t, %s)", res, !noop, checkOK, engineUtil.CleanError(err))
+		}
 	}
 
 	if checkOK && err != nil { // should never return this way
diff --git a/engine/graph/engine.go b/engine/graph/engine.go
index 487559ee..c02eaf4c 100644
--- a/engine/graph/engine.go
+++ b/engine/graph/engine.go
@@ -268,7 +268,7 @@ func (obj *Engine) Commit() error {
 					obj.wlock.Unlock()
 				}()
 
-				if obj.Debug || true {
+				if obj.Debug {
 					obj.Logf("%s: Working...", v)
 				}
 				// contains the Watch and CheckApply loops
diff --git a/engine/resources/augeas.go b/engine/resources/augeas.go
index 2f6cabcd..23510393 100644
--- a/engine/resources/augeas.go
+++ b/engine/resources/augeas.go
@@ -206,7 +206,6 @@ func (obj *AugeasRes) checkApplySet(ctx context.Context, apply bool, ag *augeas.
 
 // CheckApply method for Augeas resource.
 func (obj *AugeasRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
-	obj.init.Logf("CheckApply: %s", obj.File)
 	// By default we do not set any option to augeas, we use the defaults.
 	opts := augeas.None
 	if obj.Lens != "" {
diff --git a/engine/resources/aws_ec2.go b/engine/resources/aws_ec2.go
index c4dc483c..d819a5f2 100644
--- a/engine/resources/aws_ec2.go
+++ b/engine/resources/aws_ec2.go
@@ -638,7 +638,7 @@ func (obj *AwsEc2Res) snsWatch(ctx context.Context) error {
 
 // CheckApply method for AwsEc2 resource.
 func (obj *AwsEc2Res) CheckApply(ctx context.Context, apply bool) (bool, error) {
-	obj.init.Logf("CheckApply(%t)", apply)
+	obj.init.Logf("CheckApply(%t)", apply) // XXX: replace with logf on change
 
 	// find the instance we need to check
 	instance, err := describeInstanceByName(obj.client, obj.prependName())
diff --git a/engine/resources/file.go b/engine/resources/file.go
index a4c063fe..69f43dd4 100644
--- a/engine/resources/file.go
+++ b/engine/resources/file.go
@@ -605,7 +605,7 @@ func (obj *FileRes) fileCheckApply(ctx context.Context, apply bool, src io.ReadS
 		}
 		// FIXME: respect obj.Recurse here...
 		// there is a dir here, where we want a file...
-		obj.init.Logf("fileCheckApply: removing (force): %s", cleanDst)
+		obj.init.Logf("removing (force): %s", cleanDst)
 		if err := os.RemoveAll(cleanDst); err != nil { // dangerous ;)
 			return "", false, err
 		}
@@ -651,7 +651,7 @@ func (obj *FileRes) fileCheckApply(ctx context.Context, apply bool, src io.ReadS
 		return sha256sum, false, nil
 	}
 	if obj.init.Debug {
-		obj.init.Logf("fileCheckApply: apply: %v -> %s", src, dst)
+		obj.init.Logf("apply: %v -> %s", src, dst)
 	}
 
 	dstClose() // unlock file usage so we can write to it
@@ -672,12 +672,12 @@ func (obj *FileRes) fileCheckApply(ctx context.Context, apply bool, src io.ReadS
 
 	// TODO: should we offer a way to cancel the copy on ^C ?
 	if obj.init.Debug {
-		obj.init.Logf("fileCheckApply: copy: %v -> %s", src, dst)
+		obj.init.Logf("copy: %v -> %s", src, dst)
 	}
 	if n, err := io.Copy(dstFile, src); err != nil {
 		return sha256sum, false, err
 	} else if obj.init.Debug {
-		obj.init.Logf("fileCheckApply: copied: %v", n)
+		obj.init.Logf("copied: %v", n)
 	}
 	return sha256sum, false, dstFile.Sync()
 }
@@ -704,7 +704,7 @@ func (obj *FileRes) dirCheckApply(ctx context.Context, apply bool) (bool, error)
 	// the path exists and is not a directory
 	// delete the file if force is given
 	if err == nil && !fileInfo.IsDir() {
-		obj.init.Logf("dirCheckApply: removing (force): %s", obj.getPath())
+		obj.init.Logf("removing (force): %s", obj.getPath())
 		if err := os.Remove(obj.getPath()); err != nil {
 			return false, err
 		}
@@ -720,6 +720,7 @@ func (obj *FileRes) dirCheckApply(ctx context.Context, apply bool) (bool, error)
 
 	if obj.Recurse {
 		// TODO: add recurse limit here
+		obj.init.Logf("mkdir -p -m %s", mode)
 		return false, os.MkdirAll(obj.getPath(), mode)
 	}
 
@@ -733,7 +734,7 @@ func (obj *FileRes) dirCheckApply(ctx context.Context, apply bool) (bool, error)
 // with the exception that a sync *can* convert a file to a dir, or vice-versa.
 func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst string, excludes []string) (bool, error) {
 	if obj.init.Debug {
-		obj.init.Logf("syncCheckApply: %s -> %s", src, dst)
+		obj.init.Logf("sync: %s -> %s", src, dst)
 	}
 	// an src of "" is now supported, if dst is a dir
 	if dst == "" {
@@ -755,12 +756,12 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 
 	if !srcIsDir && !dstIsDir && src != "" {
 		if obj.init.Debug {
-			obj.init.Logf("syncCheckApply: %s -> %s", src, dst)
+			obj.init.Logf("sync: %s -> %s", src, dst)
 		}
 		fin, err := os.Open(src)
 		if err != nil {
 			if obj.init.Debug && os.IsNotExist(err) { // if we get passed an empty src
-				obj.init.Logf("syncCheckApply: missing src: %s", src)
+				obj.init.Logf("missing src: %s", src)
 			}
 			return false, err
 		}
@@ -782,7 +783,9 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 			return false, err
 		}
 		smartSrc = mapPaths(srcFiles)
-		obj.init.Logf("syncCheckApply: srcFiles: %v", printFiles(smartSrc))
+		if obj.init.Debug {
+			obj.init.Logf("srcFiles: %v", printFiles(smartSrc))
+		}
 	}
 
 	dstFiles, err := ReadDir(dst)
@@ -790,7 +793,9 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 		return false, err
 	}
 	smartDst := mapPaths(dstFiles)
-	obj.init.Logf("syncCheckApply: dstFiles: %v", printFiles(smartDst))
+	if obj.init.Debug {
+		obj.init.Logf("dstFiles: %v", printFiles(smartDst))
+	}
 
 	for relPath, fileInfo := range smartSrc {
 		absSrc := fileInfo.AbsPath // absolute path
@@ -814,7 +819,7 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 					if absCleanDst == "" || absCleanDst == "/" {
 						return false, fmt.Errorf("don't want to remove root") // safety
 					}
-					obj.init.Logf("syncCheckApply: removing (force): %s", absCleanDst)
+					obj.init.Logf("removing (force): %s", absCleanDst)
 					if err := os.Remove(absCleanDst); err != nil {
 						return false, err
 					}
@@ -822,7 +827,7 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 				}
 
 				if obj.init.Debug {
-					obj.init.Logf("syncCheckApply: mkdir -m %s '%s'", fileInfo.Mode(), absDst)
+					obj.init.Logf("mkdir -m %s '%s'", fileInfo.Mode(), absDst)
 				}
 				if err := os.Mkdir(absDst, fileInfo.Mode()); err != nil {
 					return false, err
@@ -833,11 +838,11 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 		}
 
 		if obj.init.Debug {
-			obj.init.Logf("syncCheckApply: recurse: %s -> %s", absSrc, absDst)
+			obj.init.Logf("recurse: %s -> %s", absSrc, absDst)
 		}
 		if obj.Recurse {
 			if c, err := obj.syncCheckApply(ctx, apply, absSrc, absDst, excludes); err != nil { // recurse
-				return false, errwrap.Wrapf(err, "syncCheckApply: recurse failed")
+				return false, errwrap.Wrapf(err, "recurse failed")
 			} else if !c { // don't let subsequent passes make this true
 				checkOK = false
 			}
@@ -882,7 +887,7 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 			if isExcluded(absDst) { // skip removing excluded files
 				continue
 			}
-			obj.init.Logf("syncCheckApply: removing: %s", absCleanDst)
+			obj.init.Logf("removing: %s", absCleanDst)
 			if apply {
 				if err := os.RemoveAll(absCleanDst); err != nil { // dangerous ;)
 					return false, err
@@ -892,16 +897,16 @@ func (obj *FileRes) syncCheckApply(ctx context.Context, apply bool, src, dst str
 			continue
 		}
 		_ = absSrc
-		//obj.init.Logf("syncCheckApply: recurse rm: %s -> %s", absSrc, absDst)
+		//obj.init.Logf("recurse rm: %s -> %s", absSrc, absDst)
 		//if c, err := obj.syncCheckApply(ctx, apply, absSrc, absDst, excludes); err != nil {
-		//	return false, errwrap.Wrapf(err, "syncCheckApply: recurse rm failed")
+		//	return false, errwrap.Wrapf(err, "recurse rm failed")
 		//} else if !c { // don't let subsequent passes make this true
 		//	checkOK = false
 		//}
 		//if isExcluded(absDst) { // skip removing excluded files
 		//	continue
 		//}
-		//obj.init.Logf("syncCheckApply: removing: %s", absCleanDst)
+		//obj.init.Logf("removing: %s", absCleanDst)
 		//if apply { // safety
 		//	if err := os.Remove(absCleanDst); err != nil {
 		//		return false, err
@@ -948,7 +953,7 @@ func (obj *FileRes) stateCheckApply(ctx context.Context, apply bool) (bool, erro
 		if p == "/" {
 			return false, fmt.Errorf("don't want to remove root") // safety
 		}
-		obj.init.Logf("stateCheckApply: removing: %s", p)
+		obj.init.Logf("removing: %s", p)
 		// TODO: add recurse limit here
 		if obj.Recurse {
 			return false, os.RemoveAll(p) // dangerous ;)
@@ -1053,13 +1058,13 @@ func (obj *FileRes) sourceCheckApply(ctx context.Context, apply bool) (bool, err
 		}
 	}
 	if obj.init.Debug {
-		obj.init.Logf("syncCheckApply: excludes: %+v", excludes)
+		obj.init.Logf("excludes: %+v", excludes)
 	}
 
 	// XXX: should this work with obj.Purge && obj.Source != "" or not?
 	checkOK, err := obj.syncCheckApply(ctx, apply, obj.Source, obj.getPath(), excludes)
 	if err != nil {
-		obj.init.Logf("syncCheckApply: error: %v", err)
+		obj.init.Logf("error: %v", err)
 		return false, err
 	}
 
@@ -1187,7 +1192,7 @@ func (obj *FileRes) chownCheckApply(ctx context.Context, apply bool) (bool, erro
 		return false, nil
 	}
 
-	obj.init.Logf("chown %s:%s %s", obj.Owner, obj.Group, obj.getPath())
+	obj.init.Logf("chown %s:%s", obj.Owner, obj.Group)
 	return false, os.Chown(obj.getPath(), expectedUID, expectedGID)
 }
 
@@ -1222,7 +1227,7 @@ func (obj *FileRes) chmodCheckApply(ctx context.Context, apply bool) (bool, erro
 		return false, nil
 	}
 
-	obj.init.Logf("chmod %s %s", obj.Mode, obj.getPath())
+	obj.init.Logf("chmod %s", obj.Mode)
 	return false, os.Chmod(obj.getPath(), mode)
 }
 
diff --git a/engine/resources/group.go b/engine/resources/group.go
index 9033892d..92953892 100644
--- a/engine/resources/group.go
+++ b/engine/resources/group.go
@@ -135,8 +135,6 @@ func (obj *GroupRes) Watch(ctx context.Context) error {
 
 // CheckApply method for Group resource.
 func (obj *GroupRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
-	obj.init.Logf("CheckApply(%t)", apply)
-
 	// check if the group exists
 	exists := true
 	group, err := user.LookupGroup(obj.Name())
diff --git a/engine/resources/http_flag.go b/engine/resources/http_flag.go
index 281e2a76..6e73c942 100644
--- a/engine/resources/http_flag.go
+++ b/engine/resources/http_flag.go
@@ -238,12 +238,8 @@ func (obj *HTTPFlagRes) Watch(ctx context.Context) error {
 
 // CheckApply never has anything to do for this resource, so it always succeeds.
 func (obj *HTTPFlagRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
-	if obj.init.Debug {
-		obj.init.Logf("CheckApply")
-	}
-
 	if obj.init.Debug || true { // XXX: maybe we should always do this?
-		obj.init.Logf("CheckApply: value: %+v", obj.value)
+		obj.init.Logf("value: %+v", obj.value)
 	}
 
 	// TODO: can we send an empty (nil) value to show it has been removed?
diff --git a/engine/resources/kv.go b/engine/resources/kv.go
index c6da8a27..25320dca 100644
--- a/engine/resources/kv.go
+++ b/engine/resources/kv.go
@@ -277,8 +277,6 @@ func (obj *KVRes) lessThanCheck(value string) (bool, error) {
 
 // CheckApply method for Password resource. Does nothing, returns happy!
 func (obj *KVRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
-	obj.init.Logf("CheckApply(%t)", apply)
-
 	wg := &sync.WaitGroup{}
 	defer wg.Wait() // this must be above the defer cancel() call
 	ctx, cancel := context.WithTimeout(ctx, kvCheckApplyTimeout)
@@ -296,7 +294,7 @@ func (obj *KVRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
 
 	if val, exists := obj.init.Recv()["value"]; exists && val.Changed {
 		// if we received on Value, and it changed, wooo, nothing to do.
-		obj.init.Logf("CheckApply: `value` was updated!")
+		obj.init.Logf("`value` was received!")
 	}
 
 	value, exists, err := obj.kvGet(ctx, obj.getKey())
@@ -321,8 +319,11 @@ func (obj *KVRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
 		if !apply {
 			return false, nil
 		}
-		err := obj.kvDel(ctx, obj.getKey())
-		return false, errwrap.Wrapf(err, "error during del")
+		if err := obj.kvDel(ctx, obj.getKey()); err != nil {
+			return false, errwrap.Wrapf(err, "error during del")
+		}
+		obj.init.Logf("`value` was deleted!")
+		return false, nil
 	}
 
 	if !apply {
@@ -332,6 +333,7 @@ func (obj *KVRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
 	if err := obj.kvSet(ctx, obj.getKey(), *obj.Value); err != nil {
 		return false, errwrap.Wrapf(err, "error during set")
 	}
+	obj.init.Logf("`value` was changed!")
 
 	return false, nil
 }
diff --git a/engine/resources/nspawn.go b/engine/resources/nspawn.go
index b21fbc1d..e435bd16 100644
--- a/engine/resources/nspawn.go
+++ b/engine/resources/nspawn.go
@@ -253,7 +253,7 @@ func (obj *NspawnRes) CheckApply(ctx context.Context, apply bool) (bool, error)
 	// be stopped or the state matches we're done
 	if !exists && obj.State == stopped || properties["State"] == obj.State {
 		if obj.init.Debug {
-			obj.init.Logf("CheckApply() in valid state")
+			obj.init.Logf("in valid state")
 		}
 		return true, nil
 	}
@@ -263,7 +263,7 @@ func (obj *NspawnRes) CheckApply(ctx context.Context, apply bool) (bool, error)
 		return false, nil
 	}
 
-	obj.init.Logf("CheckApply() applying '%s' state", obj.State)
+	obj.init.Logf("applying '%s' state", obj.State)
 	// use the embedded svc to apply the correct state
 	if _, err := obj.svc.CheckApply(ctx, apply); err != nil {
 		return false, errwrap.Wrapf(err, "nested svc failed")
diff --git a/engine/resources/print.go b/engine/resources/print.go
index 1fed6201..ed8ffe1c 100644
--- a/engine/resources/print.go
+++ b/engine/resources/print.go
@@ -96,10 +96,9 @@ func (obj *PrintRes) Watch(ctx context.Context) error {
 
 // CheckApply method for Print resource. Does nothing, returns happy!
 func (obj *PrintRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
-	obj.init.Logf("CheckApply: %t", apply)
 	if val, exists := obj.init.Recv()["msg"]; exists && val.Changed {
 		// if we received on Msg, and it changed, log message
-		obj.init.Logf("CheckApply: Received `msg` of: %s", obj.Msg)
+		obj.init.Logf("received `msg` of: %s", obj.Msg)
 	}
 
 	var refresh = obj.init.Refresh()
diff --git a/engine/resources/test.go b/engine/resources/test.go
index fa8a405b..1763ef35 100644
--- a/engine/resources/test.go
+++ b/engine/resources/test.go
@@ -161,7 +161,7 @@ func (obj *TestRes) Watch(ctx context.Context) error {
 func (obj *TestRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
 	expectRecv := []string{}
 	for key, val := range obj.init.Recv() {
-		obj.init.Logf("CheckApply: Received `%s`, changed: %t", key, val.Changed)
+		obj.init.Logf("received `%s`, changed: %t", key, val.Changed)
 		expectRecv = append(expectRecv, key)
 	}
 
diff --git a/engine/resources/user.go b/engine/resources/user.go
index 4d8ef766..bef0b568 100644
--- a/engine/resources/user.go
+++ b/engine/resources/user.go
@@ -182,8 +182,6 @@ func (obj *UserRes) Watch(ctx context.Context) error {
 
 // CheckApply method for User resource.
 func (obj *UserRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
-	obj.init.Logf("CheckApply(%t)", apply)
-
 	var exists = true
 	usr, err := user.Lookup(obj.Name())
 	if err != nil {
diff --git a/engine/resources/value.go b/engine/resources/value.go
index 37e3d243..0083896d 100644
--- a/engine/resources/value.go
+++ b/engine/resources/value.go
@@ -140,7 +140,7 @@ func (obj *ValueRes) CheckApply(ctx context.Context, apply bool) (bool, error) {
 	checkOK := false
 	if val, exists := obj.init.Recv()["any"]; exists && val.Changed {
 		// if we received on Any, and it changed, invalidate the cache!
-		obj.init.Logf("CheckApply: received on `any`")
+		obj.init.Logf("received on `any`")
 		obj.isSet = true // we received something
 		obj.cachedAny = obj.Any
 		received = true // we'll always need to send below when we recv