diff --git a/util/healthz/healthz.go b/util/healthz/healthz.go index 921facea97..1b677906e3 100644 --- a/util/healthz/healthz.go +++ b/util/healthz/healthz.go @@ -3,6 +3,7 @@ package healthz import ( "fmt" "net/http" + "time" log "github.com/sirupsen/logrus" ) @@ -11,9 +12,13 @@ import ( // ServeHealthCheck relies on the provided function to return an error if unhealthy and nil otherwise. func ServeHealthCheck(mux *http.ServeMux, f func(r *http.Request) error) { mux.HandleFunc("/healthz", func(w http.ResponseWriter, r *http.Request) { + startTs := time.Now() if err := f(r); err != nil { w.WriteHeader(http.StatusServiceUnavailable) - log.Errorln(w, err) + log.WithFields(log.Fields{ + "duration": time.Since(startTs), + "component": "healthcheck", + }).WithError(err).Error("Error serving health check request") } else { fmt.Fprintln(w, "ok") } diff --git a/util/healthz/healthz_test.go b/util/healthz/healthz_test.go index 93f68beb83..e3d30c9364 100644 --- a/util/healthz/healthz_test.go +++ b/util/healthz/healthz_test.go @@ -5,7 +5,11 @@ import ( "net" "net/http" "testing" + "time" + log "github.com/sirupsen/logrus" + "github.com/sirupsen/logrus/hooks/test" + "github.com/stretchr/testify/assert" "github.com/stretchr/testify/require" ) @@ -13,7 +17,7 @@ func TestHealthCheck(t *testing.T) { sentinel := false lc := &net.ListenConfig{} ctx := t.Context() - + svcErrMsg := "This is a dummy error" serve := func(c chan<- string) { // listen on first available dynamic (unprivileged) port listener, err := lc.Listen(ctx, "tcp", ":0") @@ -27,7 +31,7 @@ func TestHealthCheck(t *testing.T) { mux := http.NewServeMux() ServeHealthCheck(mux, func(_ *http.Request) error { if sentinel { - return errors.New("This is a dummy error") + return errors.New(svcErrMsg) } return nil }) @@ -52,10 +56,26 @@ func TestHealthCheck(t *testing.T) { require.Equalf(t, http.StatusOK, resp.StatusCode, "Was expecting status code 200 from health check, but got %d instead", resp.StatusCode) sentinel = true + hook := test.NewGlobal() req, err = http.NewRequestWithContext(ctx, http.MethodGet, server+"/healthz", http.NoBody) require.NoError(t, err) resp, err = http.DefaultClient.Do(req) require.NoError(t, err) require.Equalf(t, http.StatusServiceUnavailable, resp.StatusCode, "Was expecting status code 503 from health check, but got %d instead", resp.StatusCode) + assert.NotEmpty(t, hook.Entries, "Was expecting at least one log entry from health check, but got none") + expectedMsg := "Error serving health check request" + var foundEntry log.Entry + for _, entry := range hook.Entries { + if entry.Level == log.ErrorLevel && + entry.Message == expectedMsg { + foundEntry = entry + break + } + } + require.NotEmpty(t, foundEntry, "Expected an error message '%s', but it was't found", expectedMsg) + actualErr, ok := foundEntry.Data["error"].(error) + require.True(t, ok, "Expected 'error' field to contain an error, but it doesn't") + assert.Equal(t, svcErrMsg, actualErr.Error(), "expected original error message '"+svcErrMsg+"', but got '"+actualErr.Error()+"'") + assert.Greater(t, foundEntry.Data["duration"].(time.Duration), time.Duration(0)) }