Skip to content

En/1672 disable health check log #1686

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 6 commits into
base: development
Choose a base branch
from
Open
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
36 changes: 36 additions & 0 deletions pkg/gofr/gofr_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -1162,3 +1162,39 @@
assert.False(t, ok)
})
}

func Test_NewDisableHealthCheckLog(t *testing.T) {
port := testutil.GetFreePort(t)

t.Setenv("HTTP_PORT", strconv.Itoa(port))
t.Setenv("LOG_DISABLE_PROBES", "true")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You should use the constant you define in the other file


log := testutil.StdoutOutputForFunc(func() {
logger := logging.NewLogger(logging.DEBUG)

app := New()
app.container.Logger = logger

app.GET("/test", func(*Context) (any, error) {
return "success", nil
})

go app.Run()
time.Sleep(1000 * time.Millisecond)

var netClient = &http.Client{
Timeout: 200 * time.Millisecond,
}

req, _ := http.NewRequestWithContext(t.Context(), http.MethodGet,
fmt.Sprintf("http://localhost:%d", port)+"/.well-known/alive", http.NoBody)

_, err := netClient.Do(req)

Check failure on line 1192 in pkg/gofr/gofr_test.go

View workflow job for this annotation

GitHub Actions / Code Quality🎖️

response body must be closed (bodyclose)
if err != nil {
t.Errorf("error while making HTTP request in Test_NewDisableHealthCheckLog. err : %v", err)
return
}
})

assert.NotContains(t, log, `"uri":"/.well-known/alive"`, "Test_NewDisableHealthCheckLog")
}
6 changes: 6 additions & 0 deletions pkg/gofr/http/middleware/config.go
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,8 @@ import (
"gofr.dev/pkg/gofr/config"
)

const LogDisableProbeKey = "LOG_DISABLE_PROBES"
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The constant should have a clear comment about its purpose

Or simpl prefix it with EnvVar

Suggested change
const LogDisableProbeKey = "LOG_DISABLE_PROBES"
const EnvVarLogDisableProbeKey = "LOG_DISABLE_PROBES"

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Does this one need to be exported ?

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If followed this suggestion, then yes

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I would have used

Suggested change
const LogDisableProbeKey = "LOG_DISABLE_PROBES"
const LogDisableProbeKey = "LOG_PROBES_DISABLED"

Or something like that. Maybe there are other env variables about disabling something


func GetConfigs(c config.Config) map[string]string {
middlewareConfigs := make(map[string]string)

Expand All @@ -26,6 +28,10 @@ func GetConfigs(c config.Config) map[string]string {
}
}

if val := strings.TrimSpace(c.Get(LogDisableProbeKey)); val != "" {
middlewareConfigs[LogDisableProbeKey] = val
}

return middlewareConfigs
}

Expand Down
56 changes: 41 additions & 15 deletions pkg/gofr/http/middleware/config_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -9,21 +9,47 @@ import (
)

