Skip to content

measure UserSignup provision time #1148

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
MatousJobanek merged 8 commits into from
Feb 27, 2025
Merged

measure UserSignup provision time #1148

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
b3b6279
measure UserSignup provision time
MatousJobanek Feb 25, 2025
ec07825
go mod tidy
MatousJobanek Feb 25, 2025
84c6983
wait until mur is ready
MatousJobanek Feb 26, 2025
dd27eb6
Merge branch 'master' into measure-provision-time
MatousJobanek Feb 26, 2025
97eeacf
drop redundant test
MatousJobanek Feb 26, 2025
7111164
format
MatousJobanek Feb 26, 2025
4ef1a26
improve
MatousJobanek Feb 26, 2025
612e006
update deps
MatousJobanek Feb 27, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
44 changes: 42 additions & 2 deletions controllers/usersignup/usersignup_controller.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -3,8 +3,8 @@
import (
"context"
"fmt"

"strconv"
"time"

recaptcha "cloud.google.com/go/recaptchaenterprise/v2/apiv1"
recaptchapb "cloud.google.com/go/recaptchaenterprise/v2/apiv1/recaptchaenterprisepb"
Expand Down Expand Up @@ -380,14 +380,54 @@
}
}

logger.Info("Checking whether MUR is Ready", "MUR", mur.Name)
if !condition.IsTrueWithReason(mur.Status.Conditions, toolchainv1alpha1.ConditionReady, toolchainv1alpha1.MasterUserRecordProvisionedReason) &&
!condition.IsTrue(userSignup.Status.Conditions, toolchainv1alpha1.UserSignupComplete) {
return true, r.updateIncompleteStatus(ctx, userSignup, fmt.Sprintf("MUR %s was not ready", mur.Name))
}

logger.Info("Setting UserSignup status to 'Complete'")

return true, r.updateStatus(ctx, userSignup, r.updateCompleteStatus(mur.Name))
if err := r.updateStatus(ctx, userSignup, r.updateCompleteStatus(mur.Name)); err != nil {
return true, err
}

Check warning on line 393 in controllers/usersignup/usersignup_controller.go

View check run for this annotation

Codecov / codecov/patch

controllers/usersignup/usersignup_controller.go#L392-L393 

Added lines #L392 - L393 were not covered by tests
if err := recordProvisionTime(ctx, r.Client, userSignup); err != nil {
return true, fmt.Errorf("unable to record provision time: %w", err)
}

Check warning on line 396 in controllers/usersignup/usersignup_controller.go

View check run for this annotation

Codecov / codecov/patch

controllers/usersignup/usersignup_controller.go#L395-L396 

Added lines #L395 - L396 were not covered by tests
return true, nil
}

return false, nil
}

func recordProvisionTime(ctx context.Context, cl runtimeclient.Client, userSignup *toolchainv1alpha1.UserSignup) error {
requestReceivedTime, ok := userSignup.Annotations[toolchainv1alpha1.UserSignupRequestReceivedTimeAnnotationKey]
// if annotation not present, then nothing to record
if !ok {
return nil
}
// delete annotation to make sure that we don't record the same UserSignup twice
delete(userSignup.Annotations, toolchainv1alpha1.UserSignupRequestReceivedTimeAnnotationKey)
if err := cl.Update(ctx, userSignup); err != nil {
return err
}
Copy link
Copy Markdown
Contributor

@mfrancisc mfrancisc Feb 26, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

minor - should we delete at the end? once the provisionTimeSeconds was computed. Just in case something goes wrong in the middle.

Copy link
Copy Markdown
Contributor Author

@MatousJobanek MatousJobanek Feb 26, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, I was thinking about it too. For the simplicity, I decided to delete it and log the information. In this case, the presence of the annotation says if the given UserSignup was already recorded or not. If we would want to keep it, then we would need to add another field into UserSignup.Status to store the provision time.
Both options are valid, I decided to go with the simpler one. We can always change it later.
But if there would be more people asking for having the information stored in UserSignup, then I can do it in this PR.

Copy link
Copy Markdown
Contributor

@mfrancisc mfrancisc Feb 26, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry , I was just wondering if we should move those lines after line 427, not keeping the information. Just move it as last thing in the function.

Copy link
Copy Markdown
Contributor Author

@MatousJobanek MatousJobanek Feb 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

ah, gotcha.
I used this order intentionally to ensure that the provision time for the particular UserSignup will be recorded only once. If the update fails (because of a conflict) then the controller requeue a new reconcile and try to remove the annotation again. With this approach, the provision time will be recorded only when the removal of the annotation is successful. If the removal was at the end of the function and the update failed, then we would have two records for the same UserSignup.

Copy link
Copy Markdown
Contributor

@mfrancisc mfrancisc Feb 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

gotcha, makes sense! thanks for explaining that!

I was thinking about the case in which fails after the update and before the recording ( basically parsing the value ). But I think that is tolerated, more than having duplicated recordings.

Copy link
Copy Markdown
Contributor Author

@MatousJobanek MatousJobanek Feb 27, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If it fails for parsing the value, then there is some problem between reg-service and host-operator and we should only log the error and not return it nor try to parse it again. The resulting duration would be irrelevant and we shouldn't block the UserSignup because of some broken telemetry data.

logger := log.FromContext(ctx)
parsedTime, err := time.Parse(time.RFC3339, requestReceivedTime)
if err != nil {
logger.Error(err, "unable to parse the request-received-time annotation", "value", requestReceivedTime)
return nil
}
_, phoneVerificationTriggered := userSignup.Annotations[toolchainv1alpha1.UserSignupVerificationCodeAnnotationKey]
// don't measure provision time for cases when UserSignup was either approved manually or it required phone verification step
if states.ApprovedManually(userSignup) || phoneVerificationTriggered {
return nil
}
provisionTimeSeconds := time.Since(parsedTime).Seconds()
logger.Info("provision time", "time-in-seconds", provisionTimeSeconds)
metrics.UserSignupProvisionTimeHistogram.Observe(provisionTimeSeconds)
return nil
}

func (r *Reconciler) ensureNewMurIfApproved(
ctx context.Context,
config toolchainconfig.ToolchainConfig,
Expand Down
Loading
Loading