cleanup: Minimize logging when waiting for ip address

[nirs]

The wait includes looking up the vm MAM address in all dhcpd leases every 2 seconds. We log 2 lines for each lookup which is not helpful.

The MAC adress is already logged before the search:

I0721 15:38:26.678985   10969 main.go:141] libmachine: Got mac address "d6:3f:76:90:91:76"

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 ...
I0721 15:39:10.727668   10969 main.go:141] libmachine: Attempt 22
I0721 15:39:10.727725   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:12.729841   10969 main.go:141] libmachine: Attempt 23
I0721 15:39:12.729875   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:14.730298   10969 main.go:141] libmachine: Attempt 24
I0721 15:39:14.730359   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:16.731209   10969 main.go:141] libmachine: Attempt 25
I0721 15:39:16.731268   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:18.731698   10969 main.go:141] libmachine: Attempt 26
I0721 15:39:18.731744   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:20.732305   10969 main.go:141] libmachine: Attempt 27
I0721 15:39:20.732352   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:22.732677   10969 main.go:141] libmachine: Attempt 28
I0721 15:39:22.732722   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:24.733908   10969 main.go:141] libmachine: Attempt 29
I0721 15:39:24.733962   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:26.735945   10969 main.go:141] libmachine: Attempt 30
I0721 15:39:26.736005   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:28.736324   10969 main.go:141] libmachine: Attempt 31
I0721 15:39:28.736390   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:30.737958   10969 main.go:141] libmachine: Attempt 32
I0721 15:39:30.738026   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:32.738524   10969 main.go:141] libmachine: Attempt 33
I0721 15:39:32.738599   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:34.742399   10969 main.go:141] libmachine: Attempt 34
I0721 15:39:34.742443   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:36.743380   10969 main.go:141] libmachine: Attempt 35
I0721 15:39:36.743424   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:38.744621   10969 main.go:141] libmachine: Attempt 36
I0721 15:39:38.744654   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:40.746099   10969 main.go:141] libmachine: Attempt 37
I0721 15:39:40.746194   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:42.747922   10969 main.go:141] libmachine: Attempt 38
I0721 15:39:42.747961   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:44.749110   10969 main.go:141] libmachine: Attempt 39
I0721 15:39:44.749167   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:46.760480   10969 main.go:141] libmachine: Attempt 40
I0721 15:39:46.761893   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:48.762458   10969 main.go:141] libmachine: Attempt 41
I0721 15:39:48.762614   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:50.765755   10969 main.go:141] libmachine: Attempt 42
I0721 15:39:50.765803   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:52.765945   10969 main.go:141] libmachine: Attempt 43
I0721 15:39:52.766081   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...
I0721 15:39:54.766395   10969 main.go:141] libmachine: Attempt 44
I0721 15:39:54.766440   10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases ...

Fix:

• Log one line per search
• Include (attempt/total)
• Change to debug log?

[henry3260]

@nirs
Do you mean that we should only show these logs in debug mode, and for normal output just keep something like:
D0721 15:38:26.704823 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases (attempt 0/60)...

[nirs]

@nirs Do you mean that we should only show these logs in debug mode, and for normal output just keep something like: D0721 15:38:26.704823 10969 main.go:141] libmachine: Searching for d6:3f:76:90:91:76 in /var/db/dhcpd_leases (attempt 0/60)...

Yes, looks good!

[henry3260]

@nirs I’d like to reproduce these logs to verify my changes. Could you share how you produced them?
I tried editing the MAC address using virsh and running minikube start --driver=kvm2 --alsologtostderr --v=8, but I didn’t see those logs.
I might have missed something in my setup.

[nirs]

@nirs I’d like to reproduce these logs to verify my changes. Could you share how you produced them? I tried editing the MAC address using virsh and running minikube start --driver=kvm2 --alsologtostderr --v=8, but I didn’t see those logs. I might have missed something in my setup.

These logs are used only on macOS with qemu, vfkit, and krunkit drivers.

[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