fix: Minimize logging when waiting for ip address #21753

henry3260 · 2025-10-15T18:14:22Z

Before:

I0721 15:38:26.704501 10969 main.go:141] libmachine: Attempt 0
I0721 15:38:26.704823 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:28.705345 10969 main.go:141] libmachine: Attempt 1
I0721 15:38:28.705413 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:30.706205 10969 main.go:141] libmachine: Attempt 2
I0721 15:38:30.706254 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:32.706985 10969 main.go:141] libmachine: Attempt 3
I0721 15:38:32.707114 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:34.707951 10969 main.go:141] libmachine: Attempt 4
I0721 15:38:34.708015 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:36.708653 10969 main.go:141] libmachine: Attempt 5
I0721 15:38:36.708722 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:38.709263 10969 main.go:141] libmachine: Attempt 6
I0721 15:38:38.709309 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:40.709823 10969 main.go:141] libmachine: Attempt 7
I0721 15:38:40.709885 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:42.711666 10969 main.go:141] libmachine: Attempt 8
I0721 15:38:42.711705 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:44.713371 10969 main.go:141] libmachine: Attempt 9
I0721 15:38:44.713427 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:46.713856 10969 main.go:141] libmachine: Attempt 10
I0721 15:38:46.713897 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:48.714571 10969 main.go:141] libmachine: Attempt 11
I0721 15:38:48.714619 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:50.715270 10969 main.go:141] libmachine: Attempt 12
I0721 15:38:50.715313 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:52.716156 10969 main.go:141] libmachine: Attempt 13
I0721 15:38:52.716192 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:54.717573 10969 main.go:141] libmachine: Attempt 14
I0721 15:38:54.717630 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:56.719394 10969 main.go:141] libmachine: Attempt 15
I0721 15:38:56.719576 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:58.721309 10969 main.go:141] libmachine: Attempt 16
I0721 15:38:58.721354 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:00.722254 10969 main.go:141] libmachine: Attempt 17
I0721 15:39:00.722291 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:02.723277 10969 main.go:141] libmachine: Attempt 18
I0721 15:39:02.723346 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:04.725023 10969 main.go:141] libmachine: Attempt 19
I0721 15:39:04.725093 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:06.725607 10969 main.go:141] libmachine: Attempt 20
I0721 15:39:06.725653 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:08.727193 10969 main.go:141] libmachine: Attempt 21
I0721 15:39:08.727256 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...

After:

linux-foundation-easycla · 2025-10-15T18:14:27Z

The committers listed above are authorized under a signed CLA.

✅ login: henry3260 / name: Henry Chen (37d7943)

k8s-ci-robot · 2025-10-15T18:14:32Z

Hi @henry3260. 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-sigs/prow repository.

minikube-bot · 2025-10-15T18:15:04Z

Can one of the admins verify this patch?

nirs

We repeat the same code in 3 places. Adding logging 3 times to the 3 duplicates is not the right way to maintain this code.

What we need to do:

Eliminate the duplicate code and move the retry loop to a helper (likely in the common package).
Add the nicer log in the loop, replacing 2 logs (one in the loop, one in the code searching the Mac address) with single log.

nirs · 2025-10-15T18:22:31Z

pkg/drivers/common/common.go

-	log.Debugf("Searching for %s in %s ...", mac, path)
+	if klog.V(4).Enabled() {
+		log.Debugf("Searching for %s in %s ...", mac, path)
+	}


Remove this log, there is no point in logging this since we log the attempts in the loop calling this.

Remove this log, there is no point in logging this since we log the attempts in the loop calling this.

I think we could keep the original log and only surface it when the user increases the log verbosity level. That way, it won’t clutter the default output but still offers useful traceability when needed. What do you think?

The log is not needed, lets keep it simple.

nirs · 2025-10-15T18:26:50Z

pkg/drivers/krunkit/krunkit.go

 	}
 	// Implement a retry loop because IP address isn't added to dhcp leases file immediately