func TestGetConfigs(t *testing.T) {
mockConfig := config.NewMockConfig(map[string]string{
"ACCESS_CONTROL_ALLOW_ORIGIN": "*",
"ACCESS_CONTROL_ALLOW_HEADERS": "Authorization, Content-Type",
"ACCESS_CONTROL_ALLOW_CREDENTIALS": "true",
"ACCESS_CONTROL_ALLOW_CUSTOMHEADER": "abc",
})

middlewareConfigs := GetConfigs(mockConfig)

expectedConfigs := map[string]string{
"Access-Control-Allow-Origin": "*",
"Access-Control-Allow-Headers": "Authorization, Content-Type",
"Access-Control-Allow-Credentials": "true",
// Without LOG_DISABLE_PROBES configs provided
{
mockConfig := config.NewMockConfig(map[string]string{
"ACCESS_CONTROL_ALLOW_ORIGIN": "*",
"ACCESS_CONTROL_ALLOW_HEADERS": "Authorization, Content-Type",
"ACCESS_CONTROL_ALLOW_CREDENTIALS": "true",
"ACCESS_CONTROL_ALLOW_CUSTOMHEADER": "abc",
})

middlewareConfigs := GetConfigs(mockConfig)

expectedConfigs := map[string]string{
"Access-Control-Allow-Origin": "*",
"Access-Control-Allow-Headers": "Authorization, Content-Type",
"Access-Control-Allow-Credentials": "true",
}

assert.Equal(t, expectedConfigs, middlewareConfigs, "TestGetConfigs Failed!")
assert.NotContains(t, middlewareConfigs, "Access-Control-Allow-CustomHeader", "TestGetConfigs Failed!")
}

assert.Equal(t, expectedConfigs, middlewareConfigs, "TestGetConfigs Failed!")
assert.NotContains(t, middlewareConfigs, "Access-Control-Allow-CustomHeader", "TestGetConfigs Failed!")
// With LOG_DISABLE_PROBES config provided
{
mockConfig := config.NewMockConfig(map[string]string{
"ACCESS_CONTROL_ALLOW_ORIGIN": "*",
"ACCESS_CONTROL_ALLOW_HEADERS": "Authorization, Content-Type",
"ACCESS_CONTROL_ALLOW_CREDENTIALS": "true",
"ACCESS_CONTROL_ALLOW_CUSTOMHEADER": "abc",
"LOG_DISABLE_PROBES": "true",
})

middlewareConfigs := GetConfigs(mockConfig)

expectedConfigs := map[string]string{
"Access-Control-Allow-Origin": "*",
"Access-Control-Allow-Headers": "Authorization, Content-Type",
"Access-Control-Allow-Credentials": "true",
"LOG_DISABLE_PROBES": "true",
}

assert.Equal(t, expectedConfigs, middlewareConfigs, "TestGetConfigs Failed!")
assert.NotContains(t, middlewareConfigs, "Access-Control-Allow-CustomHeader", "TestGetConfigs Failed!")
}
}
74 changes: 53 additions & 21 deletions pkg/gofr/http/middleware/logger.go
Original file line number Diff line number Diff line change
Expand Up @@ -17,6 +17,11 @@

var errHijackNotSupported = errors.New("response writer does not support hijacking")

var skipURLsForLogging = map[string]struct{}{

Check failure on line 20 in pkg/gofr/http/middleware/logger.go

View workflow job for this annotation

GitHub Actions / Code Quality🎖️

skipURLsForLogging is a global variable (gochecknoglobals)
"/.well-known/health": {},
"/.well-known/alive": {},
}

// StatusResponseWriter Defines own Response Writer to be used for logging of status - as http.ResponseWriter does not let us read status.
type StatusResponseWriter struct {
http.ResponseWriter
Expand Down Expand Up @@ -100,27 +105,32 @@

srw.Header().Set("X-Correlation-ID", traceID)

defer func(res *StatusResponseWriter, req *http.Request) {
l := &RequestLog{
TraceID: traceID,
SpanID: spanID,
StartTime: start.Format("2006-01-02T15:04:05.999999999-07:00"),
ResponseTime: time.Since(start).Nanoseconds() / 1000,
Method: req.Method,
UserAgent: req.UserAgent(),
IP: getIPAddress(req),
URI: req.RequestURI,
Response: res.status,
}

if logger != nil {
if res.status >= http.StatusInternalServerError {
logger.Error(l)
} else {
logger.Log(l)
}
}
}(srw, r)
defer log(logger, srw, r, traceID, spanID, start)

defer func() {
panicRecovery(recover(), srw, logger)
}()

inner.ServeHTTP(srw, r)
})
}
}

// LoggingSkipHealthCheck is a middleware which logs response status and time in milliseconds along with other data.

Check failure on line 119 in pkg/gofr/http/middleware/logger.go

View workflow job for this annotation

GitHub Actions / Code Quality🎖️

