Fix for humanize time in #5005

integration/skaffold/helper.go

@@ -214,7 +214,7 @@ func (b *RunBuilder) runForked(t *testing.T, out io.Writer) {
 
 	go func() {
 		cmd.Wait()
-		logrus.Infoln("Ran in", time.Since(start))
+		logrus.Infoln("Ran in", util.ShowHumanizeTime(start))
 	}()
 
 	t.Cleanup(func() {
@@ -240,8 +240,7 @@ func (b *RunBuilder) Run(t *testing.T) error {
 	if err := cmd.Run(); err != nil {
 		return fmt.Errorf("skaffold %q: %w", b.command, err)
 	}
-
-	logrus.Infoln("Ran in", time.Since(start))
+	logrus.Infoln("Ran in", util.ShowHumanizeTime(start))
 	return nil
 }
 
@@ -258,8 +257,7 @@ func (b *RunBuilder) RunWithCombinedOutput(t *testing.T) ([]byte, error) {
 	if err != nil {
 		return out, fmt.Errorf("skaffold %q: %w", b.command, err)
 	}
-
-	logrus.Infoln("Ran in", time.Since(start))
+	logrus.Infoln("Ran in", util.ShowHumanizeTime(start))
 	return out, nil
 }
 
@@ -281,8 +279,7 @@ func (b *RunBuilder) RunOrFailOutput(t *testing.T) []byte {
 		}
 		t.Fatalf("skaffold %s: %v, %s", b.command, err, out)
 	}
-
-	logrus.Infoln("Ran in", time.Since(start))
+	logrus.Infoln("Ran in", util.ShowHumanizeTime(start))
 	return out
 }
 

pkg/skaffold/build/cache/retrieve.go

@@ -30,6 +30,7 @@ import (
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/docker"
 	sErrors "github.com/GoogleContainerTools/skaffold/pkg/skaffold/errors"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/schema/latest"
+	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/util"
 )
 
 func (c *cache) Build(ctx context.Context, out io.Writer, tags tag.ImageTags, artifacts []*latest.Artifact, buildAndTest BuildAndTestFn) ([]build.Artifact, error) {
@@ -119,7 +120,7 @@ func (c *cache) Build(ctx context.Context, out io.Writer, tags tag.ImageTags, ar
 		})
 	}
 