+	attempts := 0
 	for i := 0; i < 60; i++ {


Instead of adding another variable use:

for attempts := 0; attempts < 60; attempts++ {

But I think we can keep the loop as is and use i.

nirs · 2025-10-15T18:29:25Z

pkg/drivers/krunkit/krunkit.go

+		attempts = i
+		if klog.V(4).Enabled() {
+			log.Debugf("Attempt %d", i)
+		}


This log is completely unneeded now since we log the attempts in the next log.

nirs · 2025-10-15T18:35:42Z

pkg/drivers/krunkit/krunkit.go

 		time.Sleep(2 * time.Second)
 	}
+	path := "/var/db/dhcpd_leases"
+	log.Debugf("Searching for %s in %s (attempt %d/60)", d.MACAddress, path, attempts+1)


We cannot duplicate the path here. We can use the constant from common.LeasesPath.

So I would keep only this log in this loop:

log.Debugf("Searching for %s in %s (attempt %d/%d)", d.MACAddress, common.LeasesPath, i+1, maxAttempts)

nirs · 2025-10-15T18:38:47Z

pkg/drivers/qemu/qemu.go

 		multiplier := 1
 		if detect.NestedVM() {
 			multiplier = 3 // will help with running in Free github action Macos VMs (takes 112+ retries on average)
 		}


Add a variable instead of repeating 60*multiplier and use it in the lop and the log.

cost maxAttempts := 60 * multiplier

Same comment for vfkit.go.

Add a variable instead of repeating 60*multiplier and use it in the lop and the log.

cost maxAttempts := 60 * multiplier

Would it be better to put maxAttempts in the const section instead of defining it at the top of the loop?
We can't do that because the multiplier is not a constant — its value isn't known at compile time.

Yes it must be in the function and unfortunately const will not work in Go for local value that cannot change after setting it.

nirs · 2025-10-15T18:47:05Z

pkg/drivers/krunkit/krunkit.go

 		}
 		return nil
 	}
 	// Implement a retry loop because IP address isn't added to dhcp leases file immediately


Add a constant for maxAttempts since we need it twice:

const maxAttempts = 60

This will also make it more consistent with other drivers, which will make it easier to extract this loop to a helper function, since all the drivers use the similar logic.

medyagh

I am not sure if I agree with this Change ! someitmes when the minikube log Stuck on Online it is very devistating to look at it, wondering what minikube is doing, I think we should keep this, since this will be use full to implemement Sub Steps or a Progress-bar style UI spinning later

but I really like not repeating
I0721 15:38:26.704823 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...

thats a good improveement !

instead of removing all the updates, I suggrest limit number of times it trying, we could skip every 3 or 5 times.
so long one in 5,

so the log should say

I0721 15:38:26.704823 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:38:28.705345 10969 main.go:141] libmachine: Attempt 1
I0721 15:38:28.705345 10969 main.go:141] libmachine: Attempt 5
I0721 15:38:28.705345 10969 main.go:141] libmachine: Attempt 10
...

this was actually very usefful for me when I was trying to make minikube work on Github Action Macos, I would know exactly how many Minutes to add to the timeout or find the correct Max Attempts for github actions

nirs · 2025-10-16T16:12:06Z

I am not sure if I agree with this Change !

This current code is not implementing what the issue suggests.

someitmes when the minikube log Stuck on Online it is very devistating to look at it, wondering what minikube is doing, I think we should keep this, since this will be use full to implemement Sub Steps or a Progress-bar style UI spinning later

The issue is not suggesting to remove all logs when searching the ip address, but to have log per attempt instead of 2 logs. This keeps enough progress so minikube does not fill stuck until the search is complete.

instead of removing all the updates, I suggrest limit number of times it trying, we could skip every 3 or 5 times. so long one in 5,

so the log should say

I0721 15:38:26.704823 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ... I0721 15:38:28.705345 10969 main.go:141] libmachine: Attempt 1 I0721 15:38:28.705345 10969 main.go:141] libmachine: Attempt 5 I0721 15:38:28.705345 10969 main.go:141] libmachine: Attempt 10 ...

this was actually very usefful for me when I was trying to make minikube work on Github Action Macos, I would know exactly how many Minutes to add to the timeout or find the correct Max Attempts for github actions

This will be too complicated and we should not spend time on something which is wrong by design. The way to get the ip address is to get it from the guest, either by an agent running in the guest. This will work with any network (shared, bridged) and does not require polling.

Until we have this we should do the minimal changes needed so this make less noise in the logs.

medyagh

@henry3260 please update the PR with the new Before/After

nirs

Much better now! just need to remove the unwanted constant at the op of the file, and bake the multiplier into the value so we don't repeat the multiplier.

nirs · 2025-10-16T21:35:47Z

pkg/drivers/krunkit/krunkit.go

 	serialFileName = "serial.log"
 	logLevelInfo   = "3"
 	defaultSSHUser = "docker"
+	maxAttempts    = 60


This value makes sense only in Start(), and even there is should be right above the code using it. Putting it here confuses the reader that this driver uses maxAttempts for many operations while it is used only for one operation.

Let make it a variable at the start right above the loop. This way we can bake into the value the multiplier in the 2 version using a multiplier.

henry3260 · 2025-10-17T03:44:10Z

@henry3260 please update the PR with the new Before/After

Updated the PR with the new Before/After!

henry3260 · 2025-10-17T03:46:25Z

@nirs @medyagh Thanks for the review and guidance!

k8s-ci-robot · 2025-10-17T18:34:49Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: henry3260, medyagh

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:

~~OWNERS~~ [medyagh]

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

medyagh · 2025-10-17T18:34:52Z

/ok-to-test

k8s-ci-robot · 2025-10-17T18:35:32Z

@henry3260: 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
pull-minikube-integration	`37d7943`	link	true	`/test pull-minikube-integration`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

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-sigs/prow repository. I understand the commands that are listed here.

minikube-pr-bot · 2025-10-17T19:24:28Z

kvm2 driver with docker runtime

┌────────────────┬──────────┬────────────────────────┐
│    COMMAND     │ MINIKUBE │ MINIKUBE  ( PR 21753 ) │
├────────────────┼──────────┼────────────────────────┤
│ minikube start │ 42.8s    │ 44.5s                  │
│ enable ingress │ 16.9s    │ 17.0s                  │
└────────────────┴──────────┴────────────────────────┘

Times for minikube start: 46.0s 42.7s 41.3s 41.8s 42.1s
Times for minikube (PR 21753) start: 43.6s 45.1s 43.8s 44.8s 45.2s

Times for minikube ingress: 18.9s 15.9s 16.8s 15.9s 16.9s
Times for minikube (PR 21753) ingress: 16.4s 15.9s 16.4s 15.9s 20.4s

docker driver with docker runtime

┌────────────────┬──────────┬────────────────────────┐
│    COMMAND     │ MINIKUBE │ MINIKUBE  ( PR 21753 ) │
├────────────────┼──────────┼────────────────────────┤
│ minikube start │ 23.2s    │ 23.8s                  │
│ enable ingress │ 11.9s    │ 12.3s                  │
└────────────────┴──────────┴────────────────────────┘

Times for minikube start: 20.6s 23.9s 22.6s 24.5s 24.6s
Times for minikube (PR 21753) start: 26.1s 22.4s 23.6s 23.5s 23.3s

Times for minikube ingress: 11.7s 11.7s 12.7s 10.7s 12.7s
Times for minikube (PR 21753) ingress: 10.7s 10.7s 12.7s 13.7s 13.7s

docker driver with containerd runtime

┌────────────────┬──────────┬────────────────────────┐
│    COMMAND     │ MINIKUBE │ MINIKUBE  ( PR 21753 ) │
├────────────────┼──────────┼────────────────────────┤
│ minikube start │ 20.3s    │ 20.9s                  │
│ enable ingress │ 21.0s    │ 21.2s                  │
└────────────────┴──────────┴────────────────────────┘

