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

Query-frontend doesn't log request details when request is cancelled #1136

Closed
yvrhdn opened this issue Nov 25, 2021 · 3 comments · Fixed by #1241
Closed

Query-frontend doesn't log request details when request is cancelled #1136

yvrhdn opened this issue Nov 25, 2021 · 3 comments · Fixed by #1241
Labels
good first issue Good for newcomers

Comments

@yvrhdn
Copy link
Member

yvrhdn commented Nov 25, 2021

Describe the bug

The query-frontend logs some details about the query when it completes, for example:

level=info ts=2021-11-25T11:32:38.59660534Z caller=handler.go:96 tenant=1 method=GET traceID=57060d6b589d1903 url="/tempo/api/search?x-dbg-exhaustive=true&limit=20" duration=7.079269575s response_size=96 status=200

If you cancel the request before it completes, this log does not appear.

To Reproduce

Steps to reproduce the behavior:

  1. Run Tempo (single binary or distributed, shouldn't matter)
  2. Monitor logs from the query-frontend
  3. Perform a query that is slow (so you have enough time to cancel it)
  4. Cancel the request
  5. Nothing is logged by the query-frontend

Note: it's surprisingly difficult to get a slow query in a normal sized Tempo. To makes this easier to test you might want to introduce a time.Sleep(5 * time.Second) somewhere in the query path.

Expected behavior

I'd expect to see the usual logline, but with status=499.

Additional Context

The log line is printed here:

level.Info(f.logger).Log(
"tenant", orgID,
"method", r.Method,
"traceID", traceID,
"url", r.URL.RequestURI(),
"duration", time.Since(start).String(),
"response_size", contentLength,
"status", statusCode,
)

I believe we should not return early when the request fails:

resp, err := f.roundTripper.RoundTrip(r)
if err != nil {
writeError(w, err)
return
}
if resp == nil {
writeError(w, errors.New("nil resp in ServeHTTP"))
return
}

@yvrhdn yvrhdn added the good first issue Good for newcomers label Nov 25, 2021
@wperron
Copy link
Contributor

wperron commented Nov 26, 2021

Hi 👋 I'll take a look

@josephwoodward
Copy link
Contributor

@wperron Are you still working on this? I'm looking for an issue to pick up so happy to take a look if you've been unable to find the time?

@wperron
Copy link
Contributor

wperron commented Dec 12, 2021

@wperron Are you still working on this? I'm looking for an issue to pick up so happy to take a look if you've been unable to find the time?

I was planning and getting to it this week but feel free to take a look if you want!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
good first issue Good for newcomers
Projects
None yet
3 participants