Skip to content
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.

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

Add duration to certificate creation logs #2040

Merged

Conversation

rzetelskik
Copy link
Member

@rzetelskik rzetelskik commented Jul 29, 2024

Description of your changes: This PR adds duration to certificate creation logs for ease of debugging in scenarios similar to #1997. At the moment the pre and post-creation logs have to be matched to asses the time it took to create the certificate, which can be a long running action.

I0725 14:09:06.446762       1 kubecrypto/certs.go:201] "Creating certificate" Secret="e2e-test-scyllacluster-2fws8-0-cs67t/basic-7xzt6-local-client-ca" Reason="needs new cert"
I0725 14:09:48.664868       1 kubecrypto/certs.go:206] "Certificate created" Secret="e2e-test-scyllacluster-2fws8-0-cs67t/basic-7xzt6-local-client-ca"

Which issue is resolved by this Pull Request:
Resolves #

/kind feature
/priority important-longterm

@scylla-operator-bot scylla-operator-bot bot added the kind/feature Categorizes issue or PR as related to a new feature. label Jul 29, 2024
@scylla-operator-bot scylla-operator-bot bot added the priority/important-longterm Important over the long term, but may not be staffed and/or may need multiple releases to complete. label Jul 29, 2024
@scylla-operator-bot scylla-operator-bot bot requested a review from zimnx July 29, 2024 09:13
@scylla-operator-bot scylla-operator-bot bot added the size/XS Denotes a PR that changes 0-9 lines, ignoring generated files. label Jul 29, 2024
Copy link
Member

@tnozicka tnozicka left a comment

Choose a reason for hiding this comment

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

Technically, these times will be mangled by the cache / buffer underneath. Shouldn't we rather trace the actual key generation which is what takes the time?

klog.V(2).InfoS("Creating certificate", "Secret", naming.ObjRef(tlsSecret.GetSecret()), "Reason", refreshReason)
cert, key, err := certCreator.MakeCertificate(ctx, keyGetter, signer, validity)
if err != nil {
return nil, fmt.Errorf("can't create certificate: %w", err)
}
klog.V(2).InfoS("Certificate created", "Secret", naming.ObjRef(tlsSecret.GetSecret()))
klog.V(2).InfoS("Certificate created", "Secret", naming.ObjRef(tlsSecret.GetSecret()), "Duration", time.Now().Sub(startTime))
Copy link
Member

Choose a reason for hiding this comment

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

duration is a bit ambiguous here (with cert lifetime)

Copy link
Member Author

Choose a reason for hiding this comment

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

right, changed to ElapsedTime

@tnozicka
Copy link
Member

Technically, these times will be mangled by the cache / buffer underneath. Shouldn't we rather trace the actual key generation which is what takes the time?

but these are also misplaced with regards to the sync loop, so this may just be good enough

@rzetelskik
Copy link
Member Author

@rzetelskik: The following test failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name Commit Details Required Rerun command
ci/prow/e2e-gke-parallel-clusterip 11d6b50 link true /test e2e-gke-parallel-clusterip
Full PR test history. Your PR dashboard.

New flake #2042

@rzetelskik
Copy link
Member Author

Technically, these times will be mangled by the cache / buffer underneath. Shouldn't we rather trace the actual key generation which is what takes the time?

but these are also misplaced with regards to the sync loop, so this may just be good enough

right, key generation already has the duration and you can look there, but my reasoning was that if you start debugging from the reconciliation loop this is easier to notice

@rzetelskik rzetelskik requested a review from tnozicka July 29, 2024 13:35
Copy link
Member

@tnozicka tnozicka left a comment

Choose a reason for hiding this comment

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

/approve
/lgtm

@scylla-operator-bot scylla-operator-bot bot added the lgtm Indicates that a PR is ready to be merged. label Jul 29, 2024
Copy link
Contributor

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: rzetelskik, tnozicka

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

@scylla-operator-bot scylla-operator-bot bot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Jul 29, 2024
@scylla-operator-bot scylla-operator-bot bot merged commit da9b96d into scylladb:master Jul 29, 2024
12 checks passed
@tnozicka tnozicka added kind/machinery Categorizes issue or PR as related to Makefile, scripts or similar changes. and removed kind/feature Categorizes issue or PR as related to a new feature. labels Sep 18, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
approved Indicates a PR has been approved by an approver from all required OWNERS files. kind/machinery Categorizes issue or PR as related to Makefile, scripts or similar changes. lgtm Indicates that a PR is ready to be merged. priority/important-longterm Important over the long term, but may not be staffed and/or may need multiple releases to complete. size/XS Denotes a PR that changes 0-9 lines, ignoring generated files.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants