diff --git a/api/api.go b/api/api.go index e111e824f..3753498a9 100644 --- a/api/api.go +++ b/api/api.go @@ -12,6 +12,7 @@ import ( "github.com/gorilla/handlers" "github.com/gorilla/mux" + "github.com/inconshreveable/log15" "github.com/vechain/thor/v2/api/accounts" "github.com/vechain/thor/v2/api/blocks" "github.com/vechain/thor/v2/api/debug" @@ -29,6 +30,8 @@ import ( "github.com/vechain/thor/v2/txpool" ) +var log = log15.New("pkg", "api") + // New return api router func New( repo *chain.Repository, @@ -43,6 +46,7 @@ func New( pprofOn bool, skipLogs bool, allowCustomTracer bool, + isReqLoggerEnabled bool, forkConfig thor.ForkConfig, ) (http.HandlerFunc, func()) { origins := strings.Split(strings.TrimSpace(allowedOrigins), ",") @@ -92,11 +96,15 @@ func New( } handler := handlers.CompressHandler(router) + if isReqLoggerEnabled { + handler = RequestLoggerHandler(handler, log) + } + handler = handlers.CORS( handlers.AllowedOrigins(origins), handlers.AllowedHeaders([]string{"content-type", "x-genesis-id"}), handlers.ExposedHeaders([]string{"x-genesis-id", "x-thorest-ver"}), )(handler) - return handler.ServeHTTP, - subs.Close // subscriptions handles hijacked conns, which need to be closed + + return handler.ServeHTTP, subs.Close // subscriptions handles hijacked conns, which need to be closed } diff --git a/api/request_logger.go b/api/request_logger.go new file mode 100644 index 000000000..022b65940 --- /dev/null +++ b/api/request_logger.go @@ -0,0 +1,47 @@ +// Copyright (c) 2024 The VeChainThor developers + +// Distributed under the GNU Lesser General Public License v3.0 software license, see the accompanying +// file LICENSE or + +package api + +import ( + "bytes" + "io" + "net/http" + "time" + + "github.com/inconshreveable/log15" +) + +// RequestLoggerHandler returns a http handler to ensure requests are syphoned into the writer +func RequestLoggerHandler(handler http.Handler, logger log15.Logger) http.Handler { + fn := func(w http.ResponseWriter, r *http.Request) { + // Read and log the body (note: this can only be done once) + // Ensure you don't disrupt the request body for handlers that need to read it + var bodyBytes []byte + var err error + if r.Body != nil { + bodyBytes, err = io.ReadAll(r.Body) + if err != nil { + logger.Warn("unexpected body read error", "err", err) + return // don't pass bad request to the next handler + } + r.Body = io.NopCloser(io.Reader(bytes.NewReader(bodyBytes))) + } + + logger.Info("API Request", + "timestamp", time.Now().Unix(), + "URI", r.URL.String(), + "Method", r.Method, + "Body", string(bodyBytes), + ) + + // call the original http.Handler we're wrapping + handler.ServeHTTP(w, r) + } + + // http.HandlerFunc wraps a function so that it + // implements http.Handler interface + return http.HandlerFunc(fn) +} diff --git a/api/request_logger_test.go b/api/request_logger_test.go new file mode 100644 index 000000000..8e1c502cc --- /dev/null +++ b/api/request_logger_test.go @@ -0,0 +1,95 @@ +// Copyright (c) 2024 The VeChainThor developers + +// Distributed under the GNU Lesser General Public License v3.0 software license, see the accompanying +// file LICENSE or +package api + +import ( + "net/http" + "net/http/httptest" + "strings" + "testing" + + "github.com/inconshreveable/log15" + "github.com/stretchr/testify/assert" +) + +// mockLogger is a simple logger implementation for testing purposes +type mockLogger struct { + loggedData []interface{} +} + +func (m *mockLogger) New(ctx ...interface{}) log15.Logger { return m } + +func (m *mockLogger) GetHandler() log15.Handler { return nil } + +func (m *mockLogger) SetHandler(h log15.Handler) {} + +func (m *mockLogger) Debug(msg string, ctx ...interface{}) {} + +func (m *mockLogger) Error(msg string, ctx ...interface{}) {} + +func (m *mockLogger) Crit(msg string, ctx ...interface{}) {} + +func (m *mockLogger) Info(msg string, ctx ...interface{}) { + m.loggedData = append(m.loggedData, ctx...) +} + +func (m *mockLogger) Warn(msg string, ctx ...interface{}) { + m.loggedData = append(m.loggedData, ctx...) +} + +func (m *mockLogger) GetLoggedData() []interface{} { + return m.loggedData +} + +func TestRequestLoggerHandler(t *testing.T) { + mockLog := &mockLogger{} + + // Define a test handler to wrap + testHandler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + w.Write([]byte("OK")) + }) + + // Create the RequestLoggerHandler + loggerHandler := RequestLoggerHandler(testHandler, mockLog) + + // Create a test HTTP request + reqBody := "test body" + req := httptest.NewRequest("POST", "http://example.com/foo", strings.NewReader(reqBody)) + req.Header.Set("Content-Type", "application/json") + + // Create a ResponseRecorder to record the response + rr := httptest.NewRecorder() + + // Serve the HTTP request + loggerHandler.ServeHTTP(rr, req) + + // Check the response status code + assert.Equal(t, http.StatusOK, rr.Code) + + // Check the response body + assert.Equal(t, "OK", rr.Body.String()) + + // Verify that the logger recorded the correct information + loggedData := mockLog.GetLoggedData() + assert.Contains(t, loggedData, "URI") + assert.Contains(t, loggedData, "http://example.com/foo") + assert.Contains(t, loggedData, "Method") + assert.Contains(t, loggedData, "POST") + assert.Contains(t, loggedData, "Body") + assert.Contains(t, loggedData, reqBody) + + // Check if timestamp is present + foundTimestamp := false + for i := 0; i < len(loggedData); i += 2 { + if loggedData[i] == "timestamp" { + _, ok := loggedData[i+1].(int64) + assert.True(t, ok, "timestamp should be an int64") + foundTimestamp = true + break + } + } + assert.True(t, foundTimestamp, "timestamp should be logged") +} diff --git a/cmd/thor/flags.go b/cmd/thor/flags.go index 7b47380b0..f37d877fc 100644 --- a/cmd/thor/flags.go +++ b/cmd/thor/flags.go @@ -59,6 +59,10 @@ var ( Name: "api-allow-custom-tracer", Usage: "allow custom JS tracer to be used tracer API", } + apiLogsEnabledFlag = cli.BoolFlag{ + Name: "enable-api-logs", + Usage: "enables API requests logging", + } verbosityFlag = cli.IntFlag{ Name: "verbosity", Value: int(log15.LvlInfo), diff --git a/cmd/thor/main.go b/cmd/thor/main.go index 5e3c054db..e8a1b9cc6 100644 --- a/cmd/thor/main.go +++ b/cmd/thor/main.go @@ -78,6 +78,7 @@ func main() { apiCallGasLimitFlag, apiBacktraceLimitFlag, apiAllowCustomTracerFlag, + apiLogsEnabledFlag, verbosityFlag, maxPeersFlag, p2pPortFlag, @@ -104,6 +105,7 @@ func main() { apiCallGasLimitFlag, apiBacktraceLimitFlag, apiAllowCustomTracerFlag, + apiLogsEnabledFlag, onDemandFlag, persistFlag, gasLimitFlag, @@ -210,6 +212,7 @@ func defaultAction(ctx *cli.Context) error { ctx.Bool(pprofFlag.Name), skipLogs, ctx.Bool(apiAllowCustomTracerFlag.Name), + ctx.Bool(apiLogsEnabledFlag.Name), forkConfig) defer func() { log.Info("closing API..."); apiCloser() }() @@ -279,6 +282,7 @@ func soloAction(ctx *cli.Context) error { return err } defer func() { log.Info("closing main database..."); mainDB.Close() }() + if logDB, err = openLogDB(ctx, instanceDir); err != nil { return err } @@ -323,6 +327,7 @@ func soloAction(ctx *cli.Context) error { ctx.Bool(pprofFlag.Name), skipLogs, ctx.Bool(apiAllowCustomTracerFlag.Name), + ctx.Bool(apiLogsEnabledFlag.Name), forkConfig) defer func() { log.Info("closing API..."); apiCloser() }() @@ -330,7 +335,10 @@ func soloAction(ctx *cli.Context) error { if err != nil { return err } - defer func() { log.Info("stopping API server..."); srvCloser() }() + defer func() { + log.Info("stopping API server...") + srvCloser() + }() printSoloStartupMessage(gene, repo, instanceDir, apiURL, forkConfig)