Add probe triggered log and shift the periodics timer after manual run #119089

mochizuki875 · 2023-07-05T06:24:19Z

What type of PR is this?

/kind cleanup

What this PR does / why we need it:

Output a log when probe is triggered.
Especially readinessProbe, it will be executed by two triggers:

Constant interval(depends on periodSeconds which is readinessProbe's field)
Manual run(it's implemented Make all health checks probing consistent #98376)

However, there are no means to know which executed readinessProbe, and it may make confusion like #118815.
In addition, shift the periodic timer of ReadinessProbe after manual run.

Which issue(s) this PR fixes:

Fixes #118815

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Output a log as v4-level when probe is triggered and shift the periodic timer of ReadinessProbe after manual run.

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot · 2023-07-05T06:24:28Z

Hi @mochizuki875. 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.

mochizuki875 · 2023-07-05T06:26:51Z

/sig node
/area kubelet

aimuz · 2023-07-07T10:40:07Z

/ok-to-test

bart0sh · 2023-07-24T09:34:09Z

/triage accepted
/priority important-longterm
/cc @SergeyKanzhelev

bart0sh · 2023-08-30T08:03:06Z

/assign
@mochizuki875 Would it be enough to only log manually triggered probes to reduce amount of logging?

mochizuki875 · 2023-08-30T08:13:24Z

@bart0sh
I think so because if we remove it, the probe's regular log emitted by periodSeconds will not be output.

kubernetes/pkg/kubelet/prober/worker.go

Lines 185 to 186 in 2f90380

    
           case <-probeTicker.C: 
        
           	klog.V(3).InfoS("Triggerd Probe by periodSeconds", "probeType", w.probeType, "pod", klog.KObj(w.pod), "podUID", w.pod.UID, "containerName", w.container.Name)

Should I remove regular log?

SergeyKanzhelev · 2024-08-09T17:09:34Z

the right fix will be to shift the periodics timer after the manual run. Also maybe update docs for probes

/lgtm cancel
/hold

mochizuki875 · 2024-08-28T08:50:38Z

@SergeyKanzhelev
Thank you for your comment.

the right fix will be to shift the periodics timer after the manual run.

How about updating the periodic timer to run the probe again at intervals of probeTickerPeriod starting from the moment a manual run occurs?
(Also I agree updating docs)

e.g. Assume that probeTickerPeriod=30 and first periodic run occurs at 15:00:00, and manual run occurs at 15:00:10.
Then, the next periodic run is scheduled for 15:00:40(instead of the current 15:00:30).

mochizuki875 · 2024-08-30T07:03:15Z

@SergeyKanzhelev

I've fix as below:

Change log level V(3) to V(4) (Add probe triggered log and shift the periodics timer after manual run #119089 (comment))
Shift the periodic timer of ReadinessProbe after manual run (Add probe triggered log and shift the periodics timer after manual run #119089 (comment))

In addition, I've create PR which update docs.
kubernetes/website#47727

Best regards.

mochizuki875 · 2024-08-30T07:39:45Z

/retest

hshiina · 2024-08-30T09:28:44Z

pkg/kubelet/prober/worker.go

@@ -178,7 +178,13 @@ probeLoop:
 		case <-w.stopCh:
 			break probeLoop
 		case <-probeTicker.C:
+			klog.V(4).InfoS("Triggerd Probe by periodSeconds", "probeType", w.probeType, "pod", klog.KObj(w.pod), "podUID", w.pod.UID, "containerName", w.container.Name)


I don't think this message is necessary because every probe emits a level 4 log when it runs:

kubernetes/pkg/kubelet/prober/prober.go

Lines 136 to 179 in de6db3f

func (pb *prober) runProbe(ctx context.Context, probeType probeType, p *v1.Probe, pod *v1.Pod, status v1.PodStatus, container v1.Container, containerID kubecontainer.ContainerID) (probe.Result, string, error) {

timeout := time.Duration(p.TimeoutSeconds) * time.Second

switch {

case p.Exec != nil:

klog.V(4).InfoS("Exec-Probe runProbe", "pod", klog.KObj(pod), "containerName", container.Name, "execCommand", p.Exec.Command)

command := kubecontainer.ExpandContainerCommandOnlyStatic(p.Exec.Command, container.Env)

return pb.exec.Probe(pb.newExecInContainer(ctx, container, containerID, command, timeout))

case p.HTTPGet != nil:

req, err := httpprobe.NewRequestForHTTPGetAction(p.HTTPGet, &container, status.PodIP, "probe")

if err != nil {

return probe.Unknown, "", err

}

if klogV4 := klog.V(4); klogV4.Enabled() {

port := req.URL.Port()

host := req.URL.Hostname()

path := req.URL.Path

scheme := req.URL.Scheme

headers := p.HTTPGet.HTTPHeaders

klogV4.InfoS("HTTP-Probe", "scheme", scheme, "host", host, "port", port, "path", path, "timeout", timeout, "headers", headers)

}

return pb.http.Probe(req, timeout)

case p.TCPSocket != nil:

port, err := probe.ResolveContainerPort(p.TCPSocket.Port, &container)

if err != nil {

return probe.Unknown, "", err

}

host := p.TCPSocket.Host

if host == "" {

host = status.PodIP

}

klog.V(4).InfoS("TCP-Probe", "host", host, "port", port, "timeout", timeout)

return pb.tcp.Probe(host, port, timeout)

case p.GRPC != nil:

host := status.PodIP

service := ""

if p.GRPC.Service != nil {

service = *p.GRPC.Service

}

klog.V(4).InfoS("GRPC-Probe", "host", host, "service", service, "port", p.GRPC.Port, "timeout", timeout)

return pb.grpc.Probe(host, service, int(p.GRPC.Port), timeout)

So, we can distinguish whether a probe is periodical or manual by searching the message for manual run added below.

In addition, this message looks noisy because this is emitted even while the probe in on hold. It means this message is logged for a startup probe while the container is running.

@hshiina
Indeed, you are right.
I've removed the periodical log.

k8s-ci-robot · 2024-08-31T08:46:57Z

LGTM label has been added.

Git tree hash: 3194f64f70f439205c9021bd1b57ec52312dc6fd

thockin · 2024-10-22T22:59:33Z

ping for approval!

SergeyKanzhelev

/lgtm
/approve

k8s-ci-robot · 2024-10-22T23:02:51Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: mochizuki875, SergeyKanzhelev

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/kubelet/OWNERS~~ [SergeyKanzhelev]

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

SergeyKanzhelev · 2024-10-22T23:02:59Z

this will be tricky to test, merging as-is is fine. Thanks

mochizuki875 · 2024-10-23T00:17:53Z

@SergeyKanzhelev
Thank you!

/remove-hold

k8s-ci-robot added needs-priority Indicates a PR lacks a `priority/foo` label and requires one. area/kubelet sig/node Categorizes an issue or PR as relevant to SIG Node. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Jul 5, 2023

k8s-ci-robot requested review from dchen1107 and mtaufen July 5, 2023 06:25

k8s-ci-robot added ok-to-test Indicates a non-member PR verified by an org member that is safe to test. and removed needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Jul 7, 2023

mochizuki875 mentioned this pull request Jul 9, 2023

readiness probe is not scheduled as configured periodSeconds #118815

Closed

k8s-ci-robot requested a review from SergeyKanzhelev July 24, 2023 09:34

k8s-ci-robot assigned bart0sh Aug 30, 2023

k8s-ci-robot added do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. and removed lgtm "Looks good to me", indicates that a PR is ready to be merged. labels Aug 9, 2024

k8s-ci-robot requested review from bart0sh, derekwaynecarr, mrunalp, SergeyKanzhelev and zouyee August 9, 2024 17:09

mochizuki875 mentioned this pull request Aug 30, 2024

Add statement regarding ReadinessProbe manual run kubernetes/website#47727

Merged

mochizuki875 added 2 commits August 30, 2024 06:46

Add probe triggered log

f337511

shift the periodics timer

b3f9f16

mochizuki875 force-pushed the add_probe_triggered_log branch from 2f90380 to b3f9f16 Compare August 30, 2024 06:51

mochizuki875 changed the title ~~Add probe triggered log~~ Add probe triggered log and shift the periodics timer after manual run Aug 30, 2024

hshiina reviewed Aug 30, 2024

View reviewed changes

remove probeTicker log

6191fb8

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

thockin assigned tallclair Oct 22, 2024

SergeyKanzhelev approved these changes Oct 22, 2024

View reviewed changes

k8s-ci-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Oct 22, 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 Oct 23, 2024

k8s-ci-robot merged commit 5fa794d into kubernetes:master Oct 23, 2024
13 of 14 checks passed

k8s-ci-robot added this to the v1.32 milestone Oct 23, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add probe triggered log and shift the periodics timer after manual run #119089

Add probe triggered log and shift the periodics timer after manual run #119089

mochizuki875 commented Jul 5, 2023 •

edited

Loading

k8s-ci-robot commented Jul 5, 2023

mochizuki875 commented Jul 5, 2023

aimuz commented Jul 7, 2023

bart0sh commented Jul 24, 2023

bart0sh commented Aug 30, 2023

mochizuki875 commented Aug 30, 2023

SergeyKanzhelev commented Aug 9, 2024

mochizuki875 commented Aug 28, 2024 •

edited

Loading

mochizuki875 commented Aug 30, 2024

mochizuki875 commented Aug 30, 2024

hshiina Aug 30, 2024

mochizuki875 Aug 30, 2024

bart0sh Aug 31, 2024

k8s-ci-robot commented Aug 31, 2024

thockin commented Oct 22, 2024

SergeyKanzhelev left a comment

k8s-ci-robot commented Oct 22, 2024

SergeyKanzhelev commented Oct 22, 2024

mochizuki875 commented Oct 23, 2024

	func (pb prober) runProbe(ctx context.Context, probeType probeType, p v1.Probe, pod *v1.Pod, status v1.PodStatus, container v1.Container, containerID kubecontainer.ContainerID) (probe.Result, string, error) {
	timeout := time.Duration(p.TimeoutSeconds) * time.Second
	switch {
	case p.Exec != nil:
	klog.V(4).InfoS("Exec-Probe runProbe", "pod", klog.KObj(pod), "containerName", container.Name, "execCommand", p.Exec.Command)
	command := kubecontainer.ExpandContainerCommandOnlyStatic(p.Exec.Command, container.Env)
	return pb.exec.Probe(pb.newExecInContainer(ctx, container, containerID, command, timeout))

	case p.HTTPGet != nil:
	req, err := httpprobe.NewRequestForHTTPGetAction(p.HTTPGet, &container, status.PodIP, "probe")
	if err != nil {
	return probe.Unknown, "", err
	}
	if klogV4 := klog.V(4); klogV4.Enabled() {
	port := req.URL.Port()
	host := req.URL.Hostname()
	path := req.URL.Path
	scheme := req.URL.Scheme
	headers := p.HTTPGet.HTTPHeaders
	klogV4.InfoS("HTTP-Probe", "scheme", scheme, "host", host, "port", port, "path", path, "timeout", timeout, "headers", headers)
	}
	return pb.http.Probe(req, timeout)

	case p.TCPSocket != nil:
	port, err := probe.ResolveContainerPort(p.TCPSocket.Port, &container)
	if err != nil {
	return probe.Unknown, "", err
	}
	host := p.TCPSocket.Host
	if host == "" {
	host = status.PodIP
	}
	klog.V(4).InfoS("TCP-Probe", "host", host, "port", port, "timeout", timeout)
	return pb.tcp.Probe(host, port, timeout)

	case p.GRPC != nil:
	host := status.PodIP
	service := ""
	if p.GRPC.Service != nil {
	service = *p.GRPC.Service
	}
	klog.V(4).InfoS("GRPC-Probe", "host", host, "service", service, "port", p.GRPC.Port, "timeout", timeout)
	return pb.grpc.Probe(host, service, int(p.GRPC.Port), timeout)

Add probe triggered log and shift the periodics timer after manual run #119089

Add probe triggered log and shift the periodics timer after manual run #119089

Conversation

mochizuki875 commented Jul 5, 2023 • edited Loading

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?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

k8s-ci-robot commented Jul 5, 2023

mochizuki875 commented Jul 5, 2023

aimuz commented Jul 7, 2023

bart0sh commented Jul 24, 2023

bart0sh commented Aug 30, 2023

mochizuki875 commented Aug 30, 2023

SergeyKanzhelev commented Aug 9, 2024

mochizuki875 commented Aug 28, 2024 • edited Loading

mochizuki875 commented Aug 30, 2024

mochizuki875 commented Aug 30, 2024

hshiina Aug 30, 2024

Choose a reason for hiding this comment

mochizuki875 Aug 30, 2024

Choose a reason for hiding this comment

bart0sh Aug 31, 2024

Choose a reason for hiding this comment

k8s-ci-robot commented Aug 31, 2024

thockin commented Oct 22, 2024

SergeyKanzhelev left a comment

Choose a reason for hiding this comment

k8s-ci-robot commented Oct 22, 2024

SergeyKanzhelev commented Oct 22, 2024

mochizuki875 commented Oct 23, 2024

mochizuki875 commented Jul 5, 2023 •

edited

Loading

mochizuki875 commented Aug 28, 2024 •

edited

Loading