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.

Sign up for GitHub

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

[proxytest] Wait all requests to finish before closing the server #5950

Merged
merged 4 commits into from
Nov 7, 2024
Merged

[proxytest] Wait all requests to finish before closing the server #5950

Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
a06cf6f
proxytest: wait all requests to finish before closing the server
AndersonQ Nov 5, 2024
f34fc7f
close the server first
AndersonQ Nov 6, 2024
4993aab
close after last request
AndersonQ Nov 6, 2024
8482891
add comment
AndersonQ Nov 6, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 20 additions & 3 deletions testing/proxytest/proxytest.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -38,6 +38,7 @@ type Proxy struct {
// proxiedRequests is a "request log" for every request the proxy receives.
proxiedRequests []string
proxiedRequestsMu sync.Mutex
requestsWG *sync.WaitGroup

opts options
log *slog.Logger
Expand Down Expand Up @@ -164,8 +165,9 @@ func New(t *testing.T, optns ...Option) *Proxy {
lv = slog.LevelDebug
}
p := Proxy{
opts: opts,
client: opts.client,
requestsWG: &sync.WaitGroup{},
opts: opts,
client: opts.client,
log: slog.New(slog.NewTextHandler(logfWriter(opts.logFn), &slog.HandlerOptions{
Level: lv,
})),
Expand All @@ -176,6 +178,12 @@ func New(t *testing.T, optns ...Option) *Proxy {

p.Server = httptest.NewUnstartedServer(
http.HandlerFunc(func(ww http.ResponseWriter, r *http.Request) {
// Sometimes, on CI obviously, the last log happens after the test
// finishes. See https://github.com/elastic/elastic-agent/issues/5869.
// Therefore, let's add an extra layer to try to avoid that.
p.requestsWG.Add(1)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just a maybe stupid question, but my understanding of it is that we increment the waitgroup on each request. Don't we know how many request we are gonna perform on this test so we can add them beforehand and leave only requestsWG.Done() inside the handler func?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no, we don't. The proxy is used on tests and each test might vary, or even not be possible to know for sure how many requests will go through the proxy

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

just thinking out loud here; 🙂 how do we cover for the scenario where there are still incoming requests but for some reason one of them manages to call Done() on the syncgroup and cause the Wait() in Close() to exit while other incoming ones haven't executed the Add() on the syncgroup yet?!

Copy link
Member Author

@AndersonQ AndersonQ Nov 6, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I updated it to close the server first: https://github.com/elastic/elastic-agent/pull/5950/files#diff-a0f5baf4d9cd4570b51a51302d316d3628ef5833bae89a0819aa1abfce8ce2deR254

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

moving the close before the wait is effectively the same code as before though right?! I mean from the description of the issue "Makes the proxytest to wait all requests to finish before closing the underlying HTTP server" I understand that the reason behind the issue is that we call p.Server.Close() before all requests have been done, right?!

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

no, the point is that p.Server.Close() should wait all requests to finish, then return.
The last request log should happen before the server closes, but, as we see in the test failing, some how it isn't the case.
That's why I added another barrier to try to force the request log to be logged before the test ends.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I still don't see how p.Server.Close() waits for all requests to finish especially now that it is before p.requestsWG.Wait(); p.Close() will wait probably for some requests to finish until a syncgroup.Done() inside the HandlerFunc manages to lower the syncgroup enough to cause the p.requestsWG.Wait() to exit. 🙂

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That's right, the wait has to come before.
The main idea here is to try to delay a bit the end of the test, just enough for the last request log to be logged before the test end.

That's why it isn't a huge problem if a request slips over the wait group.

Copy link
Contributor

@pkoutsovasilis pkoutsovasilis Nov 6, 2024 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am far from an expert in this particular piece of code, but the case that we have here, reminds me a lot some other rare cases where we need close a channel on the readers end without knowing if the writers are done writing to it. Usually we treat such cases with first shutting down the writers (here should be the components that make requests to the proxy) then, if we have no shutdown confirmation from the writers, we wait as much as we think the writers should take to shutdown (not ideal) and then we close the channel (the proxy server in this case). Would a similar approach work here?! could we at each test "shutdown" the components that make requests to the proxy first and then close the proxy server?

defer p.requestsWG.Done()

w := &proxyResponseWriter{w: ww}

requestID := uuid.Must(uuid.NewV4()).String()
Expand All @@ -187,7 +195,7 @@ func New(t *testing.T, optns ...Option) *Proxy {

p.ServeHTTP(w, rrr)

opts.logFn(fmt.Sprintf("[%s] DONE %d - %s %s %s %s\n",
p.log.Info(fmt.Sprintf("[%s] DONE %d - %s %s %s %s\n",
requestID, w.statusCode, r.Method, r.URL, r.Proto, r.RemoteAddr))
}),
)
Expand Down Expand Up @@ -245,6 +253,15 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
p.serveHTTP(w, r)
}

func (p *Proxy) Close() {
// Sometimes, on CI obviously, the last log happens after the test
// finishes. See https://github.com/elastic/elastic-agent/issues/5869.
// So, manually wait all ongoing requests to finish.
p.requestsWG.Wait()

p.Server.Close()
}

func (p *Proxy) serveHTTP(w http.ResponseWriter, r *http.Request) {
resp, err := p.processRequest(r)
if err != nil {
Expand Down