From ad9089d4d7ffa0cda836a45ef459126d32deab1c Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Carlos=20Henrique=20Guard=C3=A3o=20Gandarez?= Date: Mon, 25 Nov 2024 11:23:10 -0300 Subject: [PATCH] Log backoff as debug --- cmd/run.go | 5 +- cmd/run_test.go | 136 +++++++++++++++++++++++++++++++++++++ pkg/api/error.go | 7 ++ pkg/log/log.go | 10 +++ pkg/wakaerror/wakaerror.go | 32 +++++---- 5 files changed, 177 insertions(+), 13 deletions(-) diff --git a/cmd/run.go b/cmd/run.go index 12b68a52..da9e5bc7 100644 --- a/cmd/run.go +++ b/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) } diff --git a/cmd/run_test.go b/cmd/run_test.go index b5104b59..08064568 100644 --- a/cmd/run_test.go +++ b/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() diff --git a/pkg/api/error.go b/pkg/api/error.go index e308edb5..c8d87a60 100644 --- a/pkg/api/error.go +++ b/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) diff --git a/pkg/log/log.go b/pkg/log/log.go index 54720343..fe781222 100644 --- a/pkg/log/log.go +++ b/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...)) diff --git a/pkg/wakaerror/wakaerror.go b/pkg/wakaerror/wakaerror.go index 6211c08b..156f0683 100644 --- a/pkg/wakaerror/wakaerror.go +++ b/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 + } +)