DVO-1024: log "id" claim from CL authorization token (#19)

Engine API auth includes optional "id" claim which CL might set to its,
well, id. To improve troubleshooting, log not only remote IP of the CL
node, but also its "id", if set.

Author: ilyaluk

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