Improved logging and metrics. (#227)

1. Improve logging to include API method, user ID, etc in the output. We do this by intercepting the request details in the "middleware" and adding them to the request context, as well as adding a wrapper to logrus that simplifies including the fields in the output.

2. Breakdown API metrics by method. This will allow us to differentiate call counts and durations by API method (eg, eth_call vs eth_getStorageAt).

pkg/prom/middleware.go

@@ -17,25 +17,105 @@
 package prom
 
 import (
+	"bytes"
+	"context"
+	"encoding/json"
+	"fmt"
+	"io"
 	"net/http"
 	"time"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
+	"github.com/google/uuid"
+
 	"github.com/ethereum/go-ethereum/rpc"
 )
 
-// HTTPMiddleware http connection metric reader
-func HTTPMiddleware(next http.Handler) http.Handler {
-	if !metrics {
-		return next
+const (
+	jsonMethod               = "method"
+	jsonParams               = "params"
+	jsonReqId                = "id"
+	headerUserId             = "X-User-Id"
+	headerOriginalRemoteAddr = "X-Original-Remote-Addr"
+)
+
+// Peek at the request and update the Context accordingly (eg, API method, user ID, etc.)
+func preprocessRequest(r *http.Request) (*http.Request, error) {
+	// Generate a unique ID for this request.
+	uniqId, err := uuid.NewUUID()
+	if nil != err {
+		return nil, err
 	}
 
-	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		httpCount.Inc()
+	// Read the body so that we can peek inside.
+	body, err := io.ReadAll(r.Body)
+	if nil != err {
+		return nil, err
+	}
 
+	// Replace it with a re-readable copy.
+	r.Body = io.NopCloser(bytes.NewBuffer(body))
+
+	// All API requests should be JSON.
+	var result map[string]interface{}
+	err = json.Unmarshal(body, &result)
+	if nil != err {
+		return nil, err
+	}
+
+	// Pull out the method name, request ID, user ID, and address info.
+	reqId := fmt.Sprintf("%g", result[jsonReqId])
+	reqMethod := fmt.Sprintf("%v", result[jsonMethod])
+	reqParams := fmt.Sprintf("%v", result[jsonParams])
+	// Truncate parameters unless trace logging is enabled.
+	if !log.IsLevelEnabled(log.TraceLevel) {
+		if len(reqParams) > 250 {
+			reqParams = reqParams[:250] + "..."
+		}
+	}
+	userId := r.Header.Get(headerUserId)
+	conn := r.Header.Get(headerOriginalRemoteAddr)
+	if len(conn) == 0 {
+		conn = r.RemoteAddr
+	}
+
+	// Add it all to the request context.
+	ctx := r.Context()
+	ctx = context.WithValue(ctx, log.CtxKeyUniqId, uniqId.String())
+	ctx = context.WithValue(ctx, log.CtxKeyApiMethod, reqMethod)
+	ctx = context.WithValue(ctx, log.CtxKeyApiParams, string(reqParams))
+	ctx = context.WithValue(ctx, log.CtxKeyApiReqId, reqId)
+	ctx = context.WithValue(ctx, log.CtxKeyUserId, userId)
+	ctx = context.WithValue(ctx, log.CtxKeyConn, conn)
+
+	return r.WithContext(ctx), nil
+}
+
+// HTTPMiddleware http connection metric reader
+func HTTPMiddleware(next http.Handler) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		start := time.Now()
+		r, err := preprocessRequest(r)
+		if nil != err {
+			log.WithError(err).Error("Error preprocessing request")
+			w.WriteHeader(http.StatusBadRequest)
+			return
+		}
+		ctx := r.Context()
+		apiMethod := fmt.Sprintf("%s", ctx.Value(log.CtxKeyApiMethod))
+
+		if metrics {
+			httpCount.WithLabelValues(apiMethod).Inc()
+		}
+
+		log.Debugx(ctx, "START")
 		next.ServeHTTP(w, r)
 		duration := time.Now().Sub(start)
-		httpDuration.Observe(float64(duration.Seconds()))
+		log.Debugxf(context.WithValue(ctx, log.CtxKeyDuration, duration.Milliseconds()), "END")
+
+		if metrics {
+			httpDuration.WithLabelValues(apiMethod).Observe(duration.Seconds())
+		}
 	})
 }
 

pkg/prom/prom.go

@@ -33,8 +33,8 @@ const (
 var (
 	metrics bool
 
-	httpCount    prometheus.Counter
-	httpDuration prometheus.Histogram
+	httpCount    *prometheus.CounterVec
+	httpDuration *prometheus.HistogramVec
 	wsCount      prometheus.Gauge
 	ipcCount     prometheus.Gauge
 )
@@ -43,18 +43,19 @@ var (
 func Init() {
 	metrics = true
 
-	httpCount = promauto.NewCounter(prometheus.CounterOpts{
+	httpCount = promauto.NewCounterVec(prometheus.CounterOpts{
 		Namespace: namespace,
 		Subsystem: subsystemHTTP,
 		Name:      "count",
 		Help:      "http request count",
-	})
-	httpDuration = promauto.NewHistogram(prometheus.HistogramOpts{
+	}, []string{"method"})
+
+	httpDuration = promauto.NewHistogramVec(prometheus.HistogramOpts{
 		Namespace: namespace,
 		Subsystem: subsystemHTTP,
 		Name:      "duration",
 		Help:      "http request duration",
-	})
+	}, []string{"method"})
 
 	wsCount = promauto.NewGauge(prometheus.GaugeOpts{
 		Namespace: namespace,

pkg/prom/serve.go

@@ -20,8 +20,8 @@ import (
 	"errors"
 	"net/http"
 
+	"github.com/cerc-io/ipld-eth-server/v4/pkg/log"
 	"github.com/prometheus/client_golang/prometheus/promhttp"
-	"github.com/sirupsen/logrus"
 )
 
 var errPromHTTP = errors.New("can't start http server for prometheus")
@@ -36,7 +36,7 @@ func Serve(addr string) *http.Server {
 	}
 	go func() {
 		if err := srv.ListenAndServe(); err != nil {
-			logrus.
+			log.
 				WithError(err).
 				WithField("module", "prom").
 				WithField("addr", addr).