-	logrus.Infoln("Cache check complete in", time.Since(start))
+	logrus.Infoln("Cache check completed in", util.ShowHumanizeTime(start))
 
 	bRes, err := buildAndTest(ctx, out, tags, needToBuild)
 	if err != nil {

pkg/skaffold/diagnose/diagnose.go

@@ -29,6 +29,7 @@ import (
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/filemon"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/schema/latest"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/sync"
+	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/util"
 )
 
 type Config interface {
@@ -112,26 +113,25 @@ func typeOfArtifact(a *latest.Artifact) string {
 	}
 }
 
-func timeToListDependencies(ctx context.Context, a *latest.Artifact, cfg docker.Config) (time.Duration, []string, error) {
+func timeToListDependencies(ctx context.Context, a *latest.Artifact, cfg docker.Config) (string, []string, error) {
 	start := time.Now()
 	paths, err := build.DependenciesForArtifact(ctx, a, cfg, nil)
-	return time.Since(start), paths, err
+	return util.ShowHumanizeTime(start), paths, err
 }
 
-func timeToConstructSyncMap(a *latest.Artifact, cfg docker.Config) (time.Duration, error) {
+func timeToConstructSyncMap(a *latest.Artifact, cfg docker.Config) (string, error) {
 	start := time.Now()
 	_, err := sync.SyncMap(a, cfg)
-	return time.Since(start), err
+	return util.ShowHumanizeTime(start), err
 }
 
-func timeToComputeMTimes(deps []string) (time.Duration, error) {
+func timeToComputeMTimes(deps []string) (string, error) {
 	start := time.Now()
 
 	if _, err := filemon.Stat(func() ([]string, error) { return deps, nil }); err != nil {
-		return 0, fmt.Errorf("computing modTimes: %w", err)
+		return "nil", fmt.Errorf("computing modTimes: %w", err)
 	}
-
-	return time.Since(start), nil
+	return util.ShowHumanizeTime(start), nil
 }
 
 func sizeOfDockerContext(ctx context.Context, a *latest.Artifact, cfg docker.Config) (int64, error) {

pkg/skaffold/runner/build_deploy.go

@@ -30,6 +30,7 @@ import (
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/color"
 	deployutil "github.com/GoogleContainerTools/skaffold/pkg/skaffold/deploy/util"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/schema/latest"
+	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/util"
 )
 
 // Build builds a list of artifacts.
@@ -212,7 +213,7 @@ func (r *SkaffoldRunner) imageTags(ctx context.Context, out io.Writer, artifacts
 		color.Yellow.Fprintln(out, "Some taggers failed. Rerun with -vdebug for errors.")
 	}
 
-	logrus.Infoln("Tags generated in", time.Since(start))
+	logrus.Infoln("Tags generated in", util.ShowHumanizeTime(start))
 	return imageTags, nil
 }
 

pkg/skaffold/runner/deploy.go

@@ -32,6 +32,7 @@ import (
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/event"
 	kubernetesclient "github.com/GoogleContainerTools/skaffold/pkg/skaffold/kubernetes/client"
 	kubectx "github.com/GoogleContainerTools/skaffold/pkg/skaffold/kubernetes/context"
+	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/util"
 )
 
 func (r *SkaffoldRunner) Deploy(ctx context.Context, out io.Writer, artifacts []build.Artifact) error {
@@ -167,6 +168,6 @@ func (r *SkaffoldRunner) performStatusCheck(ctx context.Context, out io.Writer)
 		return err
 	}
 
-	color.Default.Fprintln(out, "Deployments stabilized in", time.Since(start))
+	color.Default.Fprintln(out, "Deployments stabilized in", util.ShowHumanizeTime(start))
 	return nil
 }

pkg/skaffold/runner/dev.go

@@ -35,6 +35,7 @@ import (
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/kubernetes/portforward"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/schema/latest"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/sync"
+	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/util"
 	"github.com/GoogleContainerTools/skaffold/proto"
 )
 
@@ -205,7 +206,7 @@ func (r *SkaffoldRunner) Dev(ctx context.Context, out io.Writer, artifacts []*la
 		return fmt.Errorf("watching skaffold configuration %q: %w", r.runCtx.ConfigurationFile(), err)
 	}
 
-	logrus.Infoln("List generated in", time.Since(start))
+	logrus.Infoln("List generated in", util.ShowHumanizeTime(start))
 
 	// Init Sync State
 	if err := sync.Init(ctx, artifacts); err != nil {

pkg/skaffold/runner/load_images.go

@@ -86,7 +86,7 @@ func (r *SkaffoldRunner) loadImages(ctx context.Context, out io.Writer, artifact
 		color.Green.Fprintln(out, "Loaded")
 	}
 
-	color.Default.Fprintln(out, "Images loaded in", time.Since(start))
+	color.Default.Fprintln(out, "Images loaded in", util.ShowHumanizeTime(start))
 	return nil
 }
 

pkg/skaffold/runner/timings.go

@@ -29,6 +29,7 @@ import (
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/deploy"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/schema/latest"
 	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/test"
+	"github.com/GoogleContainerTools/skaffold/pkg/skaffold/util"
 )
 
 // WithTimings creates a deployer that logs the duration of each phase.
@@ -60,8 +61,7 @@ func (w withTimings) Build(ctx context.Context, out io.Writer, tags tag.ImageTag
 	if err != nil {
 		return nil, err
 	}
-
-	logrus.Infoln("Build complete in", time.Since(start))
+	logrus.Infoln("Build completed in", util.ShowHumanizeTime(start))
 	return bRes, nil
 }
 
@@ -72,8 +72,7 @@ func (w withTimings) Test(ctx context.Context, out io.Writer, builds []build.Art
 	if err != nil {
 		return err
 	}
-
-	logrus.Infoln("Test complete in", time.Since(start))
+	logrus.Infoln("Test completed in", util.ShowHumanizeTime(start))
 	return nil
 }
 
@@ -85,8 +84,7 @@ func (w withTimings) Deploy(ctx context.Context, out io.Writer, builds []build.A
 	if err != nil {
 		return nil, err
 	}
-
-	logrus.Infoln("Deploy complete in", time.Since(start))
+	logrus.Infoln("Deploy completed in", util.ShowHumanizeTime(start))
 	return ns, err
 }
 
@@ -98,8 +96,7 @@ func (w withTimings) Cleanup(ctx context.Context, out io.Writer) error {
 	if err != nil {
 		return err
 	}
-
-	logrus.Infoln("Cleanup complete in", time.Since(start))
+	logrus.Infoln("Cleanup completed in", util.ShowHumanizeTime(start))
 	return nil
 }
 
@@ -111,7 +108,6 @@ func (w withTimings) Prune(ctx context.Context, out io.Writer) error {
 	if err != nil {
 		return err
 	}
-
-	logrus.Infoln("Image prune complete in", time.Since(start))
+	logrus.Infoln("Image prune completed in", util.ShowHumanizeTime(start))
 	return nil
 }

pkg/skaffold/runner/timings_test.go

@@ -94,7 +94,7 @@ func TestTimingsBuild(t *testing.T) {
 		{
 			description:  "build success",
 			shouldOutput: "",
-			shouldLog:    "Build complete in .+$",
+			shouldLog:    "Build completed in .+$",
 			shouldErr:    false,
 		},
 		{
@@ -130,7 +130,7 @@ func TestTimingsPrune(t *testing.T) {
 		{
 			description:  "test success",
 			shouldOutput: "(?m)^Pruning images...\n",
-			shouldLog:    "Image prune complete in .+$",
+			shouldLog:    "Image prune completed in .+$",
 			shouldErr:    false,
 		},
 		{
@@ -166,7 +166,7 @@ func TestTimingsTest(t *testing.T) {
 		{
 			description:  "test success",
 			shouldOutput: "",
-			shouldLog:    "Test complete in .+$",
+			shouldLog:    "Test completed in .+$",
 			shouldErr:    false,
 		},
 		{
@@ -202,7 +202,7 @@ func TestTimingsDeploy(t *testing.T) {
 		{
 			description:  "prune success",
 			shouldOutput: "(?m)^Starting deploy...\n",
-			shouldLog:    "Deploy complete in .+$",
+			shouldLog:    "Deploy completed in .+$",
 			shouldErr:    false,
 		},
 		{
@@ -238,7 +238,7 @@ func TestTimingsCleanup(t *testing.T) {
 		{
 			description:  "cleanup success",
 			shouldOutput: "(?m)^Cleaning up...\n",
-			shouldLog:    "Cleanup complete in .+$",
+			shouldLog:    "Cleanup completed in .+$",
 			shouldErr:    false,
 		},
 		{

pkg/skaffold/util/util.go

@@ -27,6 +27,7 @@ import (
 	"regexp"
 	"sort"
 	"strings"
+	"time"
 
 	"github.com/sirupsen/logrus"
 
@@ -341,3 +342,28 @@ func IsSubPath(basepath string, targetpath string) bool {
 func hasHiddenPrefix(s string) bool {
 	return strings.HasPrefix(s, hiddenPrefix)
 }
+
+// ShowHumanizeTime returns time in human readable format
+func ShowHumanizeTime(start time.Time) string {
+	shortTime := time.Since(start).Truncate(time.Millisecond)
+	longTime := shortTime.String()
+	out := time.Time{}.Add(shortTime)
+
+	if time.Since(start).Seconds() < 1 {
+		return time.Since(start).String()
+	}
+
+	longTime = strings.ReplaceAll(longTime, "h", " hour ")
+	longTime = strings.ReplaceAll(longTime, "m", " minute ")
+	longTime = strings.ReplaceAll(longTime, "s", " second")
+	if out.Hour() > 1 {
+		longTime = strings.ReplaceAll(longTime, "hour", "hours")
+	}
+	if out.Minute() > 1 {
+		longTime = strings.ReplaceAll(longTime, "minute", "minutes")
+	}
+	if out.Second() > 1 {
+		longTime = strings.ReplaceAll(longTime, "second", "seconds")
+	}
+	return longTime
+}

pkg/skaffold/util/util_test.go

@@ -19,6 +19,7 @@ package util
 import (
 	"path/filepath"
 	"testing"
+	"time"
 
 	"github.com/mitchellh/go-homedir"
 
@@ -468,3 +469,44 @@ func TestIsURL(t *testing.T) {
 func stringPointer(s string) *string {
 	return &s
 }
+
+func TestShowHumanizeTime(t *testing.T) {
+	currTime := time.Now()
+	duration1, _ := time.ParseDuration("1h58m30.918273645s")
+	duration2, _ := time.ParseDuration("5.23494327s")
+	tests := []struct {
+		description  string
+		value        time.Time
+		expected     string
+		expectedUp   string
+		expectedDown string
+	}{
+		{
+			description:  "Case for 1h58m30.918273645s",
+			value:        currTime.Add(-duration1),
+			expected:     "1 hour 58 minutes 30.918 seconds",
+			expectedUp:   "1 hour 58 minutes 30.919 seconds",
+			expectedDown: "1 hour 58 minutes 30.917 seconds",
+		},
+		{
+			description:  "Case for 5.23494327s",
+			value:        currTime.Add(-duration2),
+			expected:     "5.235 seconds",
+			expectedUp:   "5.236 seconds",
+			expectedDown: "5.234 seconds",
+		},
+	}
+	for _, test := range tests {
+		testutil.Run(t, test.description, func(t *testutil.T) {
+			humanizedValue := ShowHumanizeTime(test.value)
+			switch humanizedValue {
+			case test.expectedUp:
+				t.CheckDeepEqual(test.expectedUp, humanizedValue)
+			case test.expectedDown:
+				t.CheckDeepEqual(test.expectedDown, humanizedValue)
+			default:
+				t.CheckDeepEqual(test.expected, humanizedValue)
+			}
+		})
+	}
+}