address review comments

Author: janezpodhostnik

module/util/log.go

@@ -14,19 +14,19 @@ import (
 type LogProgressFunc[T int | uint | int32 | uint32 | uint64 | int64] func(addProgress T)
 
 type LogProgressConfig[T int | uint | int32 | uint32 | uint64 | int64] struct {
-	// Message is part of the messages that will be logged.
+	// message is part of the messages that will be logged.
 	// The full template is: `%s progress %d/%d (%.1f%%) total time %s`.
-	Message string
-	// Total is the total value of progress expected.
-	// When Total is added to LogProgressFunc the progress is considered to be 100%.
-	Total T
-	// NoDataLogDuration. If the last log line was more than this duration ago and a new data point is added, a new log line is logged.
-	// No line is logged if no data is received. The minimum resolution for NoDataLogDuration is 1 millisecond.
-	NoDataLogDuration time.Duration
-	// Ticks is the number of increments to log at. If Total is > 0 there will be at least 2 ticks. One at 0 and one at Total.
-	// If you want to log at every 10% set Ticks to 11 (one is at 0%).
-	// If the number of ticks is more than Total, it will be set to Total + 1.
-	Ticks uint64
+	message string
+	// total is the total value of progress expected.
+	// When total is added to LogProgressFunc the progress is considered to be 100%.
+	total T
+	// noDataLogDuration. If the last log line was more than this duration ago and a new data point is added, a new log line is logged.
+	// No line is logged if no data is received. The minimum resolution for noDataLogDuration is 1 millisecond.
+	noDataLogDuration time.Duration
+	// ticks is the number of increments to log at. If total is > 0 there will be at least 2 ticks. One at 0 and one at total.
+	// If you want to log at every 10% set ticks to 11 (one is at 0%).
+	// If the number of ticks is more than total, it will be set to total + 1.
+	ticks uint64
 }
 
 // DefaultLogProgressConfig returns a LogProgressConfig with default values.
@@ -36,15 +36,46 @@ func DefaultLogProgressConfig[T int | uint | int32 | uint32 | uint64 | int64](
 	message string,
 	total T,
 ) LogProgressConfig[T] {
+	return NewLogProgressConfig[T](
+		message,
+		total,
+		60*time.Second,
+		10,
+	)
+}
+
+// NewLogProgressConfig creates and returns a new LogProgressConfig with the specified message, total, duration, and ticks.
+// The duration is rounded to the nearest millisecond.
+// The number of ticks is the number of increments to log at. Logging at 0% is always done.
+// If you want to log at 10% increments, set ticks to 10.
+func NewLogProgressConfig[T int | uint | int32 | uint32 | uint64 | int64](
+	message string,
+	total T,
+	noDataLogDuration time.Duration,
+	ticks uint64,
+) LogProgressConfig[T] {
+	// sanitize total
+	if total < 0 {
+		total = 0
+	}
+
+	// add the tick at 0%
+	ticks = ticks + 1
+
+	// sanitize ticks
+	// number of ticks should be at most total + 1
+	if uint64(total+1) < ticks {
+		ticks = uint64(total + 1)
+	}
+
 	return LogProgressConfig[T]{
-		Message:           message,
-		Total:             total,
-		Ticks:             11,
-		NoDataLogDuration: 60 * time.Second,
+		message:           message,
+		total:             total,
+		noDataLogDuration: noDataLogDuration,
+		ticks:             ticks,
 	}
-}
 
-type LogProgressOption[T int | uint | int32 | uint32 | uint64 | int64] func(config *LogProgressConfig[T])
+}
 
 // LogProgress takes a LogProgressConfig and return function such that when called adds the given
 // number to the progress and logs the progress in defined increments or there is a time gap between progress
