DVO-1024: log "id" claim from CL authorization token

cmd/jwt-tokens-service/main.go

@@ -8,8 +8,9 @@ import (
 	"log"
 	"net/http"
 	"os"
+	"time"
 
-	"github.com/golang-jwt/jwt"
+	"github.com/golang-jwt/jwt/v5"
 )
 
 var (
@@ -64,7 +65,7 @@ func generateJWT(secretHex string) (string, error) {
 	token := jwt.New(jwt.SigningMethodHS256)
 	claims := token.Claims.(jwt.MapClaims)
 
-	claims["iat"] = jwt.TimeFunc().Unix()
+	claims["iat"] = time.Now().Unix()
 	if *clientID != "" {
 		claims["id"] = *clientID
 	}

go.mod

@@ -41,7 +41,7 @@ require (
 
 require (
 	github.com/ethereum/go-ethereum v1.15.2
-	github.com/golang-jwt/jwt v3.2.2+incompatible
+	github.com/golang-jwt/jwt/v5 v5.2.2
 	github.com/gorilla/mux v1.8.0
 	github.com/sirupsen/logrus v1.9.3
 	github.com/stretchr/testify v1.9.0

go.sum

@@ -34,8 +34,8 @@ github.com/go-ole/go-ole v1.3.0 h1:Dt6ye7+vXGIKZ7Xtk4s6/xVdGDQynvom7xCFEdWr6uE=
 github.com/go-ole/go-ole v1.3.0/go.mod h1:5LS6F96DhAwUc7C+1HLexzMXY1xGRSryjyPPKW6zv78=
 github.com/gofrs/flock v0.8.1 h1:+gYjHKf32LDeiEEFhQaotPbLuUXjY5ZqxKgXy7n59aw=
 github.com/gofrs/flock v0.8.1/go.mod h1:F1TvTiK9OcQqauNUHlbJvyl9Qa1QvF/gOUDKA14jxHU=
-github.com/golang-jwt/jwt v3.2.2+incompatible h1:IfV12K8xAKAnZqdXVzCZ+TOjboZ2keLg81eXfW3O+oY=
-github.com/golang-jwt/jwt v3.2.2+incompatible/go.mod h1:8pz2t5EyA70fFQQSrl6XZXzqecmYZeUEB8OUGHkxJ+I=
+github.com/golang-jwt/jwt/v5 v5.2.2 h1:Rl4B7itRWVtYIHFrSNd7vhTiz9UpLdi6gZhZ3wEeDy8=
+github.com/golang-jwt/jwt/v5 v5.2.2/go.mod h1:pqrtFR0X4osieyHYxtmOUWsAWrfe1Q5UVIyoH402zdk=
 github.com/golang/snappy v0.0.5-0.20220116011046-fa5810519dcb h1:PBC98N2aIaM3XXiurYmW7fx4GZkL8feAMVq7nEjURHk=
 github.com/golang/snappy v0.0.5-0.20220116011046-fa5810519dcb/go.mod h1:/XxbfmMg8lxefKM7IXC3fBNl/7bRcc72aCRzEWrmP2Q=
 github.com/google/subcommands v1.2.0/go.mod h1:ZjhPrFU+Olkh9WazFPsl27BQ4UPiG37m3yTrtFlrHVk=

proxy.go

@@ -16,6 +16,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/golang-jwt/jwt/v5"
 	"github.com/sirupsen/logrus"
 )
 
@@ -114,6 +115,38 @@ func (p *ProxyService) StartHTTPServer() error {
 	return err
 }
 
+func getLogFieldsFromRequest(req *http.Request) logrus.Fields {
+	logFields := logrus.Fields{"remoteHost": getRemoteHost(req)}
+
+	token := strings.TrimPrefix(req.Header.Get("Authorization"), "Bearer ")
+	jwtID := getIDClaim(token)
+	if jwtID != "" {
+		logFields["clID"] = jwtID
+	}
+
+	return logFields
+}
+
+// getIDClaim extracts the "id" claim from JWT token
+// Ignores signatures and does not validate the token.
+// Returns empty string if no token, invalid token, or no "id" claim
+func getIDClaim(tokenStr string) string {
+	token, _, err := jwt.NewParser().ParseUnverified(tokenStr, jwt.MapClaims{})
+	if err != nil {
+		return ""
+	}
+
+	if claims, ok := token.Claims.(jwt.MapClaims); ok {
+		if id, exists := claims["id"]; exists {
+			if idStr, ok := id.(string); ok {
+				return idStr
+			}
+		}
+	}
+
+	return ""
+}
+
 func (p *ProxyService) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 	// return OK for all GET requests, used for debug
 	if req.Method == http.MethodGet {
@@ -129,15 +162,16 @@ func (p *ProxyService) ServeHTTP(w http.ResponseWriter, req *http.Request) {
 		return
 	}
 
+	log := p.log.WithFields(getLogFieldsFromRequest(req))
 	remoteHost := getRemoteHost(req)
-	requestJSON, err := p.checkBeaconRequest(bodyBytes, remoteHost)
+	requestJSON, err := p.checkBeaconRequest(log, bodyBytes, remoteHost)
 	if err != nil {
 		w.WriteHeader(http.StatusInternalServerError)
 		return
 	}
 
 	if p.shouldFilterRequest(remoteHost, requestJSON.Method) {
-		p.log.WithField("remoteHost", remoteHost).Debug("request filtered from beacon node proxy is not synced to")
+		log.Debug("request filtered from beacon node proxy is not synced to")
 		w.WriteHeader(http.StatusOK)
 		return
 	}
@@ -257,28 +291,28 @@ func (p *ProxyService) callProxies(req *http.Request, bodyBytes []byte) {
 	}
 }
 
-func (p *ProxyService) checkBeaconRequest(bodyBytes []byte, remoteHost string) (JSONRPCRequest, error) {
+func (p *ProxyService) checkBeaconRequest(log *logrus.Entry, bodyBytes []byte, remoteHost string) (JSONRPCRequest, error) {
 	var requestJSON JSONRPCRequest
 	var batchRequestJSON []JSONRPCRequest
 	err := json.Unmarshal(bodyBytes, &requestJSON)
 
 	if err != nil {
-		p.log.WithError(err).Warn("failed to decode request body json, trying to decode as batch request")
+		log.WithError(err).Warn("failed to decode request body json, trying to decode as batch request")
 		// may be batch request
 		if err := json.Unmarshal(bodyBytes, &batchRequestJSON); err != nil {
-			p.log.WithError(err).Error("failed to decode request body json as batch request")
+			log.WithError(err).Error("failed to decode request body json as batch request")
 			return requestJSON, err
 		}
 		// not interested in batch requests
 		return requestJSON, nil
 	}
 
-	p.log.WithFields(logrus.Fields{
+	log.WithFields(logrus.Fields{
 		"method": requestJSON.Method,
 		"id":     requestJSON.ID,
 	}).Debug("request received from beacon node")
 
-	p.updateBestBeaconEntry(requestJSON, remoteHost)
+	p.updateBestBeaconEntry(log, requestJSON, remoteHost)
 
 	return requestJSON, nil
 }
@@ -302,14 +336,12 @@ func (p *ProxyService) isFromBestBeaconEntry(remoteHost string) bool {
 }
 
 // updates for which the proxy / beacon should sync to
-func (p *ProxyService) updateBestBeaconEntry(request JSONRPCRequest, requestAddr string) {
+func (p *ProxyService) updateBestBeaconEntry(log *logrus.Entry, request JSONRPCRequest, requestAddr string) {
 	p.mu.Lock()
 	defer p.mu.Unlock()
 
 	if p.bestBeaconEntry == nil {
-		log.WithFields(logrus.Fields{
-			"newAddr": requestAddr,
-		}).Info("request received from beacon node")
+		log.Info("request received from beacon node")
 		p.bestBeaconEntry = &BeaconEntry{Addr: requestAddr, Timestamp: 0}
 	}