Merge pull request #1134 from wakatime/feature/backoff-debug-message

Log backoff as debug

Author: gandarez

cmd/run.go

@@ -37,6 +37,7 @@ import (
 
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
+	"go.uber.org/zap/zapcore"
 	iniv1 "gopkg.in/ini.v1"
 	"gopkg.in/natefinch/lumberjack.v2"
 )
@@ -340,7 +341,9 @@ func runCmd(ctx context.Context, v *viper.Viper, verbose bool, sendDiagsOnErrors
 			verbose = verbose || errwaka.ShouldLogError()
 		}
 
-		if verbose {
+		if errloglevel, ok := err.(wakaerror.LogLevel); ok {
+			logger.Logf(zapcore.Level(errloglevel.LogLevel()), "failed to run command: %s", err)
+		} else if verbose {
 			logger.Errorf("failed to run command: %s", err)
 		}
 

cmd/run_test.go

@@ -13,6 +13,7 @@ import (
 	"time"
 
 	"github.com/wakatime/wakatime-cli/cmd"
+	"github.com/wakatime/wakatime-cli/pkg/api"
 	"github.com/wakatime/wakatime-cli/pkg/exitcode"
 	"github.com/wakatime/wakatime-cli/pkg/log"
 	"github.com/wakatime/wakatime-cli/pkg/offline"
@@ -77,6 +78,73 @@ func TestRunCmd_Err(t *testing.T) {
 	assert.Eventually(t, func() bool { return numCalls == 0 }, time.Second, 50*time.Millisecond)
 }
 
+func TestRunCmd_ErrBackoff(t *testing.T) {
+	testServerURL, router, tearDown := setupTestServer()
+	defer tearDown()
+
+	ctx := context.Background()
+
+	var numCalls int
+
+	router.HandleFunc("/plugins/errors", func(_ http.ResponseWriter, _ *http.Request) {
+		numCalls++
+	})
+
+	version.OS = "some os"
+	version.Arch = "some architecture"
+	version.Version = "some version"
+
+	tmpDir := t.TempDir()
+
+	offlineQueueFile, err := os.CreateTemp(tmpDir, "")
+	require.NoError(t, err)
+
+	defer offlineQueueFile.Close()
+
+	logFile, err := os.CreateTemp(tmpDir, "")
+	require.NoError(t, err)
+
+	defer logFile.Close()
+
+	v := viper.New()
+	v.Set("api-url", testServerURL)
+	v.Set("entity", "/path/to/file")
+	v.Set("key", "00000000-0000-4000-8000-000000000000")
+	v.Set("log-file", logFile.Name())
+	v.Set("offline-queue-file", offlineQueueFile.Name())
+	v.Set("plugin", "vim")
+
+	logger, err := cmd.SetupLogging(ctx, v)
+	require.NoError(t, err)
+
+	defer logger.Flush()
+
+	ctx = log.ToContext(ctx, logger)
+
+	var cmdNumCalls int
+
+	cmdFn := func(_ context.Context, _ *viper.Viper) (int, error) {
+		cmdNumCalls++
+		return 42, api.ErrBackoff{Err: errors.New("fail")}
+	}
+
+	err = cmd.RunCmd(ctx, v, false, false, cmdFn)
+	require.Error(t, err)
+
+	var errexitcode exitcode.Err
+
+	require.ErrorAs(t, err, &errexitcode)
+
+	assert.Equal(t, 42, err.(exitcode.Err).Code)
+	assert.Equal(t, 1, cmdNumCalls)
+	assert.Eventually(t, func() bool { return numCalls == 0 }, time.Second, 50*time.Millisecond)
+
+	output, err := io.ReadAll(logFile)
+	require.NoError(t, err)
+
+	assert.Empty(t, string(output))
+}
+
 func TestRunCmd_Verbose_Err(t *testing.T) {
 	testServerURL, router, tearDown := setupTestServer()
 	defer tearDown()
@@ -104,6 +172,7 @@ func TestRunCmd_Verbose_Err(t *testing.T) {
 	v.Set("key", "00000000-0000-4000-8000-000000000000")
 	v.Set("offline-queue-file", offlineQueueFile.Name())
 	v.Set("plugin", "vim")
+	v.Set("verbose", true)
 
 	var cmdNumCalls int
 
@@ -123,6 +192,73 @@ func TestRunCmd_Verbose_Err(t *testing.T) {
 	assert.Eventually(t, func() bool { return numCalls == 0 }, time.Second, 50*time.Millisecond)
 }
 
+func TestRunCmd_Verbose_ErrBackoff(t *testing.T) {
+	testServerURL, router, tearDown := setupTestServer()
+	defer tearDown()
+
+	ctx := context.Background()
+
+	var numCalls int
+
+	router.HandleFunc("/plugins/errors", func(_ http.ResponseWriter, _ *http.Request) {
+		numCalls++
+	})
+
+	version.OS = "some os"
+	version.Arch = "some architecture"
+	version.Version = "some version"
+
+	tmpDir := t.TempDir()
+
+	offlineQueueFile, err := os.CreateTemp(tmpDir, "")
+	require.NoError(t, err)
+
+	defer offlineQueueFile.Close()
+
+	logFile, err := os.CreateTemp(tmpDir, "")
+	require.NoError(t, err)
+
+	defer logFile.Close()
+
+	v := viper.New()
+	v.Set("api-url", testServerURL)
+	v.Set("entity", "/path/to/file")
+	v.Set("key", "00000000-0000-4000-8000-000000000000")
+	v.Set("offline-queue-file", offlineQueueFile.Name())
+	v.Set("plugin", "vim")
+	v.Set("log-file", logFile.Name())
+	v.Set("verbose", true)
+
+	logger, err := cmd.SetupLogging(ctx, v)
+	require.NoError(t, err)
+
+	defer logger.Flush()
+
+	ctx = log.ToContext(ctx, logger)
+
+	var cmdNumCalls int
+
+	cmdFn := func(_ context.Context, _ *viper.Viper) (int, error) {
+		cmdNumCalls++
+		return 42, api.ErrBackoff{Err: errors.New("fail")}
+	}
+
+	err = cmd.RunCmd(ctx, v, true, false, cmdFn)
+
+	var errexitcode exitcode.Err
+
+	require.ErrorAs(t, err, &errexitcode)
+
+	assert.Equal(t, 42, err.(exitcode.Err).Code)
+	assert.Equal(t, 1, cmdNumCalls)
+	assert.Eventually(t, func() bool { return numCalls == 0 }, time.Second, 50*time.Millisecond)
+
+	output, err := io.ReadAll(logFile)
+	require.NoError(t, err)
+
+	assert.Contains(t, string(output), "failed to run command: fail")
+}
+
 func TestRunCmd_SendDiagnostics_Err(t *testing.T) {
 	testServerURL, router, tearDown := setupTestServer()
 	defer tearDown()

pkg/api/error.go

@@ -5,6 +5,8 @@ import (
 
 	"github.com/wakatime/wakatime-cli/pkg/exitcode"
 	"github.com/wakatime/wakatime-cli/pkg/wakaerror"
+
+	"go.uber.org/zap/zapcore"
 )
 
 // Err represents a general api error.
@@ -120,6 +122,11 @@ func (ErrBackoff) ExitCode() int {
 	return exitcode.ErrBackoff
 }
 
+// LogLevel method to implement wakaerror.LogLevel interface.
+func (ErrBackoff) LogLevel() int8 {
+	return int8(zapcore.DebugLevel)
+}
+
 // Message method to implement wakaerror.Error interface.
 func (e ErrBackoff) Message() string {
 	return fmt.Sprintf("rate limited: %s", e.Err)

pkg/log/log.go

@@ -130,6 +130,16 @@ func SetJww(verbose bool, w io.Writer) {
 	}
 }
 
+// Log logs a message at the given level.
+func (l Logger) Log(level zapcore.Level, msg string) {
+	l.entry.Log(level, msg)
+}
+
+// Logf logs a message at the given level.
+func (l Logger) Logf(level zapcore.Level, format string, args ...any) {
+	l.entry.Log(level, fmt.Sprintf(format, args...))
+}
+
 // Debugf logs a message at level Debug.
 func (l *Logger) Debugf(format string, args ...any) {
 	l.entry.Log(zapcore.DebugLevel, fmt.Sprintf(format, args...))

pkg/wakaerror/wakaerror.go

@@ -1,14 +1,22 @@
 package wakaerror
 
-// Error is a custom error interface.
-type Error interface {
-	// ExitCode returns the exit code for the error.
-	ExitCode() int
-	// Message returns the error message.
-	Message() string
-	// SendDiagsOnErrors returns true when diagnostics should be sent on error.
-	SendDiagsOnErrors() bool
-	// ShouldLogError returns true when error should be logged.
-	ShouldLogError() bool
-	error
-}
+type (
+	// Error is a custom error interface.
+	Error interface {
+		// ExitCode returns the exit code for the error.
+		ExitCode() int
+		// Message returns the error message.
+		Message() string
+		// SendDiagsOnErrors returns true when diagnostics should be sent on error.
+		SendDiagsOnErrors() bool
+		// ShouldLogError returns true when error should be logged.
+		ShouldLogError() bool
+		error
+	}
+
+	// LogLevel is a custom log level interface to return log level for error.
+	LogLevel interface {
+		// LogLevel returns the log level for the error.
+		LogLevel() int8
+	}
+)