From 9288b6981761a1c93788dbf92768c4a7cdd9a16f Mon Sep 17 00:00:00 2001 From: Alan Hamlett Date: Sun, 7 May 2023 19:59:29 +0200 Subject: [PATCH] Only log rate limited backoff message when debug mode enabled --- cmd/heartbeat/heartbeat.go | 4 +- cmd/heartbeat/heartbeat_test.go | 130 ++++++++++++++++++++++++++++++++ cmd/run.go | 16 ++-- 3 files changed, 143 insertions(+), 7 deletions(-) diff --git a/cmd/heartbeat/heartbeat.go b/cmd/heartbeat/heartbeat.go index c2d75fd0..5e450c21 100644 --- a/cmd/heartbeat/heartbeat.go +++ b/cmd/heartbeat/heartbeat.go @@ -45,11 +45,11 @@ func Run(v *viper.Viper) (int, error) { log.Errorf("failed to save heartbeats to offline queue: %s", err) } - return errauth.ExitCode(), fmt.Errorf("sending heartbeat(s) failed: %s", errauth.Message()) + return errauth.ExitCode(), fmt.Errorf("sending heartbeat(s) failed: %w", errauth) } if errwaka, ok := err.(wakaerror.Error); ok { - return errwaka.ExitCode(), fmt.Errorf("sending heartbeat(s) failed: %s", errwaka.Message()) + return errwaka.ExitCode(), fmt.Errorf("sending heartbeat(s) failed: %w", errwaka) } return exitcode.ErrGeneric, fmt.Errorf( diff --git a/cmd/heartbeat/heartbeat_test.go b/cmd/heartbeat/heartbeat_test.go index d51f392f..7dd27e11 100644 --- a/cmd/heartbeat/heartbeat_test.go +++ b/cmd/heartbeat/heartbeat_test.go @@ -17,6 +17,7 @@ import ( cmdheartbeat "github.com/wakatime/wakatime-cli/cmd/heartbeat" "github.com/wakatime/wakatime-cli/pkg/api" "github.com/wakatime/wakatime-cli/pkg/heartbeat" + "github.com/wakatime/wakatime-cli/pkg/ini" "github.com/wakatime/wakatime-cli/pkg/log" "github.com/wakatime/wakatime-cli/pkg/offline" "github.com/wakatime/wakatime-cli/pkg/project" @@ -751,6 +752,135 @@ func TestSendHeartbeats_ErrAuth_UnsetAPIKey(t *testing.T) { assert.Eventually(t, func() bool { return numCalls == 0 }, time.Second, 50*time.Millisecond) } +func TestSendHeartbeats_ErrBackoff(t *testing.T) { + _, router, tearDown := setupTestServer() + defer tearDown() + + var numCalls int + + router.HandleFunc("/users/current/heartbeats.bulk", func(w http.ResponseWriter, req *http.Request) { + numCalls++ + + // send response + w.WriteHeader(http.StatusInternalServerError) + }) + + tmpDir := t.TempDir() + + logFile, err := os.CreateTemp(tmpDir, "") + require.NoError(t, err) + + defer logFile.Close() + + v := viper.New() + + v.Set("internal.backoff_at", time.Now().Add(10*time.Minute).Format(ini.DateFormat)) + v.Set("internal.backoff_retries", "1") + v.SetDefault("sync-offline-activity", 1000) + v.Set("api-url", "https://example.org") + v.Set("entity", "testdata/main.go") + v.Set("entity-type", "file") + v.Set("key", "00000000-0000-4000-8000-000000000000") + v.Set("log-file", logFile.Name()) + + cmd.SetupLogging(v) + + defer func() { + if file, ok := log.Output().(*os.File); ok { + _ = file.Sync() + file.Close() + } else if handler, ok := log.Output().(io.Closer); ok { + handler.Close() + } + }() + + offlineQueueFile, err := os.CreateTemp(t.TempDir(), "") + require.NoError(t, err) + + defer offlineQueueFile.Close() + + err = cmdheartbeat.SendHeartbeats(v, offlineQueueFile.Name()) + require.Error(t, err) + assert.ErrorAs(t, err, &api.ErrBackoff{}) + + assert.Equal(t, 0, numCalls) + + offlineCount, err := offline.CountHeartbeats(offlineQueueFile.Name()) + require.NoError(t, err) + + assert.Equal(t, 1, offlineCount) + + output, err := io.ReadAll(logFile) + require.NoError(t, err) + + assert.Empty(t, string(output)) +} + +func TestSendHeartbeats_ErrBackoff_Verbose(t *testing.T) { + _, router, tearDown := setupTestServer() + defer tearDown() + + var numCalls int + + router.HandleFunc("/users/current/heartbeats.bulk", func(w http.ResponseWriter, req *http.Request) { + numCalls++ + + // send response + w.WriteHeader(http.StatusInternalServerError) + }) + + tmpDir := t.TempDir() + + logFile, err := os.CreateTemp(tmpDir, "") + require.NoError(t, err) + + defer logFile.Close() + + v := viper.New() + + v.Set("internal.backoff_at", time.Now().Add(10*time.Minute).Format(ini.DateFormat)) + v.Set("internal.backoff_retries", "1") + v.SetDefault("sync-offline-activity", 1000) + v.Set("api-url", "https://example.org") + v.Set("entity", "testdata/main.go") + v.Set("entity-type", "file") + v.Set("key", "00000000-0000-4000-8000-000000000000") + v.Set("log-file", logFile.Name()) + v.Set("verbose", true) + + cmd.SetupLogging(v) + + defer func() { + if file, ok := log.Output().(*os.File); ok { + _ = file.Sync() + file.Close() + } else if handler, ok := log.Output().(io.Closer); ok { + handler.Close() + } + }() + + offlineQueueFile, err := os.CreateTemp(t.TempDir(), "") + require.NoError(t, err) + + defer offlineQueueFile.Close() + + err = cmdheartbeat.SendHeartbeats(v, offlineQueueFile.Name()) + require.Error(t, err) + assert.ErrorAs(t, err, &api.ErrBackoff{}) + + assert.Equal(t, 0, numCalls) + + offlineCount, err := offline.CountHeartbeats(offlineQueueFile.Name()) + require.NoError(t, err) + + assert.Equal(t, 1, offlineCount) + + output, err := io.ReadAll(logFile) + require.NoError(t, err) + + assert.Contains(t, string(output), "will retry at") +} + func setupTestServer() (string, *http.ServeMux, func()) { router := http.NewServeMux() srv := httptest.NewServer(router) diff --git a/cmd/run.go b/cmd/run.go index 0862a193..11791114 100644 --- a/cmd/run.go +++ b/cmd/run.go @@ -297,7 +297,7 @@ func runCmd(v *viper.Viper, verbose bool, sendDiagsOnErrors bool, cmd cmdFn) int // run command exitCode, err := cmd(v) - if err != nil { + if err != nil && (verbose || canLogError(err)) { log.Errorf("failed to run command: %s", err) resetLogs() @@ -331,11 +331,13 @@ func saveHeartbeats(v *viper.Viper) { func sendDiagnostics(v *viper.Viper, d diagnostics) error { paramAPI, err := params.LoadAPIParams(v) if err != nil { - var errauth api.ErrAuth + // Prevent sending diags for api key errors. + if !errors.As(err, &api.ErrAuth{}) { + return fmt.Errorf("failed to load API parameters: %s", err) + } - // api.ErrAuth represents an error when parsing api key. - // In this context api key is not required to send diagnostics. - if !errors.As(err, &errauth) { + // Prevent sending diags for api connection errors. + if !errors.As(err, &api.ErrBackoff{}) { return fmt.Errorf("failed to load API parameters: %s", err) } } @@ -375,3 +377,7 @@ func captureLogs(dest io.Writer) func() { log.SetOutput(logOutput) } } + +func canLogError(err error) bool { + return !errors.As(err, &api.ErrBackoff{}) +}