From 5871741c3d2f6e90e33afd919be8e3b5d223ba4f Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Fran=C3=A7ois=20Samin?= Date: Thu, 2 Jul 2020 22:13:00 +0200 Subject: [PATCH] fix(engine): keep the main trace.span in context (#5287) --- engine/api/observability/helper.go | 46 +++++++++++++++++++++++++++-- engine/api/observability/tracing.go | 10 ++++++- engine/api/project/dao.go | 19 ++++++++++-- engine/api/router.go | 12 +++++--- engine/api/services/http.go | 13 ++++++++ 5 files changed, 91 insertions(+), 9 deletions(-) diff --git a/engine/api/observability/helper.go b/engine/api/observability/helper.go index a32162c5d1..07cd7908fb 100644 --- a/engine/api/observability/helper.go +++ b/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() } } diff --git a/engine/api/observability/tracing.go b/engine/api/observability/tracing.go index c76f28c25e..dd1bc81902 100644 --- a/engine/api/observability/tracing.go +++ b/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 } diff --git a/engine/api/project/dao.go b/engine/api/project/dao.go index cf4564b61d..d0b3e07f0e 100644 --- a/engine/api/project/dao.go +++ b/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{} diff --git a/engine/api/router.go b/engine/api/router.go index ee2ac9d216..4b5a43bbb8 100644 --- a/engine/api/router.go +++ b/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 diff --git a/engine/api/services/http.go b/engine/api/services/http.go index 7a9901dce5..e15fbd6cb1 100644 --- a/engine/api/services/http.go +++ b/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...) }