chore(e2e): extend logging test to 3 node cluster #18806

ghouscht · 2024-10-29T11:39:43Z

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 68.75%. Comparing base (3696b32) to head (8d094d2).

❗ Current head 8d094d2 differs from pull request most recent head cb19f64

Please upload reports for the commit cb19f64 to get more accurate results.

❗ Your organization needs to install the Codecov GitHub app to enable full functionality.

Additional details and impacted files

see 21 files with indirect coverage changes

@@            Coverage Diff             @@
##             main   #18806      +/-   ##
==========================================
+ Coverage   68.73%   68.75%   +0.02%     
==========================================
  Files         420      420              
  Lines       35512    35512              
==========================================
+ Hits        24410    24418       +8     
+ Misses       9675     9663      -12     
- Partials     1427     1431       +4

Continue to review full report in Codecov by Sentry.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 3696b32...cb19f64. Read the comment docs.

serathius · 2024-10-29T18:37:10Z

tests/e2e/logging_test.go

+
+			var lines []string
+			for i := range tc.clusterSize {
+				lines = append(lines, epc.Procs[i].Logs().Lines()...)


Think we need to collect log lines after we close the server, did you encounter error with that?

If I remember safely get logs from closed process you need to get handle of logs epc.Procs[i].Logs() before closing process and call .Lines() after closing.

I did encounter the allowed error but apparently not all the time. It indeed does make a difference if .Lines() is called after closing. By doing so the resulting log lines seem to be constant. Will update the PR.

serathius · 2024-10-29T18:40:41Z

tests/e2e/logging_test.go

+		{
+			name:          "single node cluster",
+			clusterSize:   1,
+			allowedErrors: map[string]bool{"setting up serving from embedded etcd failed.": true},


Would be good to followup why we get this log.

cc @jmhbnz @ahrtr

Yes, saw the comment in the issue. From what I saw in release-3.5 branch this does not happen. I'll have a look where exactly it comes from.

Interesting, thanks @ghouscht !

It seems that there are multiple sources for this error. One example is:

{"level":"error","ts":"2024-10-30T09:17:44.048443+0100","caller":"embed/etcd.go:875","msg":"setting up serving from embedded etcd failed.","error":"http: Server closed" ...

and that is because the errHandler function (https://github.com/ghouscht/etcd/blob/issue-17329/server/embed/etcd.go#L873-L875) does not check for the http.ErrServerClosed error. This error is always returned by Serve methods after a call to Close or Shutdown: https://pkg.go.dev/net/http#ErrServerClosed.

After ignoring the error mentioned above I also saw this:

{"level":"error","ts":"2024-10-30T09:17:44.048443+0100","caller":"embed/etcd.go:875","msg":"setting up serving from embedded etcd failed.","error":"accept tcp 127.0.0.1:20000: use of closed network connection" ...

Currently trying to figure out where this comes from.

The error logs are generated when closing/shutting down etcd. The listeners are closed firstly, then the accepter will return errors. They should be expected. One possible additional test case is to verify that there is no any error logs before closing etcd, which of course can be discussed & implemented separately.

{"level":"info","ts":"2024-10-30T08:25:35.363864Z","caller":"osutil/interrupt_unix.go:65","msg":"received signal; shutting down","signal":"interrupt"} {"level":"info","ts":"2024-10-30T08:25:35.363960Z","caller":"embed/etcd.go:398","msg":"closing etcd server","name":"default","data-dir":"default.etcd","advertise-peer-urls":["http://localhost:2380"],"advertise-client-urls":["http://localhost:2379"]} ...... {"level":"error","ts":"2024-10-30T08:25:35.364157Z","caller":"embed/etcd.go:874","msg":"setting up serving from embedded etcd failed.","error":"http: Server closed","stacktrace":"go.etcd.io/etcd/server/v3/embed.(*Etcd).errHandler\n\tgo.etcd.io/etcd/server/v3/embed/etcd.go:874\ngo.etcd.io/etcd/server/v3/embed.(*serveCtx).serve.func3\n\tgo.etcd.io/etcd/server/v3/embed/serve.go:176"} {"level":"error","ts":"2024-10-30T08:25:35.364250Z","caller":"embed/etcd.go:874","msg":"setting up serving from embedded etcd failed.","error":"accept tcp 127.0.0.1:2379: use of closed network connection","stacktrace":"go.etcd.io/etcd/server/v3/embed.(*Etcd).errHandler\n\tgo.etcd.io/etcd/server/v3/embed/etcd.go:874\ngo.etcd.io/etcd/server/v3/embed.(*Etcd).serveClients.func1\n\tgo.etcd.io/etcd/server/v3/embed/etcd.go:776"} ... {"level":"error","ts":"2024-10-30T08:25:35.394822Z","caller":"embed/etcd.go:874","msg":"setting up serving from embedded etcd failed.","error":"accept tcp 127.0.0.1:2380: use of closed network connection","stacktrace":"go.etcd.io/etcd/server/v3/embed.(*Etcd).errHandler\n\tgo.etcd.io/etcd/server/v3/embed/etcd.go:874\ngo.etcd.io/etcd/server/v3/embed.(*Etcd).servePeers.func3\n\tgo.etcd.io/etcd/server/v3/embed/etcd.go:614"}

Yeah this is what I figured out as well. In that case these errors are expected and we could simply adapt the errorHandler function to ignore them, e.g. like this:

if err != nil && !errors.Is(err, http.ErrServerClosed) && !errors.Is(err, net.ErrClosed) { e.GetLogger().Error("setting up serving from embedded etcd failed.", zap.Error(err)) }

It's difficult to be certain whether http.ErrServerClose or net.ErrClosed is expected by just one error itself. Suggest not to change the production code for now.

But I think it is. https://cs.opensource.google/go/go/+/refs/tags/go1.23.2:src/net/http/server.go;l=3286-3288;drc=773767def0e0f29584a69bd760430167b7479d7d
http.ErrServerClose means.

Signed-off-by: Thomas Gosteli <[email protected]>

ahrtr · 2024-10-30T08:49:12Z

/ok-to-test

ahrtr

LGTM

Thanks

k8s-ci-robot · 2024-10-30T09:31:14Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: ahrtr, ghouscht, serathius

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~~ [ahrtr,serathius]

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

k8s-ci-robot added area/testing needs-ok-to-test labels Oct 29, 2024

k8s-ci-robot added the size/M label Oct 29, 2024

ghouscht force-pushed the issue-17329 branch 2 times, most recently from cd7b0f9 to 7b37673 Compare October 29, 2024 11:45

ghouscht force-pushed the issue-17329 branch from 7b37673 to 576c797 Compare October 29, 2024 13:49

ghouscht mentioned this pull request Oct 29, 2024

[3.5] chore(e2e): backport TestNoErrorLogsDuringNormalOperations test #18807

Merged

serathius reviewed Oct 29, 2024

View reviewed changes

chore(e2e): extend logging test to 3 node cluster

cb19f64

Signed-off-by: Thomas Gosteli <[email protected]>

ghouscht force-pushed the issue-17329 branch from 576c797 to cb19f64 Compare October 30, 2024 07:47

k8s-ci-robot added ok-to-test and removed needs-ok-to-test labels Oct 30, 2024

serathius approved these changes Oct 30, 2024

View reviewed changes

k8s-ci-robot added the approved label Oct 30, 2024

ahrtr approved these changes Oct 30, 2024

View reviewed changes

ahrtr added the stage/merge-when-tests-green label Oct 30, 2024

ahrtr merged commit 10de4d6 into etcd-io:main Oct 30, 2024
35 checks passed

ghouscht deleted the issue-17329 branch October 30, 2024 09:46

This was referenced Oct 30, 2024

[3.4] chore(e2e): backport TestNoErrorLogsDuringNormalOperations test #18809

Merged

Add an e2e tests that detects error logs during etcd bootstrap #17329

Open

Receiving error logs while trying to perform etcd operations #17424

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

chore(e2e): extend logging test to 3 node cluster #18806

chore(e2e): extend logging test to 3 node cluster #18806

ghouscht commented Oct 29, 2024

k8s-ci-robot commented Oct 29, 2024

codecov-commenter commented Oct 29, 2024 •

edited

Loading

serathius Oct 29, 2024 •

edited

Loading

ghouscht Oct 30, 2024

serathius Oct 29, 2024

serathius Oct 29, 2024

ghouscht Oct 30, 2024

serathius Oct 30, 2024

ghouscht Oct 30, 2024

ahrtr Oct 30, 2024

ghouscht Oct 30, 2024

ahrtr Oct 30, 2024

serathius Oct 31, 2024

ahrtr commented Oct 30, 2024

ahrtr left a comment

k8s-ci-robot commented Oct 30, 2024

chore(e2e): extend logging test to 3 node cluster #18806

chore(e2e): extend logging test to 3 node cluster #18806

Conversation

ghouscht commented Oct 29, 2024

k8s-ci-robot commented Oct 29, 2024

codecov-commenter commented Oct 29, 2024 • edited Loading

Codecov Report

serathius Oct 29, 2024 • edited Loading

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

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

Choose a reason for hiding this comment

ahrtr commented Oct 30, 2024

ahrtr left a comment

Choose a reason for hiding this comment

k8s-ci-robot commented Oct 30, 2024

codecov-commenter commented Oct 29, 2024 •

edited

Loading

serathius Oct 29, 2024 •

edited

Loading