fix: review feedback

Author: Swop

internal/config/load_test.go

@@ -14,15 +14,15 @@ const (
   - owner: test
     name: repo0
     base_ref: main
-    stabilize_duration: 300
+    stabilize_duration_seconds: 300
     expected_request_count: 4
-    ttl: 20
+    ttl_seconds: 20
   - owner: test
     name: repo1
     base_ref: develop
-    stabilize_duration: 100
+    stabilize_duration_seconds: 100
     expected_request_count: 5
-    ttl: 30`
+    ttl_seconds: 30`
 )
 
 func TestLoadServerConfig(t *testing.T) {

internal/config/server/latest/server_schema.go

@@ -10,7 +10,7 @@ type GithubRepositoryConfig struct {
 	Owner                string `yaml:"owner"`
 	Name                 string `yaml:"name"`
 	BaseRef              string `yaml:"base_ref"`
-	StabilizeDuration    int    `yaml:"stabilize_duration"`
-	TTL                  int    `yaml:"ttl"`
+	StabilizeDuration    int    `yaml:"stabilize_duration_seconds"`
+	TTL                  int    `yaml:"ttl_seconds"`
 	ExpectedRequestCount int    `yaml:"expected_request_count"`
 }

internal/lease/leaseprovider.go

@@ -62,7 +62,7 @@ type leaseProviderImpl struct {
 	mutex sync.Mutex
 	opts  ProviderOpts
 
-	lastUpdatedAt *time.Time
+	lastUpdatedAt time.Time
 
 	acquired *Request
 	known    map[string]*Request
@@ -71,14 +71,14 @@ type leaseProviderImpl struct {
 func NewLeaseProvider(opts ProviderOpts) Provider {
 	return &leaseProviderImpl{
 		opts:          opts,
-		lastUpdatedAt: nil,
+		lastUpdatedAt: time.Now(),
 		known:         make(map[string]*Request),
 	}
 }
 
 func (lp *leaseProviderImpl) MarshalJSON() ([]byte, error) {
 	return json.Marshal(&struct {
-		LastUpdatedAt *time.Time          `json:"last_updated_at"`
+		LastUpdatedAt time.Time           `json:"last_updated_at"`
 		Acquired      *Request            `json:"acquired"`
 		Known         map[string]*Request `json:"known"`
 	}{
@@ -148,7 +148,12 @@ func (lp *leaseProviderImpl) insert(ctx context.Context, leaseRequest *Request)
 		log.Ctx(ctx).Debug().EmbedObject(leaseRequest).Msg("Lease request is already existing")
 		// Priority changed, update it
 		if existing.Priority != leaseRequest.Priority {
-			log.Ctx(ctx).Debug().EmbedObject(leaseRequest).Msgf("Lease request priority has changed (previous: %d, new: %d)", existing.Priority, leaseRequest.Priority)
+			log.Ctx(ctx).
+				Debug().
+				EmbedObject(leaseRequest).
+				Int("previous_priority", existing.Priority).
+				Int("new_priority", leaseRequest.Priority).
+				Msg("Lease request priority has changed")
 			existing.Priority = leaseRequest.Priority
 			updated = true
 		}
@@ -160,7 +165,12 @@ func (lp *leaseProviderImpl) insert(ctx context.Context, leaseRequest *Request)
 		allowedTransition := existingStatus == StatusAcquired && (leaseRequestStatus == StatusSuccess || leaseRequestStatus == StatusFailure)
 		// condition
 		if statusMismatch && allowedTransition {
-			log.Ctx(ctx).Debug().EmbedObject(leaseRequest).Msgf("Lease request status has changed (previous: %s, new: %s)", existingStatus, leaseRequestStatus)
+			log.Ctx(ctx).
+				Debug().
+				EmbedObject(leaseRequest).
+				Str("previous_status", existingStatus).
+				Str("new_status", leaseRequestStatus).
+				Msg("Lease request status has changed")
 			existing.Status = &leaseRequestStatus
 			updated = true
 		} else if statusMismatch {
@@ -172,9 +182,12 @@ func (lp *leaseProviderImpl) insert(ctx context.Context, leaseRequest *Request)
 	}
 
 	if updated {
-		now := time.Now()
-		lp.lastUpdatedAt = &now
-		log.Ctx(ctx).Debug().Msgf("Provider last updated time bumped (new time: %s, StabilizeDuration now ends at %s)", lp.lastUpdatedAt.Format(time.RFC3339), lp.lastUpdatedAt.Add(lp.opts.StabilizeDuration).Format(time.RFC3339))
+		lp.lastUpdatedAt = time.Now()
+		log.Ctx(ctx).
+			Debug().
+			Time("new_last_updated_at", lp.lastUpdatedAt).
+			Time("new_stabilize_ends_at", lp.lastUpdatedAt.Add(lp.opts.StabilizeDuration)).
+			Msg("Provider last updated time bumped")
 	}
 
 	lp.evictTTL(ctx)
@@ -188,20 +201,40 @@ func (lp *leaseProviderImpl) evaluateRequest(ctx context.Context, req *Request)
 
 	if lp.acquired != nil && !(pointer.StringDeref(lp.acquired.Status, StatusAcquired) == StatusFailure) {
 		// Lock already acquired
-		log.Ctx(ctx).Debug().EmbedObject(req).Msgf("Lock already acquired (by sha %s, priority %d)", lp.acquired.HeadSHA, lp.acquired.Priority)
+		log.Ctx(ctx).
+			Debug().
+			EmbedObject(req).
+			Msgf("Lock already acquired (by sha %s, priority %d)", lp.acquired.HeadSHA, lp.acquired.Priority)
 		return req
 	}
 	// 1st: we reached the time limit -> lastUpdatedAt + StabilizeDuration > now
-	passedStabilizeDuration := time.Since(*lp.lastUpdatedAt) >= lp.opts.StabilizeDuration
-	log.Ctx(ctx).Debug().Msg("Now: " + time.Now().Format(time.RFC3339))
-	log.Ctx(ctx).Debug().EmbedObject(req).Msgf("Stabilize duration check: Duration config: %.0fs, Last updated at: %s, Stabilize duration end: %s, Stabilize duration passed: %t", lp.opts.StabilizeDuration.Seconds(), lp.lastUpdatedAt.Format(time.RFC3339), lp.lastUpdatedAt.Add(lp.opts.StabilizeDuration).Format(time.RFC3339), passedStabilizeDuration)
+	passedStabilizeDuration := time.Since(lp.lastUpdatedAt) >= lp.opts.StabilizeDuration
+	log.Ctx(ctx).
+		Debug().
+		EmbedObject(req).
+		Float64("config_stabilize_duration_sec", lp.opts.StabilizeDuration.Seconds()).
+		Time("last_updated_at", lp.lastUpdatedAt).
+		Time("stabilize_ends_at", lp.lastUpdatedAt.Add(lp.opts.StabilizeDuration)).
+		Time("current_time", time.Now()).
+		Bool("stabilize_duration_passed", passedStabilizeDuration).
+		Msg("Stabilize duration check")
+
 	// 2nd: we received all requests and can take a decision
-	// 3rd: there has been no previous failure
 	reachedExpectedRequestCount := len(lp.known) >= lp.opts.ExpectedRequestCount
-	log.Ctx(ctx).Debug().EmbedObject(req).Msgf("Expected request count check: config: %d, actual: %d, expected request count reached: %t", lp.opts.ExpectedRequestCount, len(lp.known), reachedExpectedRequestCount)
+	log.Ctx(ctx).
+		Debug().
+		EmbedObject(req).
+		Int("config_expected_request_count", lp.opts.ExpectedRequestCount).
+		Int("actual_request_count", len(lp.known)).
+		Bool("expected_request_count_reached", reachedExpectedRequestCount).
+		Msg("Expected request count check")
 
+	// 3rd: there has been no previous failure
 	if lp.acquired == nil && (!passedStabilizeDuration && !reachedExpectedRequestCount) {
-		log.Ctx(ctx).Debug().EmbedObject(req).Msg("Stabilize duration has not been met yet, or we're still waiting for more request to register")
+		log.Ctx(ctx).
+			Debug().
+			EmbedObject(req).
+			Msg("Stabilize duration has not been met yet, or we're still waiting for more request to register")
 		return req
 	}
 
@@ -217,8 +250,14 @@ func (lp *leaseProviderImpl) evaluateRequest(ctx context.Context, req *Request)
 	if req.Priority == maxPriority {
 		req.Status = pointer.String(StatusAcquired)
 		lp.acquired = req
-		log.Ctx(ctx).Debug().EmbedObject(req).Msg("Current lease request has the higher priority. It then acquires the lock")
-		log.Ctx(ctx).Info().EmbedObject(req).Msg("Lock acquired")
+		log.Ctx(ctx).
+			Debug().
+			EmbedObject(req).
+			Msg("Current lease request has the higher priority. It then acquires the lock")
+		log.Ctx(ctx).
+			Info().
+			EmbedObject(req).
+			Msg("Lock acquired")
 	}
 
 	return req

internal/lease/leaseprovider_test.go

@@ -31,6 +31,7 @@ func TestLeaseRequest_UpdateLastSeenAt_Update(t *testing.T) {
 }
 
 func TestNewLeaseProvider(t *testing.T) {
+	creationTime := time.Now()
 	opts := ProviderOpts{
 		StabilizeDuration:    time.Minute,
 		TTL:                  time.Second,
@@ -43,7 +44,7 @@ func TestNewLeaseProvider(t *testing.T) {
 	assert.Equal(t, opts, leaseProviderImpl.opts)
 	assert.NotNil(t, leaseProviderImpl.known)
 	assert.Nil(t, leaseProviderImpl.acquired)
-	assert.Nil(t, leaseProviderImpl.lastUpdatedAt)
+	assert.True(t, leaseProviderImpl.lastUpdatedAt.After(creationTime))
 }
 
 func Test_leaseProviderImpl_insert_update_ok(t *testing.T) {
@@ -242,8 +243,7 @@ func Test_leaseProviderImpl_evaluateRequest_timePassed(t *testing.T) {
 	assert.Equal(t, *req2.Status, StatusPending)
 
 	// Simulate a time passed by setting the last updated timestamp in the past
-	updatedAt := time.Now().Add(-2 * time.Minute)
-	lpImpl.lastUpdatedAt = &updatedAt
+	lpImpl.lastUpdatedAt = time.Now().Add(-2 * time.Minute)
 	_ = lpImpl.evaluateRequest(context.Background(), req2)
 	assert.Equal(t, *req2.Status, StatusAcquired)
 }
@@ -438,8 +438,7 @@ func Test_leaseProviderImpl__FullLoop_ReleaseFailedNoNewRequest(t *testing.T) {
 
 	// req2 has the highest priority -> it gets the lease (assuming sufficient time passed)
 	// (note: backdate the stabilisation duration)
-	updatedAt := time.Now().Add(-100 * time.Minute)
-	lpImpl.lastUpdatedAt = &updatedAt
+	lpImpl.lastUpdatedAt = time.Now().Add(-100 * time.Minute)
 	req2, err = lp.Acquire(context.Background(), req2)
 	assert.NoError(t, err)
 	assert.Equal(t, StatusAcquired, *req2.Status)

internal/server/handlers/utils.go

@@ -28,7 +28,7 @@ func getLeaseProviderOrFail(c *fiber.Ctx, orchestrator lease.ProviderOrchestrato
 	provider, err := orchestrator.Get(owner, repo, baseRef)
 	if err != nil {
 		log.Ctx(c.UserContext()).Error().Err(err).Msg("Error when retrieving provider")
-		return nil, apiError(c, fiber.StatusBadRequest, err.Error(), nil)
+		return nil, apiError(c, fiber.StatusNotFound, err.Error(), nil)
 	}
 
 	return provider, nil