Thanos rules fanout OOMs occasionally

[s-urbaniak]

Thanos, Prometheus and Golang version used:
Thanos 0.15.0
Prometheus 2.22.2
Golang 1.15

Object Storage Provider: N/A

What happened: When invoking the /v1/api/rules endpoint, thanos querier OOMs

What you expected to happen: It doesn't OOM

How to reproduce it (as minimally and precisely as possible): So far we have no determinstic reproduction. What we know is that the OOM happens most likely if errors occur during the proxy fanout. This is backed by pprof heap snapshots we gathered during the OOM:

We see ~3GB used memory in the callstack collector of pkg/errors: https://github.com/pkg/errors/blob/5dd12d0cfe7f152f80558d591504ce685299311e/stack.go#L163-L169

Full logs to relevant components:
I don't have a log file at hand but will request one. Previous logs didn't reveal any errors (rules proxy errors are not being logged).

Anything else we need to know:

Environment:

• OS (e.g. from /etc/os-release): RHOS
• Kernel (e.g. uname -a): Unknown
• Others: OpenShift 4.6.8

cc @mbarnes @gsleeman @mrbarge

[s-urbaniak]

cc @bwplotka

[s-urbaniak]

Side note: to me this looks like a recursion issue.

[GiedriusS]

Maybe you also have some goroutine dumps?

[s-urbaniak]

@GiedriusS indeed, to get goroutine dumps was my conclusion as well after investigating the heap dump. I already asked for those.

[s-urbaniak]

I think I have a reproducer. Simulating a 503 response in the prometheus sidecar during a /api/v1/rules request:

diff --git a/pkg/promclient/promclient.go b/pkg/promclient/promclient.go
index 4a4cc525..fc3b0f70 100644
--- a/pkg/promclient/promclient.go
+++ b/pkg/promclient/promclient.go
@@ -129,6 +129,12 @@ func (c *Client) req2xx(ctx context.Context, u *url.URL, method string) (_ []byt
        if err != nil {
                return nil, resp.StatusCode, errors.Wrap(err, "read body")
        }
+
+       if u.Path == "/api/v1/rules" {
+               // let's simulate WAL replay
+               resp.StatusCode = 503
+       }
+
        if resp.StatusCode/100 != 2 {
                return nil, resp.StatusCode, errors.Errorf("expected 2xx response, got %d. Body: %v", resp.StatusCode, string(body))
        }

and executing the TestRulesAPI_Fanout e2e test effectively lets thanos querier consume all CPU and memory on my laptop. Since I can can investigate now locally, continuing with finding the actual root cause which, as stated above, seems to be a recursion issue.

This effectively is a very common scenario in the field where Prometheus is replaying its write ahead log and returning 503 during that time frame.

[bwplotka]

Amazing. Looks like error path is not well tested/leaky!

[s-urbaniak]

Small update: it looks like this is a spinning issue rather than recursion. It seems, that in the case of a 503 response we are hotlooping in the following for loop, never reaching the io.EOF state:

thanos/pkg/rules/proxy.go

Lines 104 to 136 in a62cbb9

	for {
	rule, err := rules.Recv()
	if err == io.EOF {
	return nil
	}
	if err != nil {
	err = errors.Wrapf(err, "receiving rules from rules client %v", stream.client)
	if stream.request.PartialResponseStrategy == storepb.PartialResponseStrategy_ABORT {
	return err
	}
	if err := stream.server.Send(rulespb.NewWarningRulesResponse(err)); err != nil {
	return errors.Wrapf(err, "sending rules error to server %v", stream.server)
	}
	continue
	}
	if w := rule.GetWarning(); w != "" {
	if err := stream.server.Send(rulespb.NewWarningRulesResponse(errors.New(w))); err != nil {
	return errors.Wrapf(err, "sending rules warning to server %v", stream.server)
	}
	continue
	}
	select {
	case stream.channel <- rule.GetGroup():
	case <-ctx.Done():
	return ctx.Err()
	}
	}

.

Continuing investigation.

[s-urbaniak]

Hypothesis: instead of continueing in case of error handling we can simply return nil because the backend actually will never return io.EOF in that case.

[s-urbaniak]

Yes, this seems to do the trick, continuing with writing a dedicated e2e test and submitting a PR.

[s-urbaniak]

closed via #3734