Comment should end in a period (godot)
// It is same as the Logging but skips logging for health-check URLs
func LoggingSkipHealthCheck(logger logger) func(inner http.Handler) http.Handler {
return func(inner http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
start := time.Now()
srw := &StatusResponseWriter{ResponseWriter: w}
traceID := trace.SpanFromContext(r.Context()).SpanContext().TraceID().String()
spanID := trace.SpanFromContext(r.Context()).SpanContext().SpanID().String()

srw.Header().Set("X-Correlation-ID", traceID)

if _, ok := skipURLsForLogging[r.URL.Path]; !ok {
defer log(logger, srw, r, traceID, spanID, start)
}

defer func() {
panicRecovery(recover(), srw, logger)
Expand All @@ -131,6 +141,28 @@
}
}

func log(logger logger, res *StatusResponseWriter, req *http.Request, traceID, spanID string, start time.Time) {
l := &RequestLog{
TraceID: traceID,
SpanID: spanID,
StartTime: start.Format("2006-01-02T15:04:05.999999999-07:00"),
ResponseTime: time.Since(start).Nanoseconds() / 1000,
Method: req.Method,
UserAgent: req.UserAgent(),
IP: getIPAddress(req),
URI: req.RequestURI,
Response: res.status,
}

if logger != nil {
if res.status >= http.StatusInternalServerError {
logger.Error(l)
} else {
logger.Log(l)
}
}
}

func getIPAddress(r *http.Request) string {
ips := strings.Split(r.Header.Get("X-Forwarded-For"), ",")

Expand Down
42 changes: 42 additions & 0 deletions pkg/gofr/http/middleware/logger_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -72,6 +72,48 @@ func Test_LoggingMiddlewareError(t *testing.T) {
assert.Contains(t, logs, "GET 500")
}

func Test_LoggingSkipHealthCheck(t *testing.T) {
logs := testutil.StdoutOutputForFunc(func() {
req, _ := http.NewRequestWithContext(t.Context(), http.MethodGet, "http://dummy", http.NoBody)

rr := httptest.NewRecorder()

handler := LoggingSkipHealthCheck(logging.NewMockLogger(logging.DEBUG))(http.HandlerFunc(testHandler))

handler.ServeHTTP(rr, req)
})

assert.Contains(t, logs, "GET 200")
}

func Test_LoggingSkipHealthCheckError(t *testing.T) {
logs := testutil.StderrOutputForFunc(func() {
req, _ := http.NewRequestWithContext(t.Context(), http.MethodGet, "http://dummy", http.NoBody)

rr := httptest.NewRecorder()

handler := LoggingSkipHealthCheck(logging.NewMockLogger(logging.ERROR))(http.HandlerFunc(testHandlerError))

handler.ServeHTTP(rr, req)
})

assert.Contains(t, logs, "GET 500")
}

func Test_LoggingSkipHealthCheckAliveEndpoint(t *testing.T) {
logs := testutil.StdoutOutputForFunc(func() {
req, _ := http.NewRequestWithContext(t.Context(), http.MethodGet, "http://dummy/.well-known/alive", http.NoBody)

rr := httptest.NewRecorder()

handler := LoggingSkipHealthCheck(logging.NewMockLogger(logging.DEBUG))(http.HandlerFunc(testHandlerError))

handler.ServeHTTP(rr, req)
})

assert.Empty(t, logs)
}

// Test handler that uses the middleware.
func testHandler(w http.ResponseWriter, _ *http.Request) {
w.WriteHeader(http.StatusOK)
Expand Down
11 changes: 9 additions & 2 deletions pkg/gofr/http_server.go
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@ import (
"fmt"
"net/http"
"os"
"strconv"
"time"

"gofr.dev/pkg/gofr/container"
Expand Down Expand Up @@ -33,9 +34,15 @@ func newHTTPServer(c *container.Container, port int, middlewareConfigs map[strin
r := gofrHTTP.NewRouter()
wsManager := websocket.New()

r.Use(middleware.Tracer)

if ok, _ := strconv.ParseBool(middlewareConfigs[middleware.LogDisableProbeKey]); !ok {
r.Use(middleware.Logging(c.Logger))
} else {
r.Use(middleware.LoggingSkipHealthCheck(c.Logger))
}
Comment on lines +39 to +43
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This code looks strange to me

I mean, why having two middlewares?

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

True. Same middleware behaviour should be changed.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Okay, so changing how that logging middleware works now would mean we'd have to toss in a flag as an argument, and since that Logging function is out there for everyone, that'd be a big ol' breaking change. So, wouldn't it make more sense to just spin up a separate logging middleware and then just kinda decide whether to use it or not when we're setting up the server, based on that flag?

@ccoVeille @vikash


r.Use(
middleware.Tracer,
middleware.Logging(c.Logger),
middleware.CORS(middlewareConfigs, r.RegisteredRoutes),
middleware.Metrics(c.Metrics()),
)
Expand Down
Loading