diff --git a/controller/getchangedtargets.go b/controller/getchangedtargets.go index 96c134d..cdcad33 100644 --- a/controller/getchangedtargets.go +++ b/controller/getchangedtargets.go @@ -72,7 +72,7 @@ func (c *controller) GetChangedTargets(request *pb.GetChangedTargetsRequest, str cacheKey := common.GetComparedTargetsCachePath(request.GetFirstRevision().GetRemote(), treehash1, treehash2, request.GetRequestOptions()) cachedReader, cacheErr := storage.NewChangedTargetsReader(ctx, c.storage, cacheKey) if cacheErr != nil && !storage.IsNotFound(cacheErr) { - c.logger.Warn("GetChangedTargets: Failed to read from cache, proceeding to compute", zap.Error(cacheErr)) + logger.Warn("GetChangedTargets: Failed to read from cache, proceeding to compute", zap.Error(cacheErr)) } else if cachedReader != nil { // Buffer all responses before sending any. A concurrent goroutine write may have // left a partial blob in storage; buffering lets us detect corruption and fall @@ -95,20 +95,20 @@ func (c *controller) GetChangedTargets(request *pb.GetChangedTargetsRequest, str if readErr != nil { // Blob is corrupt (likely an incomplete write). Log and fall through to recompute. - c.logger.Warn("GetChangedTargets: Cached result is incomplete, recomputing", zap.Error(readErr)) + logger.Warn("GetChangedTargets: Cached result is incomplete, recomputing", zap.Error(readErr)) } else { cacheReadDuration := time.Since(cacheStart) - c.logger.Info("GetChangedTargets: Cache hit, streaming from storage", + logger.Info("GetChangedTargets: Cache hit, streaming from storage", zap.Duration("cache_read_duration", cacheReadDuration), ) scope.Counter("cache_hit").Inc(1) scope.Timer("cache_read_duration").Record(cacheReadDuration) if sendErr := sendWithDistanceFilter(stream, cached, request.GetOutputConfig()); sendErr != nil { - c.logger.Error("GetChangedTargets: Failed to send cached response", zap.Error(sendErr)) + logger.Error("GetChangedTargets: Failed to send cached response", zap.Error(sendErr)) return fmt.Errorf("failed to send cached response: %w", sendErr) } totalDuration := time.Since(start) - c.logger.Info("GetChangedTargets: Successfully streamed from cache", + logger.Info("GetChangedTargets: Successfully streamed from cache", zap.Duration("total_duration", totalDuration), ) scope.Timer("total_duration").Record(totalDuration) @@ -202,7 +202,7 @@ func (c *controller) GetChangedTargets(request *pb.GetChangedTargetsRequest, str } graphFetchDuration := time.Since(graphFetchStart) - c.logger.Info("GetChangedTargets: Both graphs fetched", + logger.Info("GetChangedTargets: Both graphs fetched", zap.Duration("graph_fetch_duration", graphFetchDuration), ) scope.Timer("graph_fetch_duration").Record(graphFetchDuration) @@ -236,16 +236,16 @@ func (c *controller) GetChangedTargets(request *pb.GetChangedTargetsRequest, str jobs[1].graphStreamChunks = nil compareStart := time.Now() - changedTargetsResponses, err := c.compareTargetGraphs(ctx, firstGraph, secondGraph, request.GetOutputConfig()) + changedTargetsResponses, err := c.compareTargetGraphs(logger, firstGraph, secondGraph, request.GetOutputConfig()) // Allow GC of raw graph data while the caching goroutine runs. firstGraph = nil secondGraph = nil if err != nil { - c.logger.Error("GetChangedTargets: Failed to compare target graphs", zap.Error(err)) + logger.Error("GetChangedTargets: Failed to compare target graphs", zap.Error(err)) return fmt.Errorf("failed to compare target graphs: %w", err) } compareDuration := time.Since(compareStart) - c.logger.Info("GetChangedTargets: Target graphs compared", + logger.Info("GetChangedTargets: Target graphs compared", zap.Duration("compare_duration", compareDuration), ) scope.Timer("compare_duration").Record(compareDuration) @@ -261,21 +261,21 @@ func (c *controller) GetChangedTargets(request *pb.GetChangedTargetsRequest, str if treehash1 != "" && treehash2 != "" { cacheKey := common.GetComparedTargetsCachePath(request.GetFirstRevision().GetRemote(), treehash1, treehash2, request.GetRequestOptions()) if writeErr := storage.WriteChangedTargetsStream(cacheCtx, c.storage, cacheKey, changedTargetsResponses); writeErr != nil { - c.logger.Warn("GetChangedTargets: Failed to cache result", zap.Error(writeErr)) + logger.Warn("GetChangedTargets: Failed to cache result", zap.Error(writeErr)) } } }() sendStart := time.Now() if err := sendWithDistanceFilter(stream, changedTargetsResponses, request.GetOutputConfig()); err != nil { - c.logger.Error("GetChangedTargets: Failed to send response", zap.Error(err)) + logger.Error("GetChangedTargets: Failed to send response", zap.Error(err)) return fmt.Errorf("failed to send response: %w", err) } sendDuration := time.Since(sendStart) scope.Timer("send_duration").Record(sendDuration) totalDuration := time.Since(start) - c.logger.Info("GetChangedTargets: Successfully processed request", + logger.Info("GetChangedTargets: Successfully processed request", zap.Duration("send_duration", sendDuration), zap.Duration("total_duration", totalDuration), ) @@ -283,10 +283,10 @@ func (c *controller) GetChangedTargets(request *pb.GetChangedTargetsRequest, str return nil } -func (c *controller) compareTargetGraphs(ctx context.Context, firstGraph, secondGraph []*pb.GetTargetGraphResponse, outputConfig *pb.OutputConfig) ([]*pb.GetChangedTargetsResponse, error) { +func (c *controller) compareTargetGraphs(logger *zap.Logger, firstGraph, secondGraph []*pb.GetTargetGraphResponse, outputConfig *pb.OutputConfig) ([]*pb.GetChangedTargetsResponse, error) { start := time.Now() scope := c.scope.SubScope("compare_target_graphs") - c.logger.Info("compareTargetGraphs: Computing differences between target graphs") + logger.Info("compareTargetGraphs: Computing differences between target graphs") // 1) Extract targets and metadata; index by canonical names indexStart := time.Now() @@ -477,7 +477,7 @@ func (c *controller) compareTargetGraphs(ctx context.Context, firstGraph, second }) } totalDuration := time.Since(start) - c.logger.Info("compareTargetGraphs: Done", + logger.Info("compareTargetGraphs: Done", zap.Duration("total_duration", totalDuration), ) scope.Timer("total_duration").Record(totalDuration) diff --git a/controller/getchangedtargets_test.go b/controller/getchangedtargets_test.go index a945572..94da60e 100644 --- a/controller/getchangedtargets_test.go +++ b/controller/getchangedtargets_test.go @@ -137,7 +137,7 @@ func TestCompareTargetGraphs(t *testing.T) { }, } - response, err := c.compareTargetGraphs(context.Background(), []*pb.GetTargetGraphResponse{firstGraph}, []*pb.GetTargetGraphResponse{secondGraph}, nil) + response, err := c.compareTargetGraphs(zap.NewNop(), []*pb.GetTargetGraphResponse{firstGraph}, []*pb.GetTargetGraphResponse{secondGraph}, nil) require.NoError(t, err) require.NotNil(t, response) } @@ -436,7 +436,7 @@ func TestCompareTargetGraphs_NewTarget_CanonicalIDs(t *testing.T) { }, }, } - res, err := c.compareTargetGraphs(context.Background(), first, second, nil) + res, err := c.compareTargetGraphs(zap.NewNop(), first, second, nil) require.NoError(t, err) require.Len(t, res, 2) cs := res[0].GetChangedTargets() @@ -508,7 +508,7 @@ func TestCompareTargetGraphs_SourceFileDirectAndPropagation(t *testing.T) { }, }, } - res, err := c.compareTargetGraphs(context.Background(), first, second, nil) + res, err := c.compareTargetGraphs(zap.NewNop(), first, second, nil) require.NoError(t, err) cs := res[0].GetChangedTargets() require.NotNil(t, cs) @@ -576,7 +576,7 @@ func TestCompareTargetGraphs_IndirectWhenNoSourceDep(t *testing.T) { }, }, } - res, err := c.compareTargetGraphs(context.Background(), first, second, nil) + res, err := c.compareTargetGraphs(zap.NewNop(), first, second, nil) require.NoError(t, err) cs := res[0].GetChangedTargets() require.NotNil(t, cs) @@ -641,7 +641,7 @@ func TestCompareTargetGraphs_DirectWhenDependenciesChanged(t *testing.T) { }, }, } - res, err := c.compareTargetGraphs(context.Background(), first, second, nil) + res, err := c.compareTargetGraphs(zap.NewNop(), first, second, nil) require.NoError(t, err) cs := res[0].GetChangedTargets() require.NotNil(t, cs) @@ -722,7 +722,7 @@ func TestCompareTargetGraphs_DirectWhenAttributesChanged(t *testing.T) { }, }, } - res, err := c.compareTargetGraphs(context.Background(), first, second, nil) + res, err := c.compareTargetGraphs(zap.NewNop(), first, second, nil) require.NoError(t, err) cs := res[0].GetChangedTargets() require.NotNil(t, cs) @@ -802,7 +802,7 @@ func TestCompareTargetGraphs_DirectWhenNewAttributeAdded(t *testing.T) { }, }, } - res, err := c.compareTargetGraphs(context.Background(), first, second, nil) + res, err := c.compareTargetGraphs(zap.NewNop(), first, second, nil) require.NoError(t, err) cs := res[0].GetChangedTargets() require.NotNil(t, cs) @@ -1048,7 +1048,7 @@ func TestCompareTargetGraphs_IndirectWhenOnlyHashChanged(t *testing.T) { }, }, } - res, err := c.compareTargetGraphs(context.Background(), first, second, nil) + res, err := c.compareTargetGraphs(zap.NewNop(), first, second, nil) require.NoError(t, err) cs := res[0].GetChangedTargets() require.NotNil(t, cs) diff --git a/controller/getchangedtargetsandedges.go b/controller/getchangedtargetsandedges.go index 09a7502..5a8ba1b 100644 --- a/controller/getchangedtargetsandedges.go +++ b/controller/getchangedtargetsandedges.go @@ -70,7 +70,7 @@ func (c *controller) GetChangedTargetsAndEdges(request *pb.GetChangedTargetsAndE cacheKey := common.GetChangedTargetsAndEdgesCachePath(request.GetFirstRevision().GetRemote(), treehash1, treehash2, request.GetRequestOptions()) cachedReader, cacheErr := storage.NewChangedTargetsAndEdgesReader(ctx, c.storage, cacheKey) if cacheErr != nil && !storage.IsNotFound(cacheErr) { - c.logger.Warn("GetChangedTargetsAndEdges: Failed to read from cache, proceeding to compute", zap.Error(cacheErr)) + logger.Warn("GetChangedTargetsAndEdges: Failed to read from cache, proceeding to compute", zap.Error(cacheErr)) } else if cachedReader != nil { var cached []*pb.GetChangedTargetsAndEdgesResponse var readErr error @@ -89,20 +89,20 @@ func (c *controller) GetChangedTargetsAndEdges(request *pb.GetChangedTargetsAndE cachedReader.Close() if readErr != nil { - c.logger.Warn("GetChangedTargetsAndEdges: Cached result is incomplete, recomputing", zap.Error(readErr)) + logger.Warn("GetChangedTargetsAndEdges: Cached result is incomplete, recomputing", zap.Error(readErr)) } else { cacheReadDuration := time.Since(cacheStart) - c.logger.Info("GetChangedTargetsAndEdges: Cache hit, streaming from storage", + logger.Info("GetChangedTargetsAndEdges: Cache hit, streaming from storage", zap.Duration("cache_read_duration", cacheReadDuration), ) scope.Counter("cache_hit").Inc(1) scope.Timer("cache_read_duration").Record(cacheReadDuration) if err := sendWithDistanceFilterForEdges(stream, cached, request.GetOutputConfig()); err != nil { - c.logger.Error("GetChangedTargetsAndEdges: Failed to send cached response", zap.Error(err)) + logger.Error("GetChangedTargetsAndEdges: Failed to send cached response", zap.Error(err)) return err } totalDuration := time.Since(start) - c.logger.Info("GetChangedTargetsAndEdges: Successfully streamed from cache", + logger.Info("GetChangedTargetsAndEdges: Successfully streamed from cache", zap.Duration("total_duration", totalDuration), ) scope.Timer("total_duration").Record(totalDuration) @@ -184,7 +184,7 @@ func (c *controller) GetChangedTargetsAndEdges(request *pb.GetChangedTargetsAndE } graphFetchDuration := time.Since(graphFetchStart) - c.logger.Info("GetChangedTargetsAndEdges: Both graphs fetched", + logger.Info("GetChangedTargetsAndEdges: Both graphs fetched", zap.Duration("graph_fetch_duration", graphFetchDuration), ) scope.Timer("graph_fetch_duration").Record(graphFetchDuration) @@ -213,16 +213,16 @@ func (c *controller) GetChangedTargetsAndEdges(request *pb.GetChangedTargetsAndE jobs[1].graphStreamChunks = nil compareStart := time.Now() - responses, err := c.compareTargetGraphsAndEdges(ctx, firstGraph, secondGraph, request.GetOutputConfig()) + responses, err := c.compareTargetGraphsAndEdges(logger, firstGraph, secondGraph, request.GetOutputConfig()) // Allow GC of raw graph data while the caching goroutine runs. firstGraph = nil secondGraph = nil if err != nil { - c.logger.Error("GetChangedTargetsAndEdges: Failed to compare target graphs", zap.Error(err)) + logger.Error("GetChangedTargetsAndEdges: Failed to compare target graphs", zap.Error(err)) return fmt.Errorf("failed to compare target graphs: %w", err) } compareDuration := time.Since(compareStart) - c.logger.Info("GetChangedTargetsAndEdges: Target graphs compared", + logger.Info("GetChangedTargetsAndEdges: Target graphs compared", zap.Duration("compare_duration", compareDuration), ) scope.Timer("compare_duration").Record(compareDuration) @@ -235,21 +235,21 @@ func (c *controller) GetChangedTargetsAndEdges(request *pb.GetChangedTargetsAndE if treehash1 != "" && treehash2 != "" { cacheKey := common.GetChangedTargetsAndEdgesCachePath(request.GetFirstRevision().GetRemote(), treehash1, treehash2, request.GetRequestOptions()) if writeErr := storage.WriteChangedTargetsAndEdgesStream(cacheCtx, c.storage, cacheKey, responses); writeErr != nil { - c.logger.Warn("GetChangedTargetsAndEdges: Failed to cache result", zap.Error(writeErr)) + logger.Warn("GetChangedTargetsAndEdges: Failed to cache result", zap.Error(writeErr)) } } }() sendStart := time.Now() if err := sendWithDistanceFilterForEdges(stream, responses, request.GetOutputConfig()); err != nil { - c.logger.Error("GetChangedTargetsAndEdges: Failed to send response", zap.Error(err)) + logger.Error("GetChangedTargetsAndEdges: Failed to send response", zap.Error(err)) return err } sendDuration := time.Since(sendStart) scope.Timer("send_duration").Record(sendDuration) totalDuration := time.Since(start) - c.logger.Info("GetChangedTargetsAndEdges: Successfully processed request", + logger.Info("GetChangedTargetsAndEdges: Successfully processed request", zap.Duration("send_duration", sendDuration), zap.Duration("total_duration", totalDuration), ) @@ -257,10 +257,10 @@ func (c *controller) GetChangedTargetsAndEdges(request *pb.GetChangedTargetsAndE return nil } -func (c *controller) compareTargetGraphsAndEdges(ctx context.Context, firstGraph, secondGraph []*pb.GetTargetGraphResponse, outputConfig *pb.OutputConfig) ([]*pb.GetChangedTargetsAndEdgesResponse, error) { +func (c *controller) compareTargetGraphsAndEdges(logger *zap.Logger, firstGraph, secondGraph []*pb.GetTargetGraphResponse, outputConfig *pb.OutputConfig) ([]*pb.GetChangedTargetsAndEdgesResponse, error) { start := time.Now() scope := c.scope.SubScope("compare_target_graphs_and_edges") - c.logger.Info("compareTargetGraphsAndEdges: Computing differences between target graphs") + logger.Info("compareTargetGraphsAndEdges: Computing differences between target graphs") // 1) Extract targets and metadata; index by canonical names. firstTargetsByID, firstMetadata := getTargetsAndMetadata(firstGraph) @@ -394,7 +394,7 @@ func (c *controller) compareTargetGraphsAndEdges(ctx context.Context, firstGraph // 5) Compute BFS distances if requested. if outputConfig.GetComputeDistances() { - computeDistances(c.logger, changedByName, secondByName, secondMetadata, outputConfig.GetMaxDistance()) + computeDistances(logger, changedByName, secondByName, secondMetadata, outputConfig.GetMaxDistance()) } // 6) Collect changed targets. @@ -459,7 +459,7 @@ func (c *controller) compareTargetGraphsAndEdges(ctx context.Context, firstGraph // 10) Build canonical metadata. totalDuration := time.Since(start) - c.logger.Info("compareTargetGraphsAndEdges: Done", + logger.Info("compareTargetGraphsAndEdges: Done", zap.Duration("total_duration", totalDuration), ) scope.Timer("total_duration").Record(totalDuration) diff --git a/controller/getchangedtargetsandedges_test.go b/controller/getchangedtargetsandedges_test.go index 10b2002..a4363d4 100644 --- a/controller/getchangedtargetsandedges_test.go +++ b/controller/getchangedtargetsandedges_test.go @@ -258,7 +258,7 @@ func TestCompareTargetGraphsAndEdges_Empty(t *testing.T) { }} } - res, err := c.compareTargetGraphsAndEdges(context.Background(), emptyGraph(), emptyGraph(), nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), emptyGraph(), emptyGraph(), nil) require.NoError(t, err) require.Len(t, res, 2) cte, _ := collectCTEResponses(res) @@ -298,7 +298,7 @@ func TestCompareTargetGraphsAndEdges_AddedTarget(t *testing.T) { }, } - res, err := c.compareTargetGraphsAndEdges(context.Background(), first, second, nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), first, second, nil) require.NoError(t, err) cte, meta := collectCTEResponses(res) @@ -340,7 +340,7 @@ func TestCompareTargetGraphsAndEdges_RemovedTarget(t *testing.T) { }}, }} - res, err := c.compareTargetGraphsAndEdges(context.Background(), first, second, nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), first, second, nil) require.NoError(t, err) cte, meta := collectCTEResponses(res) @@ -395,7 +395,7 @@ func TestCompareTargetGraphsAndEdges_NewEdge(t *testing.T) { }, } - res, err := c.compareTargetGraphsAndEdges(context.Background(), first, second, nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), first, second, nil) require.NoError(t, err) cte, meta := collectCTEResponses(res) @@ -446,7 +446,7 @@ func TestCompareTargetGraphsAndEdges_RemovedEdge(t *testing.T) { }, } - res, err := c.compareTargetGraphsAndEdges(context.Background(), first, second, nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), first, second, nil) require.NoError(t, err) cte, meta := collectCTEResponses(res) @@ -499,7 +499,7 @@ func TestCompareTargetGraphsAndEdges_ChangedTargetClassification(t *testing.T) { }, } - res, err := c.compareTargetGraphsAndEdges(context.Background(), first, second, nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), first, second, nil) require.NoError(t, err) cte, meta := collectCTEResponses(res) @@ -546,7 +546,7 @@ func TestCompareTargetGraphsAndEdges_UnchangedTargetNotReturned(t *testing.T) { }, } - res, err := c.compareTargetGraphsAndEdges(context.Background(), first, second, nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), first, second, nil) require.NoError(t, err) cte, _ := collectCTEResponses(res) assert.Empty(t, cte.GetChangedTargets()) @@ -580,7 +580,7 @@ func TestCompareTargetGraphsAndEdges_EdgePreservedWhenTargetUnchanged(t *testing } } - res, err := c.compareTargetGraphsAndEdges(context.Background(), + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), mkGraph(1, 2, "hA", "hB"), mkGraph(10, 20, "hA", "hB"), nil, @@ -632,7 +632,7 @@ func TestCompareTargetGraphsAndEdges_CanonicalIDs(t *testing.T) { }, } - res, err := c.compareTargetGraphsAndEdges(context.Background(), first, second, nil) + res, err := c.compareTargetGraphsAndEdges(zap.NewNop(), first, second, nil) require.NoError(t, err) cte, meta := collectCTEResponses(res) diff --git a/core/workspace/gitrequest.go b/core/workspace/gitrequest.go index 0ef8f96..eb23733 100644 --- a/core/workspace/gitrequest.go +++ b/core/workspace/gitrequest.go @@ -20,6 +20,7 @@ import ( "path/filepath" "github.com/uber/tango/core/git" + "go.uber.org/zap" ) type gitRequest struct { @@ -27,9 +28,10 @@ type gitRequest struct { requestID string baseRef string commit string + logger *zap.SugaredLogger } -func NewGitRequest(git git.Interface, requestPath string, baseRef string, commit string) Request { +func NewGitRequest(git git.Interface, requestPath string, baseRef string, commit string, logger *zap.SugaredLogger) Request { // get the last part of the request path requestID := filepath.Base(requestPath) return &gitRequest{ @@ -37,14 +39,17 @@ func NewGitRequest(git git.Interface, requestPath string, baseRef string, commit requestID: requestID, baseRef: baseRef, commit: commit, + logger: logger, } } // Apply applies the change request to the workspace. func (r *gitRequest) Apply(ctx context.Context) error { + r.logger.Infow("gitRequest: Applying PR", zap.String("request_id", r.requestID), zap.String("base_ref", r.baseRef), zap.String("commit", r.commit)) ref := fmt.Sprintf("+pull/%s/head:pull/%s/head", r.requestID, r.requestID) err := r.git.Fetch(ctx, "origin", ref, "--force", "--no-tags") if err != nil { + r.logger.Errorw("gitRequest: Failed to fetch PR", zap.String("request_id", r.requestID), zap.Error(err)) return err } if r.commit != "" { @@ -58,19 +63,24 @@ func (r *gitRequest) Apply(ctx context.Context) error { } patch, err := r.git.Diff(ctx, r.baseRef, fmt.Sprintf("pull/%s/head", r.requestID), "--binary", "--merge-base") if err != nil { + r.logger.Errorw("gitRequest: Failed to compute diff", zap.String("request_id", r.requestID), zap.Error(err)) return err } err = r.git.ApplyPatch(ctx, patch) if err != nil { + r.logger.Errorw("gitRequest: Failed to apply patch", zap.String("request_id", r.requestID), zap.Error(err)) return err } err = r.git.Commit(ctx, fmt.Sprintf("Applied PR: %s", r.requestID), "--allow-empty") if err != nil { + r.logger.Errorw("gitRequest: Failed to commit", zap.String("request_id", r.requestID), zap.Error(err)) return err } err = r.git.SubmoduleUpdate(ctx) if err != nil { + r.logger.Errorw("gitRequest: Failed to update submodules", zap.String("request_id", r.requestID), zap.Error(err)) return err } + r.logger.Infow("gitRequest: Successfully applied PR", zap.String("request_id", r.requestID)) return nil } diff --git a/core/workspace/gitrequest_test.go b/core/workspace/gitrequest_test.go index 0dfe548..d0bc84e 100644 --- a/core/workspace/gitrequest_test.go +++ b/core/workspace/gitrequest_test.go @@ -23,15 +23,16 @@ import ( "github.com/stretchr/testify/require" gitmock "github.com/uber/tango/core/git/gitmock" "go.uber.org/mock/gomock" + "go.uber.org/zap" ) func TestNewGitRequest_InvalidPath(t *testing.T) { - req := NewGitRequest(nil, "invalid", "baseRef", "") + req := NewGitRequest(nil, "invalid", "baseRef", "", zap.NewNop().Sugar()) require.NotNil(t, req) } func TestNewGitRequest_ExtractsID(t *testing.T) { - r := NewGitRequest(nil, "/org/repo/pull/456", "baseRef", "abc123") + r := NewGitRequest(nil, "/org/repo/pull/456", "baseRef", "abc123", zap.NewNop().Sugar()) gr, ok := r.(*gitRequest) assert.True(t, ok, "expected *gitRequest, got %T", r) assert.Equal(t, "456", gr.requestID) @@ -48,7 +49,7 @@ func TestGitRequest_Apply_CommitIsAncestor_Success(t *testing.T) { git.EXPECT().ApplyPatch(gomock.Any(), gomock.Any()).Return(nil) git.EXPECT().Commit(gomock.Any(), gomock.Any(), gomock.Any()).Return(nil) git.EXPECT().SubmoduleUpdate(gomock.Any()).Return(nil) - req := NewGitRequest(git, "123", "baseRef", "deadbeef") + req := NewGitRequest(git, "123", "baseRef", "deadbeef", zap.NewNop().Sugar()) err := req.Apply(context.Background()) require.NoError(t, err) } @@ -58,7 +59,7 @@ func TestGitRequest_Apply_CommitNotAncestor_ReturnsError(t *testing.T) { git := gitmock.NewMockInterface(ctrl) git.EXPECT().Fetch(gomock.Any(), "origin", gomock.Any(), gomock.Any()).Return(nil) git.EXPECT().IsAncestor(gomock.Any(), "deadbeef", "pull/456/head").Return(false, nil) - req := NewGitRequest(git, "456", "baseRef", "deadbeef") + req := NewGitRequest(git, "456", "baseRef", "deadbeef", zap.NewNop().Sugar()) err := req.Apply(context.Background()) require.Error(t, err) assert.Contains(t, err.Error(), "deadbeef") @@ -69,7 +70,7 @@ func TestGitRequest_Apply_IsAncestorFails_ReturnsError(t *testing.T) { git := gitmock.NewMockInterface(ctrl) git.EXPECT().Fetch(gomock.Any(), "origin", gomock.Any(), gomock.Any()).Return(nil) git.EXPECT().IsAncestor(gomock.Any(), "deadbeef", "pull/789/head").Return(false, errors.New("ancestor check failed")) - req := NewGitRequest(git, "789", "baseRef", "deadbeef") + req := NewGitRequest(git, "789", "baseRef", "deadbeef", zap.NewNop().Sugar()) err := req.Apply(context.Background()) require.Error(t, err) assert.Contains(t, err.Error(), "failed to read PR commit history") diff --git a/core/workspace/request.go b/core/workspace/request.go index 120e3f6..4f05226 100644 --- a/core/workspace/request.go +++ b/core/workspace/request.go @@ -19,6 +19,7 @@ import ( "net/url" "github.com/uber/tango/core/git" + "go.uber.org/zap" ) // Request represents a change request type, like Phabricator diff or Github pull request @@ -27,14 +28,14 @@ type Request interface { } // NewRequest creates a new request based on the request URL. -func NewRequest(rawURL string, g git.Interface, baseRef string, commit string) (Request, error) { +func NewRequest(rawURL string, g git.Interface, baseRef string, commit string, logger *zap.SugaredLogger) (Request, error) { u, err := url.Parse(rawURL) if err != nil { return nil, err } switch u.Scheme { case "github": - return NewGitRequest(g, u.Path, baseRef, commit), nil + return NewGitRequest(g, u.Path, baseRef, commit, logger), nil } return nil, nil } diff --git a/core/workspace/request_test.go b/core/workspace/request_test.go index 2a8f593..68f431e 100644 --- a/core/workspace/request_test.go +++ b/core/workspace/request_test.go @@ -19,13 +19,14 @@ import ( "github.com/stretchr/testify/require" "github.com/uber/tango/core/git" + "go.uber.org/zap" ) func TestNewRequest_Github_Success(t *testing.T) { rawURL := "github://org/repo/pull/123" var g git.Interface = nil - req, err := NewRequest(rawURL, g, "baseRef", "abc123") + req, err := NewRequest(rawURL, g, "baseRef", "abc123", zap.NewNop().Sugar()) require.NoError(t, err) require.NotNil(t, req) @@ -40,7 +41,7 @@ func TestNewRequest_InvalidURL(t *testing.T) { rawURL := "://bad" var g git.Interface = nil - req, err := NewRequest(rawURL, g, "baseRef", "") + req, err := NewRequest(rawURL, g, "baseRef", "", zap.NewNop().Sugar()) require.Error(t, err) require.Nil(t, req) } diff --git a/core/workspace/workspace.go b/core/workspace/workspace.go index 349ad22..a084fea 100644 --- a/core/workspace/workspace.go +++ b/core/workspace/workspace.go @@ -77,7 +77,10 @@ func (w *workspace) Checkout(ctx context.Context, remote string, ref string) err _, err := w.git.RevParse(ctx, commit) // commit is not present in the repository if err != nil { - w.logger.Warnf("git rev-parse %s failed with error %v, attempt to fetch from remote", commit, err) + w.logger.Warnw("git rev-parse failed, attempting to fetch from remote", + zap.String("remote", remote), + zap.String("ref", ref), + zap.Error(err)) err = w.git.Fetch(ctx, remote, ref) if err != nil { return err diff --git a/orchestrator/native_orchestrator.go b/orchestrator/native_orchestrator.go index 784917e..d21af32 100644 --- a/orchestrator/native_orchestrator.go +++ b/orchestrator/native_orchestrator.go @@ -68,10 +68,13 @@ func NewNativeOrchestrator(p Params) Orchestrator { // GetTargetGraph is used to compute the target graph locally. // It leases a workspace, checks out the base revision, applies the change requests, and computes the target graph. func (b *nativeOrchestrator) GetTargetGraph(ctx context.Context, param GetTargetGraphParam) (storage.GraphReader, error) { + logger := b.logger.With(zap.Any("build_description", param.Req.BuildDescription)) + logger.Infow("GetTargetGraph: Processing request") + // parse the config file cfg, err := config.Parse(b.configFilePath) if err != nil { - b.logger.Errorw("getGraph: Error parsing config file", zap.String("configFilePath", b.configFilePath), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error parsing config file", zap.String("configFilePath", b.configFilePath), zap.Error(err)) return nil, err } remote := param.Req.BuildDescription.Remote @@ -81,6 +84,7 @@ func (b *nativeOrchestrator) GetTargetGraph(ctx context.Context, param GetTarget } ws, err := b.repoManager.Lease(ctx, *param.Req.BuildDescription) if err != nil { + logger.Errorw("GetTargetGraph: Error leasing workspace", zap.Error(err)) return nil, err } defer func() { @@ -88,14 +92,16 @@ func (b *nativeOrchestrator) GetTargetGraph(ctx context.Context, param GetTarget if err != nil { // clean up the workspace if release fails. if removeErr := os.RemoveAll(ws.Path()); removeErr != nil { - b.logger.Errorf("failed to remove workspace: %v", removeErr) + logger.Errorf("GetTargetGraph: Failed to remove workspace: %v", removeErr) } } }() err = ws.Checkout(ctx, param.Req.BuildDescription.Remote, param.Req.BuildDescription.BaseSha) if err != nil { + logger.Errorw("GetTargetGraph: Error checking out base revision", zap.Error(err)) return nil, err } + logger.Infow("GetTargetGraph: Checked out base revision") requests := make([]workspace.Request, 0, len(param.Req.BuildDescription.Requests)) factory := b.gitFactory @@ -105,38 +111,41 @@ func (b *nativeOrchestrator) GetTargetGraph(ctx context.Context, param GetTarget gitModule := factory(ws.Path()) for _, req := range param.Req.BuildDescription.Requests { - request, err := workspace.NewRequest(req.GetUrl(), gitModule, param.Req.BuildDescription.BaseSha, req.GetCommit()) + request, err := workspace.NewRequest(req.GetUrl(), gitModule, param.Req.BuildDescription.BaseSha, req.GetCommit(), logger) if err != nil { - b.logger.Errorw("getGraph: Error creating request", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error creating request", zap.String("url", req.GetUrl()), zap.Error(err)) return nil, err } requests = append(requests, request) } err = ws.ApplyRequests(ctx, requests) if err != nil { - b.logger.Errorw("getGraph: Error applying requests to workspace", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error applying requests to workspace", zap.Error(err)) return nil, err } + logger.Infow("GetTargetGraph: Applied requests", zap.Int("request_count", len(requests))) + // Compute the treehash and download the target graph from storage if exists. treehash, err := gitModule.RevParse(ctx, "HEAD^{tree}") if err != nil { - b.logger.Errorw("Treehash computation failed", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Treehash computation failed", zap.Error(err)) return nil, err } treehashPath := common.GetGraphByTreeHash(param.Req.BuildDescription.Remote, treehash, param.Req.BuildDescription.GetStrategy(), param.Req.GetRequestOptions()) if !param.BypassCache { graphReader, err := storage.NewGraphReader(ctx, b.storage, treehashPath) if err == nil { + logger.Infow("GetTargetGraph: Cache hit on treehash", zap.String("treehash", treehash)) return graphReader, nil } if !storage.IsNotFound(err) { // Other errors (network, infra issues) should be retried - b.logger.Errorw("getGraph: Storage error", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Storage error", zap.Error(err)) return nil, err } - b.logger.Infow("getGraph: treehash not found. Computing the target graph.", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Infow("GetTargetGraph: Treehash not found, computing target graph", zap.String("treehash", treehash)) } else { - b.logger.Infow("getGraph: bypass_cache=true. Skipping cache lookup, computing the target graph.", zap.Any("request build description", param.Req.BuildDescription)) + logger.Infow("GetTargetGraph: bypass_cache=true, computing target graph") } // Compute the target graph and store it in storage. runner := b.graphRunner @@ -148,7 +157,7 @@ func (b *nativeOrchestrator) GetTargetGraph(ctx context.Context, param GetTarget QueryTimeout: time.Duration(repoCfg.QueryTimeout) * time.Second, }) if err != nil { - b.logger.Errorw("getGraph: Error creating bazel client", zap.Error(err)) + logger.Errorw("GetTargetGraph: Error creating bazel client", zap.Error(err)) return nil, err } // Use default native graph runner @@ -161,17 +170,17 @@ func (b *nativeOrchestrator) GetTargetGraph(ctx context.Context, param GetTarget } result, err := runner.Compute(ctx, ws) if err != nil { - b.logger.Errorw("getGraph: Error computing target graph", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error computing target graph", zap.Error(err)) return nil, err } responses, err := common.ResultToGetTargetGraphResponse(result) if err != nil { - b.logger.Errorw("getGraph: Error converting target graph to GetTargetGraphResponse", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error converting target graph to response", zap.Error(err)) return nil, err } err = storage.WriteGraphStream(ctx, b.storage, treehashPath, responses) if err != nil { - b.logger.Errorw("getGraph: Error writing target graph to storage", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error writing target graph to storage", zap.Error(err)) return nil, err } // Map build description to treehash for future lookup. @@ -179,13 +188,14 @@ func (b *nativeOrchestrator) GetTargetGraph(ctx context.Context, param GetTarget treehashReader := bytes.NewReader([]byte(treehash)) err = b.storage.Put(ctx, storage.UploadRequest{Key: treehashCachePath, Reader: treehashReader}) if err != nil { - b.logger.Errorw("getGraph: Error reading target graph from storage", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error storing treehash mapping", zap.Error(err)) return nil, err } graphReader, err := storage.NewGraphReader(ctx, b.storage, treehashPath) if err != nil { - b.logger.Errorw("getGraph: Error creating graph reader", zap.Any("request build description", param.Req.BuildDescription), zap.Error(err)) + logger.Errorw("GetTargetGraph: Error creating graph reader", zap.Error(err)) return nil, err } + logger.Infow("GetTargetGraph: Done computing and storing target graph", zap.String("treehash", treehash)) return graphReader, nil }