fix(engine): keep the main trace.span in context (#5287)

engine/api/observability/helper.go

@@ -105,9 +105,51 @@ func ContextGetTags(ctx context.Context, s ...string) []tag.Mutator {
 	return tags
 }
 
+func MainSpan(ctx context.Context) *trace.Span {
+	spanI := ctx.Value(contextMainSpan)
+	if spanI == nil {
+		return nil
+	}
+
+	rootSpan, ok := spanI.(*trace.Span)
+	if !ok {
+		return nil
+	}
+
+	return rootSpan
+}
+
+func SpanFromMain(ctx context.Context, name string, tags ...trace.Attribute) (context.Context, func()) {
+	rootSpan := MainSpan(ctx)
+	if rootSpan == nil {
+		return ctx, func() {}
+	}
+	rootSpanContext := rootSpan.SpanContext()
+
+	var traceOpts = []trace.StartOption{}
+
+	var sampler trace.Sampler
+	if rootSpanContext.IsSampled() {
+		sampler = trace.AlwaysSample()
+	}
+
+	if sampler != nil {
+		traceOpts = append(traceOpts, trace.WithSampler(sampler))
+	}
+
+	ctx, span := trace.StartSpanWithRemoteParent(ctx, name, rootSpanContext, traceOpts...)
+	span.AddLink(trace.Link{
+		TraceID: rootSpanContext.TraceID,
+		SpanID:  rootSpanContext.SpanID,
+	})
+	span.AddAttributes(tags...)
+
+	return ctx, span.End
+}
+
 // Span start a new span from the parent context
 func Span(ctx context.Context, name string, tags ...trace.Attribute) (context.Context, func()) {
-	log.Debug("# %s - begin", name)
+	// log.Debug("# %s - begin", name)
 	if ctx == nil {
 		return context.Background(), func() {}
 	}
@@ -118,7 +160,7 @@ func Span(ctx context.Context, name string, tags ...trace.Attribute) (context.Co
 	}
 	ctx = tracingutils.SpanContextToContext(ctx, span.SpanContext())
 	return ctx, func() {
-		log.Debug("# %s - end", name)
+		// log.Debug("# %s - end", name)
 		span.End()
 	}
 }

engine/api/observability/tracing.go

@@ -12,6 +12,12 @@ import (
 	"github.com/ovh/cds/sdk/tracingutils"
 )
 
+type contextKey int
+
+const (
+	contextMainSpan contextKey = iota
+)
+
 // New may start a tracing span
 func New(ctx context.Context, s service, name string, sampler trace.Sampler, spanKind int) (context.Context, *trace.Span) {
 	if traceExporter == nil {
@@ -79,6 +85,8 @@ func Start(ctx context.Context, s service, w http.ResponseWriter, req *http.Requ
 		trace.StringAttribute(UserAgentAttribute, req.UserAgent()),
 	)
 
+	ctx = context.WithValue(ctx, contextMainSpan, span)
+
 	ctx = tracingutils.SpanContextToContext(ctx, span.SpanContext())
 	ctx = ContextWithTag(ctx,
 		TagServiceType, s.Type(),
@@ -89,7 +97,7 @@ func Start(ctx context.Context, s service, w http.ResponseWriter, req *http.Requ
 
 // End may close a tracing span
 func End(ctx context.Context, w http.ResponseWriter, req *http.Request) (context.Context, error) {
-	span := trace.FromContext(ctx)
+	span := MainSpan(ctx)
 	if span == nil {
 		return ctx, nil
 	}

engine/api/project/dao.go

@@ -26,6 +26,9 @@ func loadAllByRepo(ctx context.Context, db gorp.SqlExecutor, query string, args
 
 // LoadAllByRepoAndGroupIDs returns all projects with an application linked to the repo against the groups
 func LoadAllByRepoAndGroupIDs(ctx context.Context, db gorp.SqlExecutor, groupIDs []int64, repo string, opts ...LoadOptionFunc) (sdk.Projects, error) {
+	var end func()
+	ctx, end = observability.Span(ctx, "project.LoadAllByRepoAndGroupIDs")
+	defer end()
 	query := `SELECT DISTINCT project.*
 		FROM  project
 		JOIN  application on project.id = application.project_id
@@ -44,6 +47,9 @@ func LoadAllByRepoAndGroupIDs(ctx context.Context, db gorp.SqlExecutor, groupIDs
 
 // LoadAllByRepo returns all projects with an application linked to the repo
 func LoadAllByRepo(ctx context.Context, db gorp.SqlExecutor, store cache.Store, repo string, opts ...LoadOptionFunc) (sdk.Projects, error) {
+	var end func()
+	ctx, end = observability.Span(ctx, "project.LoadAllByRepo")
+	defer end()
 	query := `SELECT DISTINCT project.*
 	FROM  project
 	JOIN  application on project.id = application.project_id
@@ -55,6 +61,9 @@ func LoadAllByRepo(ctx context.Context, db gorp.SqlExecutor, store cache.Store,
 
 // LoadAllByGroupIDs returns all projects given groups
 func LoadAllByGroupIDs(ctx context.Context, db gorp.SqlExecutor, store cache.Store, IDs []int64, opts ...LoadOptionFunc) (sdk.Projects, error) {
+	var end func()
+	ctx, end = observability.Span(ctx, "project.LoadAllByGroupIDs")
+	defer end()
 	query := `SELECT project.*
 	FROM project
 	WHERE project.id IN (
@@ -72,6 +81,9 @@ func LoadAllByGroupIDs(ctx context.Context, db gorp.SqlExecutor, store cache.Sto
 
 // LoadAll returns all projects
 func LoadAll(ctx context.Context, db gorp.SqlExecutor, store cache.Store, opts ...LoadOptionFunc) (sdk.Projects, error) {
+	var end func()
+	ctx, end = observability.Span(ctx, "project.LoadAll")
+	defer end()
 	query := "select project.* from project ORDER by project.name, project.projectkey ASC"
 	return loadprojects(ctx, db, opts, query)
 }
@@ -227,6 +239,9 @@ func LoadByID(db gorp.SqlExecutor, id int64, opts ...LoadOptionFunc) (*sdk.Proje
 
 // Load  returns a project with all its variables and applications given a user. It can also returns pipelines, environments, groups, permission, and repositorires manager. See LoadOptions
 func Load(ctx context.Context, db gorp.SqlExecutor, key string, opts ...LoadOptionFunc) (*sdk.Project, error) {
+	var end func()
+	ctx, end = observability.Span(ctx, "project.Load")
+	defer end()
 	return load(ctx, db, opts, "select project.* from project where projectkey = $1", key)
 }
 
@@ -241,7 +256,7 @@ func LoadProjectByWorkflowID(db gorp.SqlExecutor, workflowID int64, opts ...Load
 
 func loadprojects(ctx context.Context, db gorp.SqlExecutor, opts []LoadOptionFunc, query string, args ...interface{}) ([]sdk.Project, error) {
 	var end func()
-	_, end = observability.Span(ctx, "project.loadprojects")
+	ctx, end = observability.Span(ctx, "project.loadprojects")
 	defer end()
 
 	var res []dbProject
@@ -268,7 +283,7 @@ func loadprojects(ctx context.Context, db gorp.SqlExecutor, opts []LoadOptionFun
 
 func load(ctx context.Context, db gorp.SqlExecutor, opts []LoadOptionFunc, query string, args ...interface{}) (*sdk.Project, error) {
 	var end func()
-	_, end = observability.Span(ctx, "project.load")
+	ctx, end = observability.Span(ctx, "project.load")
 	defer end()
 
 	dbProj := &dbProject{}

engine/api/router.go

@@ -396,13 +396,12 @@ func (r *Router) handle(uri string, scope HandlerScope, handlers ...*service.Han
 				responseWriter.statusCode = 200
 			}
 			ctx = observability.ContextWithTag(ctx, observability.StatusCode, responseWriter.statusCode)
-
 			end := time.Now()
 			latency := end.Sub(start)
 
 			log.InfoWithFields(ctx, logrus.Fields{
 				"method":        req.Method,
-				"latency":       latency.Milliseconds(),
+				"latency_int":   latency.Nanoseconds,
 				"latency_human": latency,
 				"status":        responseWriter.statusCode,
 				"route":         cleanURL,
@@ -429,17 +428,22 @@ func (r *Router) handle(uri string, scope HandlerScope, handlers ...*service.Han
 			}
 		}
 
+		var end func()
+		ctx, end = observability.SpanFromMain(ctx, "router.handle")
+
 		if err := rc.Handler(ctx, responseWriter.wrappedResponseWriter(), req); err != nil {
 			observability.Record(r.Background, Errors, 1)
-			observability.End(ctx, responseWriter, req)
+			observability.End(ctx, responseWriter, req) // nolint
 			service.WriteError(ctx, responseWriter, req, err)
+			end()
 			deferFunc(ctx)
 			return
 		}
+		end()
 
 		// writeNoContentPostMiddleware is compliant Middleware Interface
 		// but no need to check ct, err in return
-		writeNoContentPostMiddleware(ctx, responseWriter, req, rc)
+		writeNoContentPostMiddleware(ctx, responseWriter, req, rc) // nolint
 
 		for _, m := range r.PostMiddlewares {
 			var err error

engine/api/services/http.go

@@ -18,6 +18,7 @@ import (
 	"gopkg.in/spacemonkeygo/httpsig.v0"
 
 	"github.com/ovh/cds/engine/api/authentication"
+	"github.com/ovh/cds/engine/api/observability"
 	"github.com/ovh/cds/sdk"
 	"github.com/ovh/cds/sdk/cdsclient"
 	"github.com/ovh/cds/sdk/log"
@@ -63,6 +64,12 @@ func (s *defaultServiceClient) DoMultiPartRequest(ctx context.Context, method, p
 
 // doMultiPartRequest performs an http request on a service with multipart  tar file + json field
 func doMultiPartRequest(ctx context.Context, db gorp.SqlExecutor, srvs []sdk.Service, method, path string, multiPartData *MultiPartData, in interface{}, out interface{}, mods ...cdsclient.RequestModifier) (int, error) {
+	ctx, end := observability.Span(ctx, "services.doMultiPartRequest",
+		observability.Tag("http.method", method),
+		observability.Tag("http.path", path),
+	)
+	defer end()
+
 	body := &bytes.Buffer{}
 	writer := multipart.NewWriter(body)
 
@@ -124,6 +131,12 @@ func doMultiPartRequest(ctx context.Context, db gorp.SqlExecutor, srvs []sdk.Ser
 }
 
 func (s *defaultServiceClient) DoJSONRequest(ctx context.Context, method, path string, in interface{}, out interface{}, mods ...cdsclient.RequestModifier) (http.Header, int, error) {
+	ctx, end := observability.Span(ctx, "services.DoJSONRequest",
+		observability.Tag("http.method", method),
+		observability.Tag("http.path", path),
+	)
+	defer end()
+
 	return doJSONRequest(ctx, s.db, s.srvs, method, path, in, out, mods...)
 }