feat(adapter): log time taken by controller to process webhook events

Log the duration from when a webhook request is received until the
controller responds, and separately the async event processing time.
The event ID is extracted from provider-specific headers (GitHub,
GitLab, Gitea, Bitbucket Cloud/DC) for log correlation.

https://redhat.atlassian.net/browse/SRVKP-14040

Signed-off-by: Zaki Shaikh <zashaikh@redhat.com>

Author: zakisk

pkg/adapter/adapter.go

@@ -173,6 +173,12 @@ func (l *listener) Start(ctx context.Context) error {
 
 func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 	return func(response http.ResponseWriter, request *http.Request) {
+		start := time.Now().UnixMilli()
+		eventID := getProviderEventIDFromHeader(request.Header)
+		eventLogger := l.logger.With("event-id", eventID)
+		defer func() {
+			eventLogger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
+		}()
 		if request.Method != http.MethodPost {
 			l.writeResponse(response, http.StatusOK, "ok")
 			return
@@ -270,7 +276,11 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 		localRequest := request.Clone(request.Context())
 
 		go func() {
-			defer span.End()
+			eventHandlerStart := time.Now().UnixMilli()
+			defer func() {
+				logger.Infof("event %s processed in %dms", eventID, time.Now().UnixMilli()-eventHandlerStart)
+				span.End()
+			}()
 			err := s.handleEvent(tracedCtx, localRequest)
 			if err != nil {
 				span.RecordError(err)
@@ -281,6 +291,30 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 	}
 }
 
+func getProviderEventIDFromHeader(header http.Header) string {
+	if header.Get("X-GitHub-Delivery") != "" {
+		return header.Get("X-GitHub-Delivery")
+	}
+	// For Gitea
+	if header.Get("X-Gitea-Delivery") != "" {
+		return header.Get("X-Gitea-Delivery")
+	}
+	// For GitLab
+	if header.Get("X-Gitlab-Event-UUID") != "" {
+		return header.Get("X-Gitlab-Event-UUID")
+	}
+	// For Bitbucket cloud
+	if header.Get("X-Request-UUID") != "" {
+		return header.Get("X-Request-UUID")
+	}
+	// For Bitbucket data center
+	if header.Get("X-Request-Id") != "" {
+		return header.Get("X-Request-Id")
+	}
+	// return nil UUID to indicate that git provider is unknown
+	return "00000000-0000-0000-0000-000000000000"
+}
+
 func (l listener) processRes(processEvent bool, provider provider.Interface, logger *zap.SugaredLogger, skipReason string, err error) (provider.Interface, *zap.SugaredLogger, error) {
 	if processEvent {
 		if provider == nil {

pkg/adapter/adapter_test.go

@@ -132,6 +132,7 @@ func TestHandleEvent(t *testing.T) {
 		name           string
 		event          []byte
 		eventType      string
+		eventUUID      string
 		requestType    string
 		statusCode     int
 		wantLogSnippet string
@@ -183,6 +184,15 @@ func TestHandleEvent(t *testing.T) {
 			event:       event,
 			statusCode:  200,
 		},
+		{
+			name:           "event time logged",
+			requestType:    "POST",
+			eventType:      "push",
+			event:          event,
+			statusCode:     202,
+			eventUUID:      "1234567890",
+			wantLogSnippet: "controller responded to event 1234567890",
+		},
 	}
 
 	for _, tt := range tests {
@@ -197,6 +207,10 @@ func TestHandleEvent(t *testing.T) {
 			assert.NilError(t, err)
 			req.Header.Set("X-Github-Event", tn.eventType)
 
+			if tn.eventUUID != "" {
+				req.Header.Set("X-GitHub-Delivery", tn.eventUUID)
+			}
+
 			resp, err := http.DefaultClient.Do(req)
 			assert.NilError(t, err)
 			defer resp.Body.Close()
@@ -326,3 +340,64 @@ func TestStartGracefulShutdown(t *testing.T) {
 		t.Fatal("listener did not shut down after context cancellation")
 	}
 }
+
+func TestGetProviderEventIDFromHeader(t *testing.T) {
+	tests := []struct {
+		name   string
+		header map[string][]string
+		want   string
+	}{
+		{
+			name: "github event",
+			header: map[string][]string{
+				"X-GitHub-Delivery": {"abcd"},
+			},
+			want: "abcd",
+		},
+		{
+			name: "gitea event",
+			header: map[string][]string{
+				"X-Gitea-Delivery": {"abcd"},
+			},
+			want: "abcd",
+		},
+		{
+			name: "gitlab event",
+			header: map[string][]string{
+				"X-Gitlab-Event-UUID": {"abcd"},
+			},
+			want: "abcd",
+		},
+		{
+			name: "bitbucket cloud event",
+			header: map[string][]string{
+				"X-Request-UUID": {"abcd"},
+			},
+			want: "abcd",
+		},
+		{
+			name: "bitbucket data center event",
+			header: map[string][]string{
+				"X-Request-Id": {"abcd"},
+			},
+			want: "abcd",
+		},
+		{
+			name:   "unknown git provider event",
+			header: map[string][]string{},
+			want:   "00000000-0000-0000-0000-000000000000",
+		},
+	}
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			header := http.Header{}
+			for key, values := range tt.header {
+				for _, value := range values {
+					header.Set(key, value)
+				}
+			}
+			got := getProviderEventIDFromHeader(header)
+			assert.Equal(t, got, tt.want)
+		})
+	}
+}

test/github_pullrequest_test.go

@@ -787,6 +787,26 @@ func TestGithubGHEPullRequestCELJoin(t *testing.T) {
 	assert.NilError(t, err)
 }
 
+func TestGithubGHEPullRequestEventTimeLogged(t *testing.T) {
+	ctx := context.Background()
+	g := &tgithub.PRTest{
+		Label:     "Github PullRequest Event Time Logged",
+		YamlFiles: []string{"testdata/pipelinerun.yaml"},
+		GHE:       true,
+	}
+	g.RunPullRequest(ctx, t)
+	defer g.TearDown(ctx, t)
+
+	globalNs, _, err := params.GetInstallLocation(ctx, g.Cnx)
+	assert.NilError(t, err)
+	ctx = info.StoreNS(ctx, globalNs)
+
+	reg := regexp.MustCompile("controller responded to event .* in .*ms")
+	maxLines := int64(1000)
+	err = twait.RegexpMatchingInControllerLog(ctx, g.Cnx, *reg, 20, "ghe-controller", &maxLines, nil)
+	assert.NilError(t, err)
+}
+
 // Local Variables:
 // compile-command: "go test -tags=e2e -v -info TestGithubPullRequest$ ."
 // End: