pr2960.diff

diff --git a/pkg/adapter/adapter.go b/pkg/adapter/adapter.go
index b38efff19..89cd3a8d0 100644
--- a/pkg/adapter/adapter.go
+++ b/pkg/adapter/adapter.go
@@ -173,13 +173,14 @@ 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) {
-		var logger *zap.SugaredLogger
-		start := time.Now().UnixMilli()
+		start := time.Now()
 		eventID := getProviderEventIDFromHeader(request.Header)
-		logger = l.logger.With("event-id", eventID)
+		logger := l.logger.With("event-id", eventID)
+		defer func() {
+			logger.Infof("controller responded to event %s in %dms", eventID, time.Since(start).Milliseconds())
+		}()
 		if request.Method != http.MethodPost {
 			l.writeResponse(response, http.StatusOK, "ok")
-			logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 			return
 		}
 
@@ -188,7 +189,6 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 		if err != nil {
 			logger.Errorf("failed to read body : %v", err)
 			response.WriteHeader(http.StatusInternalServerError)
-			logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 			return
 		}
 
@@ -197,7 +197,6 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 			if err := json.Unmarshal(payload, &eventBody); err != nil {
 				logger.Errorf("Invalid event body format format: %s", err)
 				response.WriteHeader(http.StatusBadRequest)
-				logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 				return
 			}
 		}
@@ -220,17 +219,14 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 		if detected {
 			if configuring && err == nil {
 				l.writeResponse(response, http.StatusCreated, "configured")
-				logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 				return
 			}
 			if configuring && err != nil {
 				logger.Errorf("repository auto-configure has failed, err: %v", err)
 				l.writeResponse(response, http.StatusOK, "failed to configure")
-				logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 				return
 			}
 			l.writeResponse(response, http.StatusOK, "skipped event")
-			logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 			return
 		}
 
@@ -240,20 +236,22 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 				l.writeResponse(response, http.StatusBadRequest, err.Error())
 			}
 			logger.Errorf("error processing incoming webhook: %v", err)
-			logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 			return
 		}
 
+		var providerLogger *zap.SugaredLogger
 		if isIncoming {
-			gitProvider, logger, err = l.processIncoming(event, targettedRepo)
+			gitProvider, providerLogger, err = l.processIncoming(event, targettedRepo)
 		} else {
-			gitProvider, logger, err = l.detectProvider(request, string(payload))
+			gitProvider, providerLogger, err = l.detectProvider(request, string(payload))
+		}
+		if providerLogger != nil {
+			logger = providerLogger
 		}
 
 		// figure out which provider request coming from
 		if err != nil || gitProvider == nil {
 			l.writeResponse(response, http.StatusOK, err.Error())
-			logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 			return
 		}
 		gitProvider.SetPacInfo(&pacInfo)
@@ -281,9 +279,9 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 		localRequest := request.Clone(request.Context())
 
 		go func() {
-			eventHandlerStart := time.Now().UnixMilli()
+			eventHandlerStart := time.Now()
 			defer func() {
-				logger.Infof("event %s processed in %dms", eventID, time.Now().UnixMilli()-eventHandlerStart)
+				logger.Infof("event %s processed in %dms", eventID, time.Since(eventHandlerStart).Milliseconds())
 				span.End()
 			}()
 			err := s.handleEvent(tracedCtx, localRequest)
@@ -293,7 +291,6 @@ func (l listener) handleEvent(ctx context.Context) http.HandlerFunc {
 		}()
 
 		l.writeResponse(response, http.StatusAccepted, "accepted")
-		logger.Infof("controller responded to event %s in %dms", eventID, time.Now().UnixMilli()-start)
 	}
 }
 
diff --git a/pkg/adapter/adapter_test.go b/pkg/adapter/adapter_test.go
index 6c7e609df..d1e63f25e 100644
--- a/pkg/adapter/adapter_test.go
+++ b/pkg/adapter/adapter_test.go
@@ -191,7 +191,7 @@ func TestHandleEvent(t *testing.T) {
 			event:          event,
 			statusCode:     202,
 			eventUUID:      "1234567890",
-			wantLogSnippet: "controller responded to event 1234567890 in 0ms",
+			wantLogSnippet: "controller responded to event 1234567890 in",
 		},
 	}
 
@@ -216,7 +216,17 @@ func TestHandleEvent(t *testing.T) {
 			defer resp.Body.Close()
 
 			if tn.wantLogSnippet != "" {
-				assert.Assert(t, logCatcher.FilterMessageSnippet(tn.wantLogSnippet).Len() > 0, logCatcher.All())
+				// the timing log line is written after the response is sent, so
+				// wait for the record instead of racing the handler.
+				found := false
+				for range 100 {
+					if logCatcher.FilterMessageSnippet(tn.wantLogSnippet).Len() > 0 {
+						found = true
+						break
+					}
+					time.Sleep(10 * time.Millisecond)
+				}
+				assert.Assert(t, found, logCatcher.All())
 			}
 			assert.Equal(t, resp.StatusCode, tn.statusCode)
 		})
diff --git a/pkg/adapter/incoming.go b/pkg/adapter/incoming.go
index 3b06a5fb1..9f1df431e 100644
--- a/pkg/adapter/incoming.go
+++ b/pkg/adapter/incoming.go
@@ -222,7 +222,7 @@ func (l *listener) processIncoming(event *info.Event, targetRepo *v1alpha1.Repos
 	// can a git ssh URL be a Repo URL? I don't think this will even ever work
 	org, repo, err := formatting.GetRepoOwnerSplitted(targetRepo.Spec.URL)
 	if err != nil {
-		return nil, nil, err
+		return nil, l.logger.With("namespace", targetRepo.Namespace), err
 	}
 	event.Organization = org
 	event.Repository = repo
diff --git a/pkg/adapter/incoming_test.go b/pkg/adapter/incoming_test.go
index 1834f029d..48434425a 100644
--- a/pkg/adapter/incoming_test.go
+++ b/pkg/adapter/incoming_test.go
@@ -1025,7 +1025,8 @@ func TestListenerProcessIncoming(t *testing.T) {
 				run: client, kint: kint, logger: logger,
 			}
 			event := info.NewEvent()
-			pintf, _, err := l.processIncoming(event, tt.targetRepo)
+			pintf, eventLogger, err := l.processIncoming(event, tt.targetRepo)
+			assert.Assert(t, eventLogger != nil, "processIncoming must always return a usable logger")
 			if tt.wantErr {
 				assert.Assert(t, err != nil)
 				return