Merge pull request #189 from rusq/cli-remake-logging

Refactor logging

channels.go

@@ -79,14 +79,14 @@ func (s *Session) getChannels(ctx context.Context, chanTypes []string, cb func(t
 		}
 		total += len(chans)
 
-		s.l().Printf("channels request #%5d, fetched: %4d, total: %8d (speed: %6.2f/sec, avg: %6.2f/sec)\n",
+		s.log.Printf("channels request #%5d, fetched: %4d, total: %8d (speed: %6.2f/sec, avg: %6.2f/sec)\n",
 			i, len(chans), total,
 			float64(len(chans))/float64(time.Since(reqStart).Seconds()),
 			float64(total)/float64(time.Since(fetchStart).Seconds()),
 		)
 
 		if nextcur == "" {
-			s.l().Printf("channels fetch complete, total: %d channels", total)
+			s.log.Printf("channels fetch complete, total: %d channels", total)
 			break
 		}
 

channels_test.go

@@ -10,6 +10,7 @@ import (
 	"github.com/slack-go/slack"
 	"github.com/stretchr/testify/assert"
 
+	"github.com/rusq/slackdump/v2/logger"
 	"github.com/rusq/slackdump/v2/types"
 )
 
@@ -80,6 +81,7 @@ func TestSession_getChannels(t *testing.T) {
 				client: mc,
 				Users:  tt.fields.Users,
 				cfg:    tt.fields.options,
+				log:    logger.Silent,
 			}
 
 			if tt.expectFn != nil {

cmd/slackdump/internal/cfg/cfg.go

@@ -11,6 +11,7 @@ import (
 
 	"github.com/rusq/slackdump/v2"
 	"github.com/rusq/slackdump/v2/auth/browser"
+	"github.com/rusq/slackdump/v2/logger"
 )
 
 var (
@@ -25,6 +26,8 @@ var (
 	SlackCookie string
 	Browser     browser.Browser
 	SlackConfig = slackdump.DefOptions
+
+	Log logger.Interface
 )
 
 type FlagMask int

cmd/slackdump/internal/dump/dump.go

@@ -100,9 +100,7 @@ func RunDump(ctx context.Context, cmd *base.Command, args []string) error {
 		return fmt.Errorf("file template error: %w", err)
 	}
 
-	cfg.SlackConfig.Logger = dlog.FromContext(ctx)
-
-	sess, err := slackdump.New(ctx, prov, cfg.SlackConfig)
+	sess, err := slackdump.New(ctx, prov, cfg.SlackConfig, slackdump.WithLogger(dlog.FromContext(ctx)))
 	if err != nil {
 		base.SetExitStatus(base.SApplicationError)
 		return err

cmd/slackdump/internal/v1/main.go

@@ -170,7 +170,7 @@ func run(ctx context.Context, p params) error {
 	ctx = dlog.NewContext(ctx, lg)
 
 	// - setting the logger for the application.
-	p.appCfg.SlackConfig.Logger = lg
+	p.appCfg.Log = lg
 
 	// - trace init
 	if traceStopFn, err := initTrace(lg, p.traceFile); err != nil {

cmd/slackdump/internal/workspace/list.go

@@ -93,7 +93,6 @@ func printAll(m manager, current string, wsps []string) {
 	fmt.Fprintln(tw,
 		"C\tname\tfilename\tmodified\tteam\tuser\terror\n"+
 			"-\t-------\t------------\t-------------------\t---------\t--------\t-----")
-	cfg.SlackConfig.Logger = logger.Silent
 	cfg.SlackConfig.UserCache.Disabled = true
 	for _, name := range wsps {
 		curr := ""
@@ -119,7 +118,7 @@ func userInfo(ctx context.Context, m manager, name string) (*slack.AuthTestRespo
 	if err != nil {
 		return nil, err
 	}
-	sess, err := slackdump.New(ctx, prov, cfg.SlackConfig)
+	sess, err := slackdump.New(ctx, prov, cfg.SlackConfig, slackdump.WithLogger(logger.Silent))
 	if err != nil {
 		return nil, err
 	}

cmd/slackdump/main.go

@@ -164,7 +164,7 @@ func invoke(cmd *base.Command, args []string) error {
 	} else {
 		lg.SetPrefix(cmd.Name() + ": ")
 		ctx = dlog.NewContext(ctx, lg)
-		cfg.SlackConfig.Logger = lg
+		cfg.Log = lg
 	}
 
 	if cmd.RequireAuth {

config.go

@@ -10,8 +10,6 @@ import (
 	ut "github.com/go-playground/universal-translator"
 	"github.com/go-playground/validator/v10"
 	translations "github.com/go-playground/validator/v10/translations/en"
-
-	"github.com/rusq/slackdump/v2/logger"
 )
 
 // Config is the option set for the Session.
@@ -24,7 +22,7 @@ type Config struct {
 	UserCache CacheConfig
 
 	BaseLocation string // base location for the dump files
-	Logger       logger.Interface
+	Logfile      string
 }
 
 // CacheConfig represents the options for the cache.
@@ -92,9 +90,9 @@ var DefOptions = Config{
 	},
 	DumpFiles:    false,
 	UserCache:    CacheConfig{Filename: "users.cache", MaxAge: 4 * time.Hour},
-	CacheDir:     "",             // default cache dir
-	Logger:       logger.Default, // default logger is the... default logger
-	BaseLocation: ".",            // default location is the current directory
+	CacheDir:     "",  // default cache dir
+	BaseLocation: ".", // default location is the current directory
+	Logfile:      "",  // empty, means STDERR
 }
 
 var (

export/expfmt_test.go

@@ -22,10 +22,10 @@ func Test_newFileExporter(t *testing.T) {
 		args  args
 		wantT string
 	}{
-		{"unknown is nodownload", args{t: ExportType(255), l: logger.Default, token: "abcd"}, "dl.Nothing"},
-		{"no", args{t: TNoDownload, l: logger.Default, token: "abcd"}, "dl.Nothing"},
-		{"standard", args{t: TStandard, fs: fsadapter.NewDirectory("."), cl: &slack.Client{}, l: logger.Default, token: "abcd"}, "*dl.Std"},
-		{"mattermost", args{t: TMattermost, fs: fsadapter.NewDirectory("."), cl: &slack.Client{}, l: logger.Default, token: "abcd"}, "*dl.Mattermost"},
+		{"unknown is nodownload", args{t: ExportType(255), l: logger.Silent, token: "abcd"}, "dl.Nothing"},
+		{"no", args{t: TNoDownload, l: logger.Silent, token: "abcd"}, "dl.Nothing"},
+		{"standard", args{t: TStandard, fs: fsadapter.NewDirectory("."), cl: &slack.Client{}, l: logger.Silent, token: "abcd"}, "*dl.Std"},
+		{"mattermost", args{t: TMattermost, fs: fsadapter.NewDirectory("."), cl: &slack.Client{}, l: logger.Silent, token: "abcd"}, "*dl.Mattermost"},
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {

fsadapter/zipfs_test.go

@@ -145,60 +145,64 @@ func TestNewZIP(t *testing.T) {
 }
 
 func TestCreateConcurrency(t *testing.T) {
-	// test for GH issue#90 - race condition in ZIP.Create
-	const (
-		numRoutines    = 16
-		testContentsSz = 1 * (1 << 20)
-	)
-
-	var buf bytes.Buffer
-	var wg sync.WaitGroup
-
-	zw := zip.NewWriter(&buf)
-	defer zw.Close()
-
-	fsa := NewZIP(zw)
-	defer fsa.Close()
-
-	// prepare workers
-	readySteadyGo := make(chan struct{})
-	panicAttacks := make(chan any, numRoutines)
-
-	for i := 0; i < numRoutines; i++ {
-		wg.Add(1)
-		go func(n int) {
-			defer func() {
-				if r := recover(); r != nil {
-					panicAttacks <- fmt.Sprintf("ZIP.Create race condition in gr %d: %v", n, r)
+	t.Parallel()
+	t.Run("issue#90", func(t *testing.T) {
+		t.Parallel()
+		// test for GH issue#90 - race condition in ZIP.Create
+		const (
+			numRoutines    = 16
+			testContentsSz = 1 * (1 << 20)
+		)
+
+		var buf bytes.Buffer
+		var wg sync.WaitGroup
+
+		zw := zip.NewWriter(&buf)
+		defer zw.Close()
+
+		fsa := NewZIP(zw)
+		defer fsa.Close()
+
+		// prepare workers
+		readySteadyGo := make(chan struct{})
+		panicAttacks := make(chan any, numRoutines)
+
+		for i := 0; i < numRoutines; i++ {
+			wg.Add(1)
+			go func(n int) {
+				defer func() {
+					if r := recover(); r != nil {
+						panicAttacks <- fmt.Sprintf("ZIP.Create race condition in gr %d: %v", n, r)
+					}
+				}()
+
+				defer wg.Done()
+				var contents bytes.Buffer
+				if _, err := io.CopyN(&contents, rand.Reader, testContentsSz); err != nil {
+					panic(err)
 				}
-			}()
 
-			defer wg.Done()
-			var contents bytes.Buffer
-			if _, err := io.CopyN(&contents, rand.Reader, testContentsSz); err != nil {
-				panic(err)
-			}
-
-			<-readySteadyGo
-			fw, err := fsa.Create(fmt.Sprintf("file%d", n))
-			if err != nil {
-				panic(err)
-			}
-			defer fw.Close()
+				<-readySteadyGo
+				fw, err := fsa.Create(fmt.Sprintf("file%d", n))
+				if err != nil {
+					panic(err)
+				}
+				defer fw.Close()
 
-			if _, err := io.Copy(fw, &contents); err != nil {
-				panic(err)
+				if _, err := io.Copy(fw, &contents); err != nil {
+					panic(err)
+				}
+			}(i)
+		}
+		close(readySteadyGo)
+		wg.Wait()
+		close(panicAttacks)
+		for r := range panicAttacks {
+			if r != nil {
+				t.Error(r)
 			}
-		}(i)
-	}
-	close(readySteadyGo)
-	wg.Wait()
-	close(panicAttacks)
-	for r := range panicAttacks {
-		if r != nil {
-			t.Error(r)
 		}
-	}
+	})
 }
 
 func TestZIP_normalizePath(t *testing.T) {

internal/app/config/config.go

@@ -43,6 +43,8 @@ type Params struct {
 	Emoji EmojiParams
 
 	SlackConfig slackdump.Config
+
+	Log logger.Interface
 }
 
 type EmojiParams struct {
@@ -160,8 +162,8 @@ func (in Input) Producer(fn func(string) error) error {
 }
 
 func (p *Params) Logger() logger.Interface {
-	if p.SlackConfig.Logger == nil {
+	if p.Log == nil {
 		return logger.Default
 	}
-	return p.SlackConfig.Logger
+	return p.Log
 }

internal/network/network.go

@@ -83,10 +83,13 @@ func WithRetry(ctx context.Context, l *rate.Limiter, maxAttempts int, fn func()
 }
 
 // waitTime returns the amount of time to wait before retrying depending on
-// the current attempt. The wait time is calculated as (x+2)^3 seconds, where
-// x is the current attempt number. The maximum wait time is capped at 5
+// the current attempt.  This variable exists to reduce the test time.
+var waitTime = cubicWait
+
+// cubicWait is the wait time function.  Time is calculated as (x+2)^3 seconds,
+// where x is the current attempt number. The maximum wait time is capped at 5
 // minutes.
-func waitTime(attempt int) time.Duration {
+func cubicWait(attempt int) time.Duration {
 	x := attempt + 2 // this is to ensure that we sleep at least 8 seconds.
 	delay := time.Duration(x*x*x) * time.Second
 	if delay > MaxAllowedWaitTime {

internal/network/network_test.go

@@ -148,14 +148,16 @@ func Test_withRetry(t *testing.T) {
 }
 
 func Test500ErrorHandling(t *testing.T) {
-	t.Parallel()
+	waitTime = func(attempt int) time.Duration { return 50 * time.Millisecond }
+	defer func() {
+		waitTime = cubicWait
+	}()
 
 	var codes = []int{500, 502, 503, 504, 598}
 	for _, code := range codes {
 		var thisCode = code
 		// This test is to ensure that we handle 500 errors correctly.
 		t.Run(fmt.Sprintf("%d error", code), func(t *testing.T) {
-			t.Parallel()
 
 			const (
 				testRetryCount = 1
@@ -227,7 +229,7 @@ func Test500ErrorHandling(t *testing.T) {
 	})
 }
 
-func Test_waitTime(t *testing.T) {
+func Test_cubicWait(t *testing.T) {
 	type args struct {
 		attempt int
 	}
@@ -245,7 +247,7 @@ func Test_waitTime(t *testing.T) {
 	}
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
-			if got := waitTime(tt.args.attempt); !reflect.DeepEqual(got, tt.want) {
+			if got := cubicWait(tt.args.attempt); !reflect.DeepEqual(got, tt.want) {
 				t.Errorf("waitTime() = %v, want %v", got, tt.want)
 			}
 		})

logger/logger.go

@@ -1,13 +1,13 @@
 package logger
 
 import (
-	"io"
 	"log"
 	"os"
 
 	"github.com/rusq/dlog"
 )
 
+// Interface is the interface for a logger.
 type Interface interface {
 	Debug(...any)
 	Debugf(fmt string, a ...any)
@@ -16,8 +16,20 @@ type Interface interface {
 	Println(...any)
 }
 
+// Default is the default logger.  It logs to stderr and debug logging can be
+// enabled by setting the DEBUG environment variable to 1.  For example:
+//
+//	DEBUG=1 slackdump
 var Default = dlog.New(log.Default().Writer(), "", log.LstdFlags, os.Getenv("DEBUG") == "1")
 
-// note: previously ioutil.Discard which is not deprecated in favord of io.Discard
-// so this is valid only from go1.16
-var Silent = dlog.New(io.Discard, "", log.LstdFlags, false)
+// Silent is a logger that does not log anything.
+var Silent = silent{}
+
+// Silent is a logger that does not log anything.
+type silent struct{}
+
+func (s silent) Debug(...any)                {}
+func (s silent) Debugf(fmt string, a ...any) {}
+func (s silent) Print(...any)                {}
+func (s silent) Printf(fmt string, a ...any) {}
+func (s silent) Println(...any)              {}

logger/logger_test.go

@@ -0,0 +1,16 @@
+package logger
+
+import "testing"
+
+func BenchmarkSlientPrintf(b *testing.B) {
+	var l = Silent
+	for i := 0; i < b.N; i++ {
+		l.Printf("hello world, %s, %d", "foo", i)
+	}
+	// This benchmark compares the performance of the Silent logger when
+	// using io.Discard, and when using a no-op function.
+	// io.Discard: BenchmarkSlientPrintf-16    	93075956	        12.92 ns/op	       8 B/op	       0 allocs/op
+	// no-op func: BenchmarkSlientPrintf-16    	1000000000	         0.2364 ns/op	       0 B/op	       0 allocs/op
+	//
+	// Oh, look! We have an WINNER.  The no-op function wins, no surprises.
+}