feat(api): add authentication and metadata log fields (#5672)

Signed-off-by: francois  samin <francois.samin@corp.ovh.com>

engine/api/auth.go

@@ -268,6 +268,11 @@ func (api *API) postAuthSigninHandler() service.Handler {
 			return err
 		}
 
+		// If the auth driver is giving a tokenID, let's keep it
+		if userInfo.ExternalTokenID != "" {
+			session.TokenID = userInfo.ExternalTokenID
+		}
+
 		log.Debug(ctx, "postAuthSigninHandler> new session %s created for %.2f seconds: %+v", session.ID, sessionDuration.Seconds(), session)
 
 		// Generate a jwt for current session

engine/api/authentication/corpsso/corpsso.go

@@ -10,6 +10,7 @@ import (
 	"strings"
 	"time"
 
+	"github.com/rockbears/log"
 	jose "gopkg.in/square/go-jose.v2"
 
 	"github.com/ovh/cds/sdk"
@@ -222,10 +223,13 @@ func (d authDriver) GetUserInfo(ctx context.Context, req sdk.AuthConsumerSigninR
 		return u, sdk.NewErrorFrom(sdk.ErrWrongRequest, "expired JWT %s/%s", itk.RemoteUser, itk.TokenID)
 	}
 
+	log.Info(ctx, "new session created for remote_user: %v, iat: %v, token_id: %v, mfa: %v", itk.RemoteUser, itk.IAT, itk.TokenID, itk.MFA)
+
 	u.Username = itk.RemoteUser
 	u.ExternalID = itk.RemoteUser
 	u.MFA = itk.MFA
 	u.Email = itk.RemoteUser + "@" + d.Config.MailDomain
+	u.ExternalTokenID = itk.TokenID
 
 	return u, nil
 }

engine/api/authentication/session.go

@@ -45,8 +45,9 @@ func CheckSession(ctx context.Context, db gorp.SqlExecutor, sessionID string) (*
 // NewSessionJWT generate a signed token for given auth session.
 func NewSessionJWT(s *sdk.AuthSession) (string, error) {
 	jwtToken := jwt.NewWithClaims(jwt.SigningMethodRS512, sdk.AuthSessionJWTClaims{
-		ID:  s.ID,
-		MFA: s.MFA,
+		ID:      s.ID,
+		MFA:     s.MFA,
+		TokenID: s.TokenID,
 		StandardClaims: jwt.StandardClaims{
 			Issuer:    GetIssuerName(),
 			Subject:   s.ConsumerID,

engine/api/router.go

@@ -1,14 +1,12 @@
 package api
 
 import (
-	"bytes"
 	"compress/gzip"
 	"context"
 	"fmt"
-	"io"
-	"io/ioutil"
 	"net/http"
 	"reflect"
+	"regexp"
 	"runtime"
 	"runtime/pprof"
 	"strings"
@@ -247,6 +245,8 @@ func (r *Router) HandlePrefix(uri string, scope HandlerScope, handlers ...*servi
 	r.Mux.PathPrefix(uri).HandlerFunc(r.pprofLabel(config, r.compress(r.setRequestID(r.recoverWrap(f)))))
 }
 
+var uriActionMetadataRegex = regexp.MustCompile("({[A-Za-z]+})")
+
 // Handle adds all handler for their specific verb in gorilla router for given uri
 func (r *Router) handle(uri string, scope HandlerScope, handlers ...*service.HandlerConfig) (map[string]*service.HandlerConfig, http.HandlerFunc) {
 	cfg := &service.RouterConfig{
@@ -269,6 +269,17 @@ func (r *Router) handle(uri string, scope HandlerScope, handlers ...*service.Han
 		cfg.Config[handlers[i].Method] = handlers[i]
 	}
 
+	// Search for all "fields" in the given URI
+	var actionMetadataFields = uriActionMetadataRegex.FindAllString(uri, -1)
+	for _, s := range actionMetadataFields {
+		s = strings.ReplaceAll(s, "{", "")
+		s = strings.ReplaceAll(s, "}", "")
+		s = doc.CleanURLParameter(s)
+		s = strings.ReplaceAll(s, "-", "_")
+		var f = log.Field("action_metadata_" + doc.CleanURLParameter(s))
+		log.RegisterField(f)
+	}
+
 	f := func(w http.ResponseWriter, req *http.Request) {
 		ctx, cancel := context.WithCancel(req.Context())
 		defer cancel()
@@ -335,6 +346,18 @@ func (r *Router) handle(uri string, scope HandlerScope, handlers ...*service.Han
 		ctx = context.WithValue(ctx, cdslog.RequestURI, req.RequestURI)
 		ctx = context.WithValue(ctx, cdslog.Deprecated, rc.IsDeprecated)
 		ctx = context.WithValue(ctx, cdslog.Handler, rc.Name)
+		ctx = context.WithValue(ctx, cdslog.Action, rc.Name)
+
+		var fields = mux.Vars(req)
+		for k, v := range fields {
+			var s = doc.CleanURLParameter(k)
+			s = strings.ReplaceAll(s, "-", "_")
+			var f = log.Field("action_metadata_" + s)
+			ctx = context.WithValue(ctx, f, v)
+		}
+
+		// By default track all request as not sudo, TrackSudo will be enabled when required
+		SetTracker(responseWriter, cdslog.Sudo, false)
 
 		// Log request start
 		start := time.Now()
@@ -437,33 +460,6 @@ func (r *Router) handle(uri string, scope HandlerScope, handlers ...*service.Han
 	return cfg.Config, f
 }
 
-type asynchronousRequest struct {
-	nbErrors      int
-	err           error
-	contextValues map[interface{}]interface{}
-	vars          map[string]string
-	request       http.Request
-	body          io.Reader
-}
-
-func (r *asynchronousRequest) do(ctx context.Context, h service.AsynchronousHandler) error {
-	for k, v := range r.contextValues {
-		ctx = context.WithValue(ctx, k, v)
-	}
-	req := &r.request
-
-	var buf bytes.Buffer
-	tee := io.TeeReader(r.body, &buf)
-	r.body = &buf
-	//Recreate a new buffer from the bytes stores in memory
-	req.Body = ioutil.NopCloser(tee)
-	r.err = h(ctx, req)
-	if r.err != nil {
-		r.nbErrors++
-	}
-	return r.err
-}
-
 // DEPRECATED marks the handler as deprecated
 var DEPRECATED = func(rc *service.HandlerConfig) {
 	rc.IsDeprecated = true

engine/api/router_middleware_auth.go

@@ -104,6 +104,10 @@ func (api *API) authMiddleware(ctx context.Context, w http.ResponseWriter, req *
 	if session != nil {
 		ctx = context.WithValue(ctx, cdslog.AuthSessionID, session.ID)
 		SetTracker(w, cdslog.AuthSessionID, session.ID)
+		ctx = context.WithValue(ctx, cdslog.AuthSessionIAT, session.Created.Unix())
+		SetTracker(w, cdslog.AuthSessionIAT, session.Created.Unix())
+		ctx = context.WithValue(ctx, cdslog.AuthSessionTokenID, session.TokenID)
+		SetTracker(w, cdslog.AuthSessionTokenID, session.TokenID)
 	}
 
 	return ctx, nil
@@ -132,7 +136,9 @@ func (api *API) authOptionalMiddleware(ctx context.Context, w http.ResponseWrite
 		log.Debug(ctx, "api.authOptionalMiddleware> no session found in context")
 		return ctx, nil
 	}
+	session.TokenID = claims.TokenID
 	ctx = context.WithValue(ctx, contextSession, session)
+	ctx = context.WithValue(ctx, cdslog.AuthSessionTokenID, session.TokenID)
 
 	// Load auth consumer for current session in database with authentified user and contacts
 	consumer, err := authentication.LoadConsumerByID(ctx, api.mustDB(), session.ConsumerID,

go.mod

@@ -101,7 +101,7 @@ require (
 	github.com/pquerna/cachecontrol v0.0.0-20200819021114-67c6ae64274f // indirect
 	github.com/prometheus/client_golang v1.1.0 // indirect
 	github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4 // indirect
-	github.com/rockbears/log v0.2.0
+	github.com/rockbears/log v0.3.0
 	github.com/rubenv/sql-migrate v0.0.0-20160620083229-6f4757563362
 	github.com/satori/go.uuid v1.2.0
 	github.com/sguiheux/go-coverage v0.0.0-20190710153556-287b082a7197
@@ -132,7 +132,7 @@ require (
 	golang.org/x/crypto v0.0.0-20200709230013-948cd5f35899
 	golang.org/x/net v0.0.0-20200528225125-3c3fba18258b
 	golang.org/x/oauth2 v0.0.0-20190604053449-0f29369cfe45
-	golang.org/x/sys v0.0.0-20200724161237-0e2f3a69832c
+	golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c
 	golang.org/x/text v0.3.2
 	golang.org/x/time v0.0.0-20190308202827-9d24e82272b4
 	google.golang.org/grpc v1.23.0

go.sum

@@ -495,8 +495,8 @@ github.com/prometheus/tsdb v0.7.1/go.mod h1:qhTCs0VvXwvX/y3TZrWD7rabWM+ijKTux40T
 github.com/rcrowley/go-metrics v0.0.0-20181016184325-3113b8401b8a/go.mod h1:bCqnVzQkZxMG4s8nGwiZ5l3QUCyqpo9Y+/ZMZ9VjZe4=
 github.com/rcrowley/go-metrics v0.0.0-20200313005456-10cdbea86bc0 h1:MkV+77GLUNo5oJ0jf870itWm3D0Sjh7+Za9gazKc5LQ=
 github.com/rcrowley/go-metrics v0.0.0-20200313005456-10cdbea86bc0/go.mod h1:bCqnVzQkZxMG4s8nGwiZ5l3QUCyqpo9Y+/ZMZ9VjZe4=
-github.com/rockbears/log v0.2.0 h1:ETfQvFJ3lPMfUw5abgbpyHQcg3YGpLTt/Dv7LSbDw8Y=
-github.com/rockbears/log v0.2.0/go.mod h1:ZgkxDU1V6kaeglaQv8JhIaZ4foVXzv+Cf44hGruhWMU=
+github.com/rockbears/log v0.3.0 h1:V26Z4/UnlwM4sIUXT01rrY0gfvrPSc//U3a6KlPcwhk=
+github.com/rockbears/log v0.3.0/go.mod h1:fKa6erpK6U16kk8xOLGusFuVz4qr+mqe+9zD0kVn7VI=
 github.com/rogpeppe/fastuuid v0.0.0-20150106093220-6724a57986af/go.mod h1:XWv6SoW27p1b0cqNHllgS5HIMJraePCO15w5zCzIWYg=
 github.com/rogpeppe/go-internal v1.3.0/go.mod h1:M8bDsm7K2OlrFYOpmOWEs/qY81heoFRclV5y23lUDJ4=
 github.com/rubenv/sql-migrate v0.0.0-20160620083229-6f4757563362 h1:lmOdpLt3XS6QyVoY6xNfOOTNWE2xtUBees+OAO+HFOg=
@@ -607,10 +607,18 @@ go.opencensus.io v0.22.0 h1:C9hSCOW830chIVkdja34wa6Ky+IzWllkUinR+BtRZd4=
 go.opencensus.io v0.22.0/go.mod h1:+kGneAE2xo2IficOXnaByMWTGM9T73dGwxeWcUqIpI8=
 go.uber.org/atomic v1.4.0 h1:cxzIVoETapQEqDhQu3QfnvXAV4AlzcvUCxkVUFw3+EU=
 go.uber.org/atomic v1.4.0/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
+go.uber.org/atomic v1.6.0 h1:Ezj3JGmsOnG1MoRWQkPBsKLe9DwWD9QeXzTRzzldNVk=
+go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
 go.uber.org/multierr v1.1.0 h1:HoEmRHQPVSqub6w2z2d2EOVs2fjyFRGyofhKuyDq0QI=
 go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0=
+go.uber.org/multierr v1.5.0 h1:KCa4XfM8CWFCpxXRGok+Q0SS/0XBhMDbHHGABQLvD2A=
+go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU=
+go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee h1:0mgffUl7nfd+FpvXMVz4IDEaUSmT1ysygQC7qYo7sG4=
+go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
 go.uber.org/zap v1.10.0 h1:ORx85nbTijNz8ljznvCMR1ZBIPKFn3jQrag10X2AsuM=
 go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
+go.uber.org/zap v1.16.0 h1:uFRZXykJGK9lLY4HtgSw44DnIcAM+kRBP7x5m+NpAOM=
+go.uber.org/zap v1.16.0/go.mod h1:MA8QOfq0BHJwdXa996Y4dYkAqRKB8/1K1QMMZVaNZjQ=
 golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20181029021203-45a5f77698d3/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20190211182817-74369b46fc67/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
@@ -696,6 +704,8 @@ golang.org/x/sys v0.0.0-20191026070338-33540a1f6037/go.mod h1:h1NjWce9XRLGQEsW7w
 golang.org/x/sys v0.0.0-20200323222414-85ca7c5b95cd/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/sys v0.0.0-20200724161237-0e2f3a69832c h1:UIcGWL6/wpCfyGuJnRFJRurA+yj8RrW7Q6x2YMCXt6c=
 golang.org/x/sys v0.0.0-20200724161237-0e2f3a69832c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
+golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c h1:VwygUrnw9jn88c4u8GD3rZQbqrP/tgas88tPUbBxQrk=
+golang.org/x/sys v0.0.0-20210124154548-22da62e12c0c/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs=
 golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.3.1-0.20180807135948-17ff2d5776d2/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ=
 golang.org/x/text v0.3.1-0.20181227161524-e6919f6577db/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk=
@@ -723,6 +733,8 @@ golang.org/x/tools v0.0.0-20190628153133-6cdbf07be9d0/go.mod h1:/rFqwRUd4F7ZHNgw
 golang.org/x/tools v0.0.0-20190816200558-6889da9d5479/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20190911174233-4f2ddba30aff/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20191012152004-8de300cfc20a/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/tools v0.0.0-20191029041327-9cc4af7d6b2c/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
+golang.org/x/tools v0.0.0-20191029190741-b9c20aec41a5/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/tools v0.0.0-20191112195655-aa38f8e97acc h1:NCy3Ohtk6Iny5V/reW2Ktypo4zIpWBdRJ1uFMjBxdg8=
 golang.org/x/tools v0.0.0-20191112195655-aa38f8e97acc/go.mod h1:b+2E5dAYhXwXZwtnZ6UAqBI28+e2cm9otk0dWdXHAEo=
 golang.org/x/xerrors v0.0.0-20190717185122-a985d3407aa7/go.mod h1:I/5z698sn9Ka8TeJc9MKroUUfqBBauWjQqLJ2OPfmY0=

sdk/doc/route.go

@@ -25,6 +25,80 @@ func CleanAndCheckURL(url string) (string, error) {
 	return url, nil
 }
 
+func CleanURLParameter(u string) string {
+	switch u {
+	case "consumerType":
+		u = "consumer-type"
+	case "key", "permProjectKey":
+		u = "project-key"
+	case "permWorkflowName", "workflowName":
+		u = "workflow-name"
+	case "workflowID":
+		u = "workflow-id"
+	case "applicationName":
+		u = "application-name"
+	case "permGroupName", "groupName":
+		u = "group-name"
+	case "permUsernamePublic", "permUsername":
+		u = "username"
+	case "permActionName", "permActionBuiltinName":
+		u = "action-name"
+	case "permJobID", "jobID":
+		u = "job-id"
+	case "pipelineKey":
+		u = "pipeline-key"
+	case "environmentName":
+		u = "environment-name"
+	case "nodeRunID":
+		u = "node-run-id"
+	case "runJobID":
+		u = "run-job-id"
+	case "stepOrder":
+		u = "step-order"
+	case "nodeID":
+		u = "node-id"
+	case "permModelName":
+		u = "model-name"
+	case "permTemplateSlug", "templateSlug":
+		u = "template-slug"
+	case "instanceID":
+		u = "instance-id"
+	case "bulkID":
+		u = "bulk-id"
+	case "permConsumerID":
+		u = "consumer-id"
+	case "permSessionID":
+		u = "session-id"
+	case "integrationID":
+		u = "integration-id"
+	case "integrationName":
+		u = "integration-name"
+	case "auditID":
+		u = "audit-id"
+	case "stageID":
+		u = "stage-id"
+	case "labelID":
+		u = "label-id"
+	case "nodeName":
+		u = "node-name"
+	case "artifactId":
+		u = "artifact-id"
+	case "hookRunID":
+		u = "hook-run-id"
+	case "vcsServer":
+		u = "vcs-server"
+	case "metricName":
+		u = "metric-name"
+	case "cloneName":
+		u = "clone-name"
+	case "serviceName":
+		u = "service-name"
+	case "sessionID":
+		u = "session-id"
+	}
+	return u
+}
+
 // CleanURL given a URL with declared variable inside, returns the same URL with harmonized variable names.
 // Ex: permProjectKey -> projectKey
 func CleanURL(url string) string {
@@ -36,78 +110,7 @@ func CleanURL(url string) string {
 			continue
 		}
 
-		switch u {
-		case "consumerType":
-			u = "consumer-type"
-		case "key", "permProjectKey":
-			u = "project-key"
-		case "permWorkflowName", "workflowName":
-			u = "workflow-name"
-		case "workflowID":
-			u = "workflow-id"
-		case "applicationName":
-			u = "application-name"
-		case "permGroupName", "groupName":
-			u = "group-name"
-		case "permUsernamePublic", "permUsername":
-			u = "username"
-		case "permActionName", "permActionBuiltinName":
-			u = "action-name"
-		case "permJobID", "jobID":
-			u = "job-id"
-		case "pipelineKey":
-			u = "pipeline-key"
-		case "environmentName":
-			u = "environment-name"
-		case "nodeRunID":
-			u = "node-run-id"
-		case "runJobID":
-			u = "run-job-id"
-		case "stepOrder":
-			u = "step-order"
-		case "nodeID":
-			u = "node-id"
-		case "permModelName":
-			u = "model-name"
-		case "permTemplateSlug", "templateSlug":
-			u = "template-slug"
-		case "instanceID":
-			u = "instance-id"
-		case "bulkID":
-			u = "bulk-id"
-		case "permConsumerID":
-			u = "consumer-id"
-		case "permSessionID":
-			u = "session-id"
-		case "integrationID":
-			u = "integration-id"
-		case "integrationName":
-			u = "integration-name"
-		case "auditID":
-			u = "audit-id"
-		case "stageID":
-			u = "stage-id"
-		case "labelID":
-			u = "label-id"
-		case "nodeName":
-			u = "node-name"
-		case "artifactId":
-			u = "artifact-id"
-		case "hookRunID":
-			u = "hook-run-id"
-		case "vcsServer":
-			u = "vcs-server"
-		case "metricName":
-			u = "metric-name"
-		case "cloneName":
-			u = "clone-name"
-		case "serviceName":
-			u = "service-name"
-		case "sessionID":
-			u = "session-id"
-		}
-
-		urlSplitted[i] = "<" + u + ">"
+		urlSplitted[i] = "<" + CleanURLParameter(u) + ">"
 	}
 	return strings.Join(urlSplitted, "/")
 }