Human friendly logs (#52)

* Fix typo in logs

Signed-off-by: Utku Ozdemir <[email protected]>

* Print fancy logs with emojis

Signed-off-by: Utku Ozdemir <[email protected]>

* Add command-line demo to README

Signed-off-by: Utku Ozdemir <[email protected]>

* docs: update demo and readme

Signed-off-by: Utku Ozdemir <[email protected]>

* Do not print progress bar when log format is not fancy

Signed-off-by: Utku Ozdemir <[email protected]>

* test: fix tests

Signed-off-by: Utku Ozdemir <[email protected]>

* test: fix tests

Signed-off-by: Utku Ozdemir <[email protected]>

* test: add tests for logger

Signed-off-by: Utku Ozdemir <[email protected]>

* test: use debug level json logging in an integration test

Signed-off-by: Utku Ozdemir <[email protected]>

* test: fix log test

Signed-off-by: Utku Ozdemir <[email protected]>

* test: add tests for progress parsing

Signed-off-by: Utku Ozdemir <[email protected]>

.github/workflows/build.yml

@@ -6,6 +6,7 @@ on:
       - master
     paths-ignore:
       - "**.md"
+      - "img/**"
       - "test/**"
       - ".gitignore"
       - "docker/**"
@@ -14,6 +15,7 @@ on:
       - master
     paths-ignore:
       - "**.md"
+      - "img/**"
       - "test/**"
       - ".gitignore"
       - "docker/**"

.github/workflows/debug-build.yml

@@ -6,6 +6,7 @@ on:
       - master
     paths-ignore:
       - "**.md"
+      - "img/**"
       - "test/**"
       - ".gitignore"
       - "docker/**"
@@ -14,6 +15,7 @@ on:
       - master
     paths-ignore:
       - "**.md"
+      - "img/**"
       - "test/**"
       - ".gitignore"
       - "docker/**"

README.md

@@ -45,7 +45,7 @@ Simply create the PVC with the same name and manifest in `ns-b` and use `pv-migr
 from one Kubernetes cluster to the other.  
 Both clusters have internet access and the source cluster supports `LoadBalancer` type services with public IPs.  
 Just use `pv-migrate` to clone the data **securely over the internet**.
-  
+
 ## Highlights
 
 - Supports in-namespace, in-cluster as well as cross-cluster migrations
@@ -56,6 +56,10 @@ Just use `pv-migrate` to clone the data **securely over the internet**.
 - Customizable strategy order
 - Supports arm32v7 (Raspberry Pi etc.) and arm64 architectures as well as amd64
 
+## Demo
+
+![pv-migrate demo GIF](img/demo.gif)
+
 ## Installation
 
 ### Using Homebrew (MacOS/Linux)

cmd/pv-migrate/main.go

@@ -28,9 +28,10 @@ func init() {
 }
 
 func main() {
-	cliApp := app.New(version, commit)
+	rootLogger := log.New()
+	cliApp := app.New(rootLogger, version, commit)
 	err := cliApp.Run(os.Args)
 	if err != nil {
-		log.Fatal(err.Error())
+		rootLogger.Fatalf(":cross_mark: Error: %s", err.Error())
 	}
 }

go.mod

@@ -4,6 +4,7 @@ go 1.16
 
 require (
 	github.com/hashicorp/go-multierror v1.1.1
+	github.com/kyokomi/emoji/v2 v2.2.8
 	github.com/schollz/progressbar/v3 v3.8.2
 	github.com/sirupsen/logrus v1.8.1
 	github.com/stretchr/testify v1.7.0

go.sum

@@ -218,6 +218,8 @@ github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
 github.com/kr/pty v1.1.5/go.mod h1:9r2w37qlBe7rQ6e1fg1S/9xpWHSnaqNdHD3WcMdbPDA=
 github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE=
 github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI=
+github.com/kyokomi/emoji/v2 v2.2.8 h1:jcofPxjHWEkJtkIbcLHvZhxKgCPl6C7MyjTrD4KDqUE=
+github.com/kyokomi/emoji/v2 v2.2.8/go.mod h1:JUcn42DTdsXJo1SWanHh4HKDEyPaR5CqkmoirZZP9qE=
 github.com/magiconair/properties v1.8.1/go.mod h1:PppfXfuXeibc/6YijjN8zIbojt8czPbwD3XqdrwzmxQ=
 github.com/mailru/easyjson v0.0.0-20190614124828-94de47d64c63/go.mod h1:C1wdFJiN94OJF2b5HbByQZoLdCWB1Yqtg26g4irojpc=
 github.com/mailru/easyjson v0.0.0-20190626092158-b2ccc519800e/go.mod h1:C1wdFJiN94OJF2b5HbByQZoLdCWB1Yqtg26g4irojpc=

internal/app/app.go

@@ -1,20 +1,27 @@
 package app
 
 import (
+	"context"
 	"fmt"
 	log "github.com/sirupsen/logrus"
 	"github.com/urfave/cli/v2"
 	"github.com/utkuozdemir/pv-migrate/engine"
+	applog "github.com/utkuozdemir/pv-migrate/internal/log"
 	"github.com/utkuozdemir/pv-migrate/internal/rsync"
 	"github.com/utkuozdemir/pv-migrate/internal/strategy"
 	"github.com/utkuozdemir/pv-migrate/migration"
+	"os"
 	"strings"
 )
 
+type cliAppContextKey string
+
 const (
 	authorName                    = "Utku Ozdemir"
 	authorEmail                   = "[email protected]"
 	CommandMigrate                = "migrate"
+	FlagLogLevel                  = "log-level"
+	FlagLogFormat                 = "log-format"
 	FlagSourceKubeconfig          = "source-kubeconfig"
 	FlagSourceContext             = "source-context"
 	FlagSourceNamespace           = "source-namespace"
@@ -31,9 +38,11 @@ const (
 	FlagRsyncImage                = "rsync-image"
 	FlagSshdImage                 = "sshd-image"
 	FlagSSHKeyAlgorithm           = "ssh-key-algorithm"
+
+	loggerContextKey cliAppContextKey = "logger"
 )
 
-func New(version string, commit string) *cli.App {
+func New(rootLogger *log.Logger, version string, commit string) *cli.App {
 	sshKeyAlgs := strings.Join(rsync.SSHKeyAlgorithms, ",")
 	return &cli.App{
 		Name:    "pv-migrate",
@@ -46,6 +55,8 @@ func New(version string, commit string) *cli.App {
 				Aliases:   []string{"m"},
 				ArgsUsage: "[SOURCE_PVC] [DESTINATION_PVC]",
 				Action: func(c *cli.Context) error {
+					logger := extractLogger(c.Context)
+
 					s := migration.PVC{
 						KubeconfigPath: c.String(FlagSourceKubeconfig),
 						Context:        c.String(FlagSourceContext),
@@ -78,10 +89,13 @@ func New(version string, commit string) *cli.App {
 						Strategies: strategies,
 						RsyncImage: c.String(FlagRsyncImage),
 						SshdImage:  c.String(FlagSshdImage),
+						Logger:     logger,
 					}
 
+					logger.Info(":rocket: Starting migration")
 					if opts.DeleteExtraneousFiles {
-						log.Info("Extraneous files will be deleted from the destination")
+						logger.Info(":white_exclamation_mark: " +
+							"Extraneous files will be deleted from the destination")
 					}
 
 					return engine.New().Run(&m)
@@ -194,11 +208,50 @@ func New(version string, commit string) *cli.App {
 				},
 			},
 		},
+		Flags: []cli.Flag{
+			cli.HelpFlag,
+			cli.VersionFlag,
+			&cli.StringFlag{
+				Name:    FlagLogLevel,
+				Aliases: []string{"l"},
+				Usage: fmt.Sprintf("Log level. Must be one of: %s",
+					strings.Join(applog.LogLevels, ", ")),
+				Value: "info",
+			},
+			&cli.StringFlag{
+				Name:    FlagLogFormat,
+				Aliases: []string{"f"},
+				Usage: fmt.Sprintf("Log format. Must be one of: %s",
+					strings.Join(applog.LogFormats, ", ")),
+				Value: applog.LogFormatFancy,
+			},
+		},
+		Before: func(c *cli.Context) error {
+			l := c.String(FlagLogLevel)
+			f := c.String(FlagLogFormat)
+			entry, err := applog.BuildLogger(rootLogger, l, f)
+			if err != nil {
+				return err
+			}
+
+			ctx := c.Context
+			c.Context = context.WithValue(ctx, loggerContextKey, entry)
+			return nil
+		},
 		Authors: []*cli.Author{
 			{
 				Name:  authorName,
 				Email: authorEmail,
 			},
 		},
+		CommandNotFound: func(c *cli.Context, s string) {
+			logger := extractLogger(c.Context)
+			logger.Errorf(":cross_mark: Error: no help topic for '%s'", s)
+			os.Exit(3)
+		},
 	}
 }
+
+func extractLogger(c context.Context) *log.Entry {
+	return c.Value(loggerContextKey).(*log.Entry)
+}

internal/integrationtest/app_test.go

@@ -2,6 +2,7 @@ package integrationtest
 
 import (
 	"fmt"
+	log "github.com/sirupsen/logrus"
 	"github.com/stretchr/testify/assert"
 	"github.com/utkuozdemir/pv-migrate/internal/app"
 	"io/ioutil"
@@ -58,9 +59,12 @@ func TestSameNS(t *testing.T) {
 	assert.NoError(t, err)
 	destNs := sourceNs
 
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 	args := []string{
-		os.Args[0], migrateCommand,
+		os.Args[0],
+		"--log-level", "debug",
+		"--log-format", "json",
+		migrateCommand,
 		sourceKubeconfigParamKey, ctx.kubeconfig,
 		sourceNsParamKey, sourceNs,
 		destKubeconfigParamKey, ctx.kubeconfig,
@@ -106,7 +110,7 @@ func TestNoChown(t *testing.T) {
 	assert.NoError(t, err)
 	destNs := sourceNs
 
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 	args := []string{
 		os.Args[0], migrateCommand,
 		sourceKubeconfigParamKey, ctx.kubeconfig,
@@ -155,7 +159,7 @@ func TestSameNSDeleteExtraneousFiles(t *testing.T) {
 	assert.NoError(t, err)
 	destNs := sourceNs
 
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 	args := []string{
 		os.Args[0], migrateCommand,
 		sourceKubeconfigParamKey, ctx.kubeconfig,
@@ -196,7 +200,7 @@ func TestMountedError(t *testing.T) {
 	dest, err := testNamespaceWithRandomBoundPVC(sourceNs)
 	assert.NoError(t, err)
 	destNs := sourceNs
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 	args := []string{
 		os.Args[0], migrateCommand,
 		sourceKubeconfigParamKey, ctx.kubeconfig,
@@ -226,7 +230,7 @@ func TestIgnoreMounted(t *testing.T) {
 	dest, err := testNamespaceWithRandomBoundPVC(sourceNs)
 	assert.NoError(t, err)
 	destNs := sourceNs
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 	args := []string{
 		os.Args[0], migrateCommand,
 		sourceKubeconfigParamKey, ctx.kubeconfig,
@@ -261,7 +265,7 @@ func TestDifferentNS(t *testing.T) {
 	assert.NoError(t, err)
 	destNs, dest, err := randomTestNamespaceWithRandomBoundPVC()
 	assert.NoError(t, err)
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 
 	args := []string{
 		os.Args[0], migrateCommand,
@@ -295,7 +299,7 @@ func TestDifferentNSRSA(t *testing.T) {
 	assert.NoError(t, err)
 	destNs, dest, err := randomTestNamespaceWithRandomBoundPVC()
 	assert.NoError(t, err)
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 
 	args := []string{
 		os.Args[0], migrateCommand,
@@ -338,7 +342,7 @@ func TestDifferentCluster(t *testing.T) {
 	_ = ioutil.WriteFile(kubeconfigCopy, kubeconfigBytes, 0600)
 	defer func() { _ = os.Remove(kubeconfigCopy) }()
 
-	cliApp := app.New("", "")
+	cliApp := app.New(log.New(), "", "")
 
 	args := []string{
 		os.Args[0], migrateCommand,

internal/k8s/job.go

@@ -38,7 +38,13 @@ func CreateJobWaitTillCompleted(logger *log.Entry, kubeClient kubernetes.Interfa
 	wg.Add(1)
 	defer wg.Wait()
 	successCh := make(chan bool, 1)
-	go tryRenderProgressBarFromRsyncLogs(&wg, kubeClient, pod, successCh, logger)
+
+	//logfmt := logger.Context.Value("log-format")
+	//if logfmt ==  {
+	//
+	//}
+
+	go tryLogProgressFromRsyncLogs(&wg, kubeClient, pod, successCh, logger)
 	p, err := waitUntilPodIsNotRunning(kubeClient, pod.Namespace, pod.Name)
 	if err != nil {
 		successCh <- false

internal/k8s/progress.go

@@ -3,8 +3,10 @@ package k8s
 import (
 	"context"
 	"fmt"
+	"github.com/kyokomi/emoji/v2"
 	"github.com/schollz/progressbar/v3"
 	log "github.com/sirupsen/logrus"
+	applog "github.com/utkuozdemir/pv-migrate/internal/log"
 	corev1 "k8s.io/api/core/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/client-go/kubernetes"
@@ -20,16 +22,58 @@ var (
 	rsyncEndRegex = regexp.MustCompile(`\s*total size is (?P<bytes>[0-9]+(,[0-9]+)*)`)
 )
 
-func tryRenderProgressBarFromRsyncLogs(wg *sync.WaitGroup, kubeClient kubernetes.Interface,
+func tryLogProgressFromRsyncLogs(wg *sync.WaitGroup, kubeClient kubernetes.Interface,
 	pod *corev1.Pod, successCh chan bool, logger *log.Entry) {
 	defer wg.Done()
-	err := renderProgressBarFromRsyncLogs(kubeClient, pod.Namespace, pod.Name, successCh)
+
+	var err error
+	logfmt := logger.Context.Value(applog.LogFormatContextKey)
+	switch logfmt {
+	case applog.LogFormatFancy:
+		err = drawProgressBarFromRsyncLogs(kubeClient, pod.Namespace, pod.Name, successCh)
+	default:
+		err = tailPodLogs(logger, kubeClient, pod.Namespace, pod.Name, successCh)
+	}
+
+	if err != nil {
+		logger.WithError(err).Warn(":warn: Cannot tail logs to display progress")
+	}
+}
+
+func tailPodLogs(logger *log.Entry, kubeClient kubernetes.Interface,
+	namespace string, pod string, successCh <-chan bool) error {
+	ticker := time.NewTicker(1 * time.Second)
+	var since metav1.Time
+	for {
+		select {
+		case success := <-successCh:
+			if success {
+				return logPodLogs(logger, kubeClient, &namespace, &pod, &since)
+			}
+			return nil
+		case <-ticker.C:
+			err := logPodLogs(logger, kubeClient, &namespace, &pod, &since)
+			if err != nil {
+				return err
+			}
+			since = metav1.Now()
+		}
+	}
+}
+
+func logPodLogs(logger *log.Entry, kubeClient kubernetes.Interface,
+	namespace *string, pod *string, since *metav1.Time) error {
+	logs, err := getLogs(kubeClient, namespace, pod, since)
 	if err != nil {
-		logger.WithError(err).Debug("Cannot tail logs to display progress")
+		return err
+	}
+	for _, l := range logs {
+		logger.Debug(l)
 	}
+	return nil
 }
 
-func renderProgressBarFromRsyncLogs(kubeClient kubernetes.Interface, namespace string,
+func drawProgressBarFromRsyncLogs(kubeClient kubernetes.Interface, namespace string,
 	pod string, successCh <-chan bool) error {
 	// probe logs to see if we can read them at all
 	_, err := getLogs(kubeClient, &namespace, &pod, nil)
@@ -44,7 +88,7 @@ func renderProgressBarFromRsyncLogs(kubeClient kubernetes.Interface, namespace s
 		progressbar.OptionSetRenderBlankState(true),
 		progressbar.OptionFullWidth(),
 		progressbar.OptionOnCompletion(func() { fmt.Println() }),
-		progressbar.OptionSetDescription("Copying data..."),
+		progressbar.OptionSetDescription(emoji.Sprint(":open_file_folder: Copying data...")),
 	)
 
 	ticker := time.NewTicker(1 * time.Second)