@@ -67,7 +98,7 @@ func LogProgress[T int | uint | int32 | uint32 | uint64 | int64](
 	// usage anyway.
 	var mux sync.Mutex
 
-	total := uint64(config.Total)
+	total := uint64(config.total)
 	logProgress := func(current uint64) {
 		mux.Lock()
 		defer mux.Unlock()
@@ -76,8 +107,8 @@ func LogProgress[T int | uint | int32 | uint32 | uint64 | int64](
 		elapsedString := elapsed.Round(1 * time.Second).String()
 
 		percentage := float64(100)
-		if config.Total > 0 {
-			percentage = (float64(current) / float64(config.Total)) * 100.
+		if config.total > 0 {
+			percentage = (float64(current) / float64(config.total)) * 100.
 		}
 
 		etaString := "unknown"
@@ -90,17 +121,17 @@ func LogProgress[T int | uint | int32 | uint32 | uint64 | int64](
 		}
 
 		if current < total {
-			log.Info().Msgf("%s progress %d/%d (%.1f%%) elapsed: %s, eta %s", config.Message, current, config.Total, percentage, elapsedString, etaString)
+			log.Info().Msgf("%s progress %d/%d (%.1f%%) elapsed: %s, eta %s", config.message, current, config.total, percentage, elapsedString, etaString)
 		} else {
-			log.Info().Msgf("%s progress %d/%d (%.1f%%) total time %s", config.Message, current, config.Total, percentage, elapsedString)
+			log.Info().Msgf("%s progress %d/%d (%.1f%%) total time %s", config.message, current, config.total, percentage, elapsedString)
 		}
 	}
 
 	// log 0% progress
 	logProgress(0)
 
 	// sanitize inputs and calculate increment
-	ticksIncludingZero := config.Ticks
+	ticksIncludingZero := config.ticks
 	if ticksIncludingZero < 2 {
 		ticksIncludingZero = 2
 	}
@@ -111,32 +142,47 @@ func LogProgress[T int | uint | int32 | uint32 | uint64 | int64](
 		increment = 1
 	}
 
-	// increment doesn't necessarily divide config.Total
+	// increment doesn't necessarily divide config.total
 	// Because we want 100% to mean 100% we need to deduct this overflow from the current value
 	// before checking if it is a multiple of the increment.
 	incrementsOverflow := total % increment
-	noLogDurationMillis := config.NoDataLogDuration.Milliseconds()
+	noLogDurationMillis := config.noDataLogDuration.Milliseconds()
 
 	return func(add T) {
+		if total == 0 {
+			return
+		}
 		if add < 0 {
 			return
 		}
 		diff := uint64(add)
 		now := time.Now().UnixMilli()
 
+		// it can technically happen that current > total. In this case we continue to log
+		// the progress using the calculated increments
 		current := currentIndex.Add(diff)
 		lastTime := lastDataTime.Swap(now)
 
 		// if the diff went over one or more increments, log the progress for each increment
-		fromTick := (current - diff - incrementsOverflow) / increment
-		toTick := (current - incrementsOverflow) / increment
+		fromTick := uint64(0)
+		if current-diff >= incrementsOverflow {
+			fromTick = (current - diff - incrementsOverflow) / increment
+		}
+		toTick := uint64(0)
+		if current >= incrementsOverflow {
+			toTick = (current - incrementsOverflow) / increment
+		}
 
 		if fromTick == toTick && now-lastTime > noLogDurationMillis {
 			// no data for a while, log whatever we are at now
 			logProgress(current)
 			return
 		}
 
+		if toTick <= fromTick {
+			return
+		}
+
 		for t := fromTick; t < toTick; t++ {
 			// (t+1) because we want to log the progress for the increment reached
 			// not the increment past

module/util/log_test.go

@@ -218,6 +218,98 @@ func TestLogProgress1000(t *testing.T) {
 	}
 }
 
+func TestLogProgressWhenTotalIs0(t *testing.T) {
+	t.Parallel()
+
+	buf := bytes.NewBufferString("")
+	lg := zerolog.New(buf)
+	logger := LogProgress(
+		lg,
+		DefaultLogProgressConfig(
+			"test",
+			0,
+		),
+	)
+
+	for i := 0; i < 10; i++ {
+		logger(1)
+	}
+
+	expectedLogs := []string{
+		fmt.Sprintf(`test progress %d/%d (100.0%%)`, 0, 0),
+	}
+
+	for _, log := range expectedLogs {
+		require.Contains(t, buf.String(), log, 0)
+	}
+
+	lines := strings.Count(buf.String(), "\n")
+	// log only once
+	require.Equal(t, 1, lines)
+}
+
+func TestLogProgressMoreTicksThenTotal(t *testing.T) {
+	t.Parallel()
+
+	buf := bytes.NewBufferString("")
+	lg := zerolog.New(buf)
+	logger := LogProgress(
+		lg,
+		DefaultLogProgressConfig(
+			"test",
+			5,
+		),
+	)
+
+	for i := 0; i < 5; i++ {
+		logger(1)
+	}
+
+	expectedLogs := []string{
+		fmt.Sprintf(`test progress %d/%d (100.0%%)`, 5, 5),
+	}
+
+	for _, log := range expectedLogs {
+		require.Contains(t, buf.String(), log, 0)
+	}
+
+	lines := strings.Count(buf.String(), "\n")
+	// log only once
+	require.Equal(t, 6, lines)
+}
+
+func TestLogProgressContinueLoggingAfter100(t *testing.T) {
+	t.Parallel()
+
+	buf := bytes.NewBufferString("")
+	lg := zerolog.New(buf)
+	logger := LogProgress(
+		lg,
+		DefaultLogProgressConfig(
+			"test",
+			100,
+		),
+	)
+
+	for i := 0; i < 15; i++ {
+		logger(10)
+	}
+
+	expectedLogs := []string{
+		fmt.Sprintf(`test progress %d/%d (100.0%%)`, 100, 100),
+		fmt.Sprintf(`test progress %d/%d (110.0%%)`, 110, 100),
+		fmt.Sprintf(`test progress %d/%d (150.0%%)`, 150, 100),
+	}
+
+	for _, log := range expectedLogs {
+		require.Contains(t, buf.String(), log, 0)
+	}
+
+	lines := strings.Count(buf.String(), "\n")
+	// log only once
+	require.Equal(t, 16, lines)
+}
+
 func TestLogProgressNoDataForAWhile(t *testing.T) {
 	t.Parallel()
 
@@ -227,12 +319,12 @@ func TestLogProgressNoDataForAWhile(t *testing.T) {
 	lg := zerolog.New(buf)
 	logger := LogProgress(
 		lg,
-		LogProgressConfig[uint64]{
-			Message:           "test",
-			Total:             uint64(total),
-			Ticks:             11,
-			NoDataLogDuration: 1 * time.Millisecond,
-		},
+		NewLogProgressConfig[uint64](
+			"test",
+			uint64(total),
+			1*time.Millisecond,
+			10,
+		),
 	)
 
 	for i := 0; i < total; i++ {