fix: invalid error message on health check failure (#26040) (#26039)

Signed-off-by: Eugene Doudine <eugene.doudine@octopus.com>

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")
 		}

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))
 }