Improve logs when there is a timeout error #1946

hty690 · 2021-03-11T07:45:13Z

The agent logs will print the failure message when the connection to
the controller is timeout. Also adding HealthCheck to remind
the users of the connectivity issue.

Fixes #822

vmwclabot · 2021-03-11T07:45:20Z

@hty690, you must sign our contributor license agreement before your changes are merged. Click here to sign the agreement. If you are a VMware employee, read this for further instruction.

vmwclabot · 2021-03-11T07:53:05Z

@hty690, your company's legal contact has approved your signed contributor license agreement. It will also be reviewed by VMware, but the merge can proceed.

tnqn · 2021-03-11T10:19:31Z

pkg/agent/controller/networkpolicy/networkpolicy_controller.go

@@ -576,6 +576,11 @@ func (w *watcher) watch() {
 		klog.Warningf("Failed to start watch for %s: %v", w.objectType, err)
 		return
 	}
+	_, ok := watcher.(*watch.StreamWatcher)


Please add comment for this handling for others to understand.

The unit test failure failed because of this. It should be because the fake client used in test is not a StreamWatcher. Maybe your original approach that compares the type of watch with watch.NewEmptyWatch() can resolve this but it looks a little implementation intrusive (maybe current approach is same).

@antoninbas what's your opinion here? The context is, the Watch method does not return error if it's a timeout error or "ProbableEOF" and return watch.NewEmptyWatch() instead, that's why you saw no log about connection problem in the issue. See https://github.com/kubernetes/kubernetes/blob/823fa75643bdc352a51cbbc83b55420734832eda/staging/src/k8s.io/client-go/rest/request.go#L702-L709

tnqn · 2021-03-11T10:47:03Z

cmd/antrea-agent/agent.go

+		}
+		return fmt.Errorf("Some watchers may not be connected")
+	})
+	apiServer.GenericAPIServer.AddHealthChecks(check)


HealthCheck will be added to livezChecks too, what the issue asked was watcher's connection state should be reflected in readiness probe.

tnqn · 2021-03-11T10:52:52Z

@hty690 please add description to the commit message and PR description about what else the PR does, e.g. improving logs when there is a timeout error, and don't add trailing period to the title of commit message and PR. See https://github.com/golang/go/wiki/CommitMessage.

codecov-io · 2021-03-11T13:08:34Z

Codecov Report

Merging #1946 (a3081a6) into main (e80ab3b) will increase coverage by 3.13%.
The diff coverage is 62.50%.

@@            Coverage Diff             @@
##             main    #1946      +/-   ##
==========================================
+ Coverage   64.35%   67.48%   +3.13%     
==========================================
  Files         193      195       +2     
  Lines       16967    16882      -85     
==========================================
+ Hits        10919    11393     +474     
+ Misses       4899     4305     -594     
- Partials     1149     1184      +35

Flag	Coverage Δ
e2e-tests	`48.40% <62.50%> (?)`
kind-e2e-tests	`56.01% <62.50%> (+0.80%)`	⬆️
unit-tests	`41.89% <0.00%> (+0.24%)`	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Impacted Files	Coverage Δ
...ntroller/networkpolicy/networkpolicy_controller.go	`70.03% <0.00%> (-0.70%)`	⬇️
pkg/agent/apiserver/apiserver.go	`69.11% <100.00%> (+1.93%)`	⬆️
pkg/apiserver/certificate/cacert_controller.go	`55.83% <0.00%> (-10.01%)`	⬇️
pkg/apiserver/apiserver.go	`87.25% <0.00%> (-1.97%)`	⬇️
pkg/agent/agent_linux.go	`100.00% <0.00%> (ø)`
pkg/controller/traceflow/controller.go	`69.48% <0.00%> (ø)`
pkg/agent/openflow/pipeline_other.go	`66.66% <0.00%> (ø)`
pkg/agent/openflow/client_other.go	`0.00% <0.00%> (ø)`
pkg/agent/openflow/network_policy.go	`76.31% <0.00%> (+0.59%)`	⬆️
pkg/agent/cniserver/pod_configuration.go	`54.68% <0.00%> (+0.78%)`	⬆️
... and 26 more

