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

Request to use Debugf instead of Infof for redundant logs in isFeatureInRange #1043

Closed
AbelHu opened this issue Jun 3, 2021 · 16 comments · Fixed by #1053
Closed

Request to use Debugf instead of Infof for redundant logs in isFeatureInRange #1043

AbelHu opened this issue Jun 3, 2021 · 16 comments · Fixed by #1053

Comments

@AbelHu
Copy link

AbelHu commented Jun 3, 2021

k8s version: v1.19.6
https://github.com/microsoft/hcsshim/blob/master/hcn/hcnsupport.go#L88-L106
We found that there are too many redundant logs in kubeproxy logs. It rotates kubeproxy logs too fast. We think that it should use Debugf instead of Infof for these logs in isFeatureInRange

time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 12"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 13"
time="2021-06-01T05:00:10Z" level=info msg="currentVersion.Major < versionRange.MinVersion.Major: 9, 10"
@TBBle
Copy link
Contributor

TBBle commented Jun 13, 2021

I would just drop those log messages entirely. They don't say what feature they were testing, so they're never actually going to be useful. They look like they were accidentally left-in debugging code in #723 while implementing unit tests.

@dcantah
Copy link
Contributor

dcantah commented Jun 15, 2021

Yea I'm not sure the logs are very helpful.. Ideally we'd do two things if we were going to keep them, they should be updated to say what feature we even care about this for (e.g. that we're checking the version range for) and swapped to debug logs. (or we can just axe them like @TBBle suggests)

dcantah added a commit to dcantah/hcsshim that referenced this issue Jun 22, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
@dcantah dcantah linked a pull request Jun 22, 2021 that will close this issue
dcantah added a commit to dcantah/hcsshim that referenced this issue Jun 24, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
dcantah added a commit to dcantah/hcsshim that referenced this issue Jun 24, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
dcantah added a commit to dcantah/hcsshim that referenced this issue Jun 24, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
dcantah added a commit to dcantah/hcsshim that referenced this issue Aug 25, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
dcantah added a commit to dcantah/hcsshim that referenced this issue Aug 25, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
(cherry picked from commit 6288bb9)
Signed-off-by: Daniel Canter <dcanter@microsoft.com>
dcantah added a commit to dcantah/hcsshim that referenced this issue Aug 25, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
(cherry picked from commit 6288bb9)
Signed-off-by: Daniel Canter <dcanter@microsoft.com>
dcantah added a commit to dcantah/hcsshim that referenced this issue Aug 25, 2021
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
(cherry picked from commit 6288bb9)
Signed-off-by: Daniel Canter <dcanter@microsoft.com>
@zhiweiv
Copy link

zhiweiv commented Dec 23, 2021

@AbelHu
Do you know when will this be fixed in Windows kube-proxy? The logs still appear in AKS 1.21.7

@AbelHu
Copy link
Author

AbelHu commented Dec 23, 2021

@zhiweiv Good question. @dcantah do you know how we can pick up this change for docker? We also noticed that redundant logs still exists

@zhiweiv
Copy link

zhiweiv commented Dec 23, 2021

We are using Windows Containerd, the version is 1.5.8 which is using hcsshim 0.8.23. The fix is only available in hcsshim 0.9.x now.

@dcantah
Copy link
Contributor

dcantah commented Dec 23, 2021

For kube-proxy here's the PR that would've gotten rid of these kubernetes/kubernetes#104880. It looks like it's going into 1.23

@AbelHu
Copy link
Author

AbelHu commented Dec 23, 2021

It seems like that we need to cherry-pick kubernetes/kubernetes#104880 to old versions.

@zhiweiv
Copy link

zhiweiv commented Dec 23, 2021

We are investigating an issue about hns load balancer rule missing for kube-dns service on Windows nodes, these logs are really annoying.

@zhiweiv
Copy link

zhiweiv commented Dec 23, 2021

@AbelHu
Do you know the AKS 1.23 release plan?

@AbelHu
Copy link
Author

AbelHu commented Dec 23, 2021

@AbelHu
Copy link
Author

AbelHu commented Dec 23, 2021

@zhiweiv What is the issue about hns load balancer rule missing for kube-dns service? You can try to upgrade your cluster or create new Windows agent pools to get the fix in https://github.com/Azure/AgentBaker/pull/1352/files.

There is a known issue caused by overlap port.

Policy creation failed: hcnCreateLoadBalancer failed in Win32: The specified port already exists.

The port was already reserved in the tcpip stack so the reservation would fail leading to failure to apply policy. Due to this failure the HNS load balancer policy for LoadBalancer IP would not be applied leading to the pods behind that load balancer to not being reachable.

@zhiweiv
Copy link

zhiweiv commented Dec 23, 2021

I found same error during the problem period, it should be the root cause, I updated AKS to 1.21.7(AKSWindows-2019-containerd-17763.2366.211215) today, will see if it gets fixed.

@zhiweiv
Copy link

zhiweiv commented Dec 23, 2021

Seems my error is slightly different with yours:cry:
E1222 10:21:07.484910 5948 proxier.go:1202] "Policy creation failed" err="hcnCreateLoadBalancer failed in Win32: The switch-port was not found. (0x803b0007) {\"Success\":false,\"Error\":\"The switch-port was not found. \",\"ErrorCode\":2151350279}"

My problem is: at certain time, all pods can't resolve dns suddenly, you can find the hns load balancer rule is missing for kube-dns service by hnsdiag list loadbalancers, restart kube-proxy will recover(I think it rebuild lb rules after reboot). It may occurs every 2~3 weeks on any Window node since September.

@zhiweiv
Copy link

zhiweiv commented Dec 24, 2021

@AbelHu
Unfortunately my issue reproduced again after upgrade AKS to latest. I am keeping the problem Windows node without restart, anything you want to query from that node?

Should I create a SR or open a new issue somewhere?

@AbelHu
Copy link
Author

AbelHu commented Dec 24, 2021

@zhiweiv Yes. Your issue is not related to this github issue. Please file a support ticket for your issue

@zhiweiv
Copy link

zhiweiv commented Dec 24, 2021

I found not just kube-dns, some non-system svc are also missing, I plan to get more evidence before file SR.

Got a lot of useful information from this thread, thanks.

princepereira pushed a commit to princepereira/hcsshim that referenced this issue Aug 28, 2024
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
princepereira pushed a commit to microsoft/hnslib that referenced this issue Sep 19, 2024
Kubeproxy logs are filled with redudnant version check spam from an unexported call that's invoked
as part of checking if a feature is supported. The logs don't detail what feature(s) are even being checked
so it just seems like spam. With the way things are implemented all of the hcn features are checked for support in
any of the `hcn.XSupported()` calls not just the one being checked, so these logs come up quite a bit if there's
many features that aren't supported on the machine.

Add two new logs in a sync.Once that logs the HNS version and supported features. This should be enough
to investigate version issues.

Should remedy microsoft/hcsshim#1043

Signed-off-by: Daniel Canter <dcanter@microsoft.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

4 participants