Times for minikube start: 20.7s 19.9s 20.5s 20.9s 19.5s
Times for minikube (PR 21753) start: 19.9s 20.7s 20.5s 23.0s 20.6s

Times for minikube ingress: 22.2s 20.2s 20.2s 20.2s 22.2s
Times for minikube (PR 21753) ingress: 21.2s 20.2s 23.2s 21.2s 20.2s

minikube-pr-bot · 2025-10-17T20:57:58Z

Here are the number of top 10 failed tests in each environments with lowest flake rate.

Environment	Test Name	Flake Rate
KVM_Linux_crio (7 failed)	TestFunctional/serial/KubectlGetPods(gopogh)	0.00% (chart)
KVM_Linux_crio (7 failed)	TestFunctional/serial/MinikubeKubectlCmd(gopogh)	0.00% (chart)
KVM_Linux_crio (7 failed)	TestFunctional/serial/MinikubeKubectlCmdDirectly(gopogh)	0.00% (chart)
KVM_Linux_crio (7 failed)	TestFunctional/serial/SoftStart(gopogh)	6.52% (chart)
Docker_Linux_containerd_arm64 (1 failed)	TestScheduledStopUnix(gopogh)	9.80% (chart)
KVM_Linux_containerd (1 failed)	TestFunctional/parallel/ConfigCmd(gopogh)	0.00% (chart)

Besides the following environments also have failed tests:

Docker_Linux_crio: 37 failed (gopogh)
Docker_Linux_crio_arm64: 44 failed (gopogh)

To see the flake rates of all tests by environment, click here.

k8s-ci-robot requested review from medyagh and nirs October 15, 2025 18:14

k8s-ci-robot added cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. labels Oct 15, 2025

k8s-ci-robot added the size/S Denotes a PR that changes 10-29 lines, ignoring generated files. label Oct 15, 2025

henry3260 force-pushed the fix/log branch from e1d457f to 22a103a Compare October 15, 2025 18:31

k8s-ci-robot added cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. and removed cncf-cla: no Indicates the PR's author has not signed the CNCF CLA. labels Oct 15, 2025

nirs reviewed Oct 15, 2025

View reviewed changes

medyagh requested changes Oct 15, 2025

View reviewed changes

henry3260 force-pushed the fix/log branch from 22a103a to de21ced Compare October 16, 2025 17:41

medyagh reviewed Oct 16, 2025

View reviewed changes

nirs reviewed Oct 16, 2025

View reviewed changes

fix: Minimize logging when waiting for IP address

37d7943

henry3260 force-pushed the fix/log branch from de21ced to 37d7943 Compare October 17, 2025 03:41

medyagh approved these changes Oct 17, 2025

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 17, 2025

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 Oct 17, 2025

medyagh self-requested a review October 17, 2025 18:34

fix: Minimize logging when waiting for ip address #21753

Are you sure you want to change the base?

fix: Minimize logging when waiting for ip address #21753

Conversation

henry3260 commented Oct 15, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Before:

After:

Uh oh!

linux-foundation-easycla bot commented Oct 15, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

k8s-ci-robot commented Oct 15, 2025

Uh oh!

minikube-bot commented Oct 15, 2025

Uh oh!

nirs left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nirs Oct 16, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

medyagh left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

nirs commented Oct 16, 2025

Uh oh!

medyagh left a comment

Choose a reason for hiding this comment

Uh oh!

nirs left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

henry3260 commented Oct 17, 2025

Uh oh!

henry3260 commented Oct 17, 2025

Uh oh!

k8s-ci-robot commented Oct 17, 2025

Uh oh!

medyagh commented Oct 17, 2025

Uh oh!

k8s-ci-robot commented Oct 17, 2025

Uh oh!

minikube-pr-bot commented Oct 17, 2025

Uh oh!

minikube-pr-bot commented Oct 17, 2025

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

6 participants

henry3260 commented Oct 15, 2025 •

edited

Loading

linux-foundation-easycla bot commented Oct 15, 2025 •

edited

Loading

nirs Oct 16, 2025 •

edited

Loading

medyagh left a comment •

edited

Loading