vmwclabot · 2021-03-11T17:07:00Z

@hty690, VMware has approved your signed contributor license agreement.

jianjuns · 2021-03-15T20:28:29Z

pkg/agent/controller/networkpolicy/networkpolicy_controller.go

@@ -576,7 +576,12 @@ func (w *watcher) watch() {
 		klog.Warningf("Failed to start watch for %s: %v", w.objectType, err)
 		return
 	}
-
+	//Make sure that watcher is not the type of watch.NewEmptyWatch()


//Make sure -> // Makesure

pkg/agent/controller/networkpolicy/networkpolicy_controller.go

tnqn · 2021-03-16T07:49:37Z

pkg/agent/controller/networkpolicy/networkpolicy_controller.go

@@ -584,6 +585,11 @@ func (w *watcher) watch() {
 		klog.Warningf("Failed to start watch for %s: %v", w.objectType, err)
 		return
 	}
+	// Makesure that watcher is not the type of watch.NewEmptyWatch()
+	if reflect.TypeOf(watcher) == reflect.TypeOf(watch.NewEmptyWatch()) {


Declare the latter as a variable to avoid unnecessary construction of emptyWatch everytime we need to compare.

tnqn · 2021-03-16T09:49:41Z

pkg/agent/apiserver/apiserver.go

+		if npq.GetControllerConnectionStatus() {
+			return nil
+		}
+		return fmt.Errorf("Some watchers may not be connected")


returned error shouldn't be capitalized

tnqn · 2021-03-16T09:53:05Z

pkg/agent/controller/networkpolicy/networkpolicy_controller.go

@@ -584,6 +585,11 @@ func (w *watcher) watch() {
 		klog.Warningf("Failed to start watch for %s: %v", w.objectType, err)
 		return
 	}
+	// Makesure that watcher is not the type of watch.NewEmptyWatch()
+	if reflect.TypeOf(watcher) == reflect.TypeOf(watch.NewEmptyWatch()) {
+		klog.Warningf("Failed to start watch for %s. Something wrong with the connection?", w.objectType)


Suggested change

klog.Warningf("Failed to start watch for %s. Something wrong with the connection?", w.objectType)

klog.Warningf("Failed to start watch for %s. Please ensure antrea service is reachable for the agent", w.objectType)

tnqn · 2021-03-16T09:56:39Z

pkg/agent/apiserver/apiserver.go

@@ -97,6 +99,14 @@ func New(aq agentquerier.AgentQuerier, npq querier.AgentNetworkPolicyInfoQuerier
 	if err != nil {
 		return nil, err
 	}
+	// Add readiness probe to check the status of watchers.
+	check := healthz.NamedCheck("watcher", func(_ *http.Request) error {


could you move this to newConfig given that function initializes the whole config?

The agent logs will print the failure message when the connection to the controller is timeout. Also adding readiness probe to remind the users of the connectivity issue. Fixes antrea-io#822

tnqn

LGTM, thanks.
@antoninbas could you check if this PR addesses the original issue?

antoninbas

I was able to test this and it meets expectations, except for the readiness probe failing with reason withheld which I am unsure about.

antoninbas · 2021-03-17T18:28:34Z

pkg/agent/apiserver/apiserver.go

+	// Add readiness probe to check the status of watchers.
+	check := healthz.NamedCheck("watcher", func(_ *http.Request) error {
+		if npq.GetControllerConnectionStatus() {
+			return nil
+		}
+		return fmt.Errorf("some watchers may not be connected")
+	})


when I test the probe, I get [-]watcher failed: reason withheld

reason withheld is not what I'd expect here, shouldn't it say some watchers may not be connected?

Seems withheld intentionally:
https://github.com/kubernetes/kubernetes/blob/480b4c74b858a9caac0b33cb4d9a1ab30ae65cf4/staging/src/k8s.io/apiserver/pkg/server/healthz/healthz.go#L227-L231

pkg/agent/controller/networkpolicy/networkpolicy_controller.go

Co-authored-by: Antonin Bas <[email protected]>

antoninbas

LGTM

tnqn · 2021-03-18T02:07:40Z

/test-all

tnqn reviewed Mar 11, 2021

View reviewed changes

hty690 force-pushed the log_issue branch from 3ff16e7 to d016c18 Compare March 11, 2021 12:16

hty690 changed the title ~~Add readiness probe for the agent.~~ Improve logs when there is a timeout error Mar 11, 2021

jianjuns reviewed Mar 15, 2021

View reviewed changes

hty690 force-pushed the log_issue branch 2 times, most recently from 4f74539 to e8b73e2 Compare March 16, 2021 07:38

tnqn reviewed Mar 16, 2021

View reviewed changes

Improve logs when there is a timeout error

966ca58

The agent logs will print the failure message when the connection to the controller is timeout. Also adding readiness probe to remind the users of the connectivity issue. Fixes antrea-io#822

hty690 force-pushed the log_issue branch from c1a1a74 to 966ca58 Compare March 16, 2021 11:03

tnqn previously approved these changes Mar 17, 2021

View reviewed changes

antoninbas reviewed Mar 17, 2021

View reviewed changes

Update pkg/agent/controller/networkpolicy/networkpolicy_controller.go

a3081a6

Co-authored-by: Antonin Bas <[email protected]>

hty690 dismissed tnqn’s stale review via a3081a6 March 18, 2021 01:15

antoninbas approved these changes Mar 18, 2021

View reviewed changes

tnqn merged commit c086437 into antrea-io:main Mar 18, 2021

hty690 deleted the log_issue branch March 30, 2021 02:53

tnqn mentioned this pull request Nov 16, 2023

Block a Pod's IP packets until its NetworkPolicies are realized #5698

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Improve logs when there is a timeout error #1946

Improve logs when there is a timeout error #1946

hty690 commented Mar 11, 2021 •

edited

Loading

vmwclabot commented Mar 11, 2021

vmwclabot commented Mar 11, 2021

tnqn Mar 11, 2021

tnqn Mar 11, 2021

tnqn commented Mar 11, 2021

codecov-io commented Mar 11, 2021 •

edited

Loading

vmwclabot commented Mar 11, 2021

jianjuns Mar 15, 2021

tnqn Mar 16, 2021

tnqn Mar 16, 2021

tnqn Mar 16, 2021

tnqn Mar 16, 2021

tnqn left a comment

antoninbas left a comment

antoninbas Mar 17, 2021

tnqn Mar 18, 2021

antoninbas left a comment

tnqn commented Mar 18, 2021

	klog.Warningf("Failed to start watch for %s. Something wrong with the connection?", w.objectType)
	klog.Warningf("Failed to start watch for %s. Please ensure antrea service is reachable for the agent", w.objectType)

Improve logs when there is a timeout error #1946

Improve logs when there is a timeout error #1946

Conversation

hty690 commented Mar 11, 2021 • edited Loading

vmwclabot commented Mar 11, 2021

vmwclabot commented Mar 11, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tnqn commented Mar 11, 2021

codecov-io commented Mar 11, 2021 • edited Loading

Codecov Report

vmwclabot commented Mar 11, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

tnqn left a comment

Choose a reason for hiding this comment

antoninbas left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

antoninbas left a comment

Choose a reason for hiding this comment

tnqn commented Mar 18, 2021

hty690 commented Mar 11, 2021 •

edited

Loading

codecov-io commented Mar 11, 2021 •

edited

Loading