Check if time is nil before logging #121554

kaisoz · 2023-10-26T21:27:16Z

What type of PR is this?

/kind bug

What this PR does / why we need it:

The Job controller logs a panic when logging a nil pod.deletionTimestamp. This PR fixes this by logging it only if it's not nil.

Which issue(s) this PR fixes:

Fixes #121392

Special notes for your reviewer:

Does this PR introduce a user-facing change?

NONE

k8s-ci-robot · 2023-10-26T21:27:25Z

This issue is currently awaiting triage.

If a SIG or subproject determines this is a relevant issue, they will accept it by applying the triage/accepted label and provide further guidance.

The triage/accepted label can be added by org members by writing /triage accepted in a comment.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

k8s-ci-robot · 2023-10-26T21:27:26Z

Hi @kaisoz. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

kaisoz · 2023-10-26T21:29:33Z

/assign @mimowo @pohly

liggitt · 2023-10-26T21:53:28Z

staging/src/k8s.io/apimachinery/pkg/apis/meta/v1/time.go

@@ -180,3 +180,12 @@ func (t Time) MarshalQueryParameter() (string, error) {

 	return t.UTC().Format(time.RFC3339), nil
 }
+
+// String returns the string representation of the wrapped time.Time
+func (t *Time) String() string {


this was previously reported in #105981 but closed because of #105981 (comment)

almost identical fixes were previously proposed in #108436 and #105982 and declined because of #105982 (comment) and #105981 (comment)

Looks like this can't be fixed, but people will keep trying...

@kaisoz: can you change this PR so that instead of adding a String method, a comment gets added why there is no String implementation ("historic reasons") and why it cannot be added now (see #105981 (comment))?

liggitt · 2023-10-26T21:53:52Z

shouldn't we fix the job controller by not logging the timestamp if it is nil?

pohly · 2023-10-27T07:18:05Z

shouldn't we fix the job controller by not logging the timestamp if it is nil?

That then would have to be done in all places where a DeletionTimestamp gets logged, causing more work for developers. Let's instead make the panic handling in klog better so that if a fmt.Stringer fails, it checks the value for nil and prints nil (or whatever fmt.Sprintf would do).

mimowo · 2023-10-27T07:49:19Z

shouldn't we fix the job controller by not logging the timestamp if it is nil?

That then would have to be done in all places where a DeletionTimestamp gets logged, causing more work for developers. Let's instead make the panic handling in klog better so that if a fmt.Stringer fails, it checks the value for nil and prints nil (or whatever fmt.Sprintf would do).

The fix in FilterActivePods is very simple, we could do it if we think it is important for 1.29 code freeze and the other approach may take longer (I'm not sure). Question to the klog approach: would the panic handling in klog introduce noticeable performance cost for the function?

pohly · 2023-10-27T08:02:40Z

if we think it is important for 1.29 code freeze

I don't think it is.

Question to the klog approach: would the panic handling in klog introduce noticeable performance cost for the function?

If it was done in advance before all fmt.Stringer calls, then maybe. But I am suggesting to only do extra work if that implementation panicked. That should be so rare (we only know of this one instance) that it shouldn't matter.

mimowo · 2023-10-27T08:13:10Z

But I am suggesting to only do extra work if that implementation panicked. That should be so rare (we only know of this one instance) that it shouldn't matter.

Makes sense. Still, the function FilterActivePods is now called on every sync by the job controller, and it panics for every non-active, not deleted pod, so terminated on its own as Succeeded, or Failed. The number of completed non-active pods in the system might be up to 12500 (default for terminated-pod-gc-threshold).

So, I'm wondering if it's preferable to prevent passing nil in to avoid potential performance increase due to handling the panics.

pohly · 2023-10-27T08:38:11Z

This only occurs at -v4 or higher, which is "Debug level verbosity". Does it matter at that level?

pohly · 2023-10-27T08:41:47Z

As simple fix at the call site might be:

// Only log p.DeletionTimestamp if non-nil, otherwise it's String implementation panics.
var deletionTime interface{}
if p.DeletionTimestamp != nil {
   deletionTime = p.DeletionTimestamp
}
logger.V(4).Info("Ignoring inactive pod", "pod", klog.KObj(p), "phase", p.Status.Phase, "deletionTime", deletionTime)

kaisoz · 2023-10-27T10:24:18Z

As simple fix at the call site might be:

// Only log p.DeletionTimestamp if non-nil, otherwise it's String implementation panics.
var deletionTime interface{}
if p.DeletionTimestamp != nil {
   deletionTime = p.DeletionTimestamp
}
logger.V(4).Info("Ignoring inactive pod", "pod", klog.KObj(p), "phase", p.Status.Phase, "deletionTime", deletionTime)

I just read the thread @pohly . So should I go ahead with your code suggestion or the comment you propose in here?

IMO I'd go with the nil check since this panic in the logs might mislead the developer while debugging

mimowo · 2023-10-27T11:03:24Z

This only occurs at -v4 or higher, which is "Debug level verbosity". Does it matter at that level?

Yeah, I missed that it is -v4. So, I'm happy with any of the fixes.

alculquicondor · 2023-10-27T13:05:33Z

As simple fix at the call site might be:

// Only log p.DeletionTimestamp if non-nil, otherwise it's String implementation panics.
var deletionTime interface{}
if p.DeletionTimestamp != nil {
   deletionTime = p.DeletionTimestamp
}
logger.V(4).Info("Ignoring inactive pod", "pod", klog.KObj(p), "phase", p.Status.Phase, "deletionTime", deletionTime)

Let's go with this

alculquicondor · 2023-10-27T13:06:52Z

@pohly, could we add a method to the klog package that wraps that?
Something like klog.SafeTimePtr(p.DeletionTimestamp)

kaisoz · 2023-10-27T13:11:36Z

@pohly, could we add a method to the klog package that wraps that? Something like klog.SafeTimePtr(p.DeletionTimestamp)

would that go to a different PR @alculquicondor or this one?

pohly · 2023-10-27T13:29:23Z

@pohly, could we add a method to the klog package that wraps that? Something like klog.SafeTimePtr(p.DeletionTimestamp)

I was wondering about that myself. But it needs to be a bit more generic (sic!):

func klog.SafePtr[T any](p *T) any {
    if p == nil {
        return nil
    }
    return p
}

@kaisoz: klog changes need to go into https://github.com/kubernetes/klog/pulls

kaisoz · 2023-10-27T14:01:37Z

@pohly, could we add a method to the klog package that wraps that? Something like klog.SafeTimePtr(p.DeletionTimestamp)

I was wondering about that myself. But it needs to be a bit more generic (sic!):
func klog.SafePtr[T any](p *T) any {
    if p == nil {
        return nil
    }
    return p
}
@kaisoz: klog changes need to go into kubernetes/klog/pulls

ahh obviously 😅 so then I'll implement the change @alculquicondor suggested 👍🏻

pacoxu · 2024-01-12T02:24:52Z

I bumped klog #122706 and you can use the new func to handle this logging issue now. @kaisoz do you have time to rebase with latest master branch and update the change?

kaisoz · 2024-01-12T08:34:39Z

I bumped klog #122706 and you can use the new func to handle this logging issue now. @kaisoz do you have time to rebase with latest master branch and update the change?

Sure! I'll take care of it today @pacoxu

pohly · 2024-01-12T09:26:08Z

The linter error is a false positive. The SafePtr helper must be added to https://github.com/kubernetes-sigs/logtools/blob/4feaefaec55f458327a13320adb5ac98024a41ce/logcheck/pkg/logcheck.go#L404-L429 and then we need to update logcheck.

@kaisoz: can you submit a PR against logcheck? I can accept it and do a release.

kaisoz · 2024-01-12T10:07:34Z

The linter error is a false positive. The SafePtr helper must be added to kubernetes-sigs/logtools@4feaefa/logcheck/pkg/logcheck.go#L404-L429 and then we need to update logcheck.

@kaisoz: can you submit a PR against logcheck? I can accept it and do a release.

Ready @pohly kubernetes-sigs/logtools#27

alculquicondor · 2024-01-12T14:17:08Z

/retest

pohly · 2024-01-12T15:07:41Z

#122733 was merged, now the tests should pass.

/retest

pacoxu · 2024-01-12T15:36:51Z

/lgtm

k8s-ci-robot · 2024-01-12T15:36:58Z

LGTM label has been added.

Git tree hash: ca36ee06facf2e3a2754f9aac6b8571d7663bee0

kaisoz · 2024-01-12T18:52:15Z

Tests now pass @pohly , I had to rebase master. Now it is ready to be approved 👍

pohly

/lgtm
/approve

pohly · 2024-01-15T08:42:18Z

/assign @mikedanese

mimowo · 2024-02-13T08:26:04Z

/assign @mikedanese

@mikedanese any progress on this? Should we re-assign?

pohly · 2024-02-13T09:21:40Z

Let's see whether @andrewsykim has time. It's a small change, just needs someone to approve.

/assign @andrewsykim

liggitt · 2024-02-13T15:46:29Z

/lgtm
/approve
/hold cancel

k8s-ci-robot · 2024-02-13T15:46:54Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: kaisoz, liggitt, pohly

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:

~~pkg/controller/OWNERS~~ [liggitt]

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

k8s-triage-robot · 2024-02-13T16:03:20Z

This PR may require API review.

If so, when the changes are ready, complete the pre-review checklist and request an API review.

Status of requested reviews is tracked in the API Review project.

k8s-ci-robot added the needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. label Oct 26, 2023

k8s-ci-robot added the needs-priority Indicates a PR lacks a `priority/foo` label and requires one. label Oct 26, 2023

k8s-ci-robot requested review from caesarxuchao and liggitt October 26, 2023 21:28

k8s-ci-robot added the kind/api-change Categorizes issue or PR as related to adding, removing, or otherwise changing an API label Oct 26, 2023

liggitt reviewed Oct 26, 2023

View reviewed changes

kaisoz force-pushed the fix-job-controller-panics branch from 682194b to 58d431d Compare October 27, 2023 14:51

kaisoz force-pushed the fix-job-controller-panics branch from 58d431d to ddf084d Compare January 12, 2024 08:45

kaisoz mentioned this pull request Jan 12, 2024

Add SafePtr to contextual logging allow list functions kubernetes-sigs/logtools#27

Merged

pohly mentioned this pull request Jan 12, 2024

hack/tools: bump logcheck to v0.8.1 #122733

Merged

Avoid panics when logging a nil pod.deletionTimestamp

9a3f1a3

kaisoz force-pushed the fix-job-controller-panics branch from ddf084d to 9a3f1a3 Compare January 12, 2024 15:34

k8s-ci-robot assigned pacoxu Jan 12, 2024

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Jan 12, 2024

pohly approved these changes Jan 13, 2024

View reviewed changes

k8s-ci-robot assigned mikedanese Jan 15, 2024

k8s-ci-robot assigned andrewsykim Feb 13, 2024

k8s-ci-robot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Feb 13, 2024

k8s-ci-robot assigned liggitt Feb 13, 2024

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Feb 13, 2024

k8s-ci-robot merged commit bd0e1e2 into kubernetes:master Feb 13, 2024
14 checks passed

k8s-ci-robot added this to the v1.30 milestone Feb 13, 2024

Check if time is nil before logging #121554

Check if time is nil before logging #121554

Conversation

kaisoz commented Oct 26, 2023 • edited

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

k8s-ci-robot commented Oct 26, 2023

k8s-ci-robot commented Oct 26, 2023

kaisoz commented Oct 26, 2023

liggitt Oct 26, 2023

Choose a reason for hiding this comment

pohly Oct 27, 2023

Choose a reason for hiding this comment

liggitt commented Oct 26, 2023

pohly commented Oct 27, 2023

mimowo commented Oct 27, 2023

pohly commented Oct 27, 2023

mimowo commented Oct 27, 2023

pohly commented Oct 27, 2023

pohly commented Oct 27, 2023

kaisoz commented Oct 27, 2023

mimowo commented Oct 27, 2023

alculquicondor commented Oct 27, 2023

alculquicondor commented Oct 27, 2023

kaisoz commented Oct 27, 2023

pohly commented Oct 27, 2023

kaisoz commented Oct 27, 2023

pacoxu commented Jan 12, 2024 • edited

kaisoz commented Jan 12, 2024

pohly commented Jan 12, 2024

kaisoz commented Jan 12, 2024

alculquicondor commented Jan 12, 2024

pohly commented Jan 12, 2024

pacoxu commented Jan 12, 2024

k8s-ci-robot commented Jan 12, 2024

kaisoz commented Jan 12, 2024

pohly left a comment

Choose a reason for hiding this comment

pohly commented Jan 15, 2024

mimowo commented Feb 13, 2024

pohly commented Feb 13, 2024

liggitt commented Feb 13, 2024

k8s-ci-robot commented Feb 13, 2024

k8s-triage-robot commented Feb 13, 2024

kaisoz commented Oct 26, 2023 •

edited

pacoxu commented Jan 12, 2024 •

edited