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

[adityapwr]

What this PR does:
I've added a logline before returning. When the request is canceled a usual logline(info) is printed but with status 499

Which issue(s) this PR fixes:
Fixes #1136

Checklist

• Tests updated
• Documentation added
• CHANGELOG.md updated - the order of entries should be [CHANGE], [FEATURE], [ENHANCEMENT], [BUGFIX]

[CLAassistant]

All committers have signed the CLA.

[adityapwr]

I added 5sec sleep in FindTraceByID to test this, here are some logs from my test.

grafana_1                   | logger=context userId=0 orgId=1 uname= t=2022-01-23T10:47:14.27+0000 lvl=eror msg="Query data error" error="failed to query data: failed get to tempo: Get \"http://tempo:3200/api/traces/bee1dd5237c8e117\": context canceled" remote_addr=172.20.0.1
grafana_1                   | logger=context userId=0 orgId=1 uname= t=2022-01-23T10:47:14.27+0000 lvl=eror msg="Request Completed" method=POST path=/api/ds/query status=500 remote_addr=172.20.0.1 time_ms=415 size=30 referer="http://localhost:3000/explore?orgId=1&left=%5B%22now-1h%22,%22now%22,%22Tempo%22,%7B%22query%22:%2249f4616bce4a7c98%22,%22queryType%22:%22nativeSearch%22,%22refId%22:%22A%22,%22datasource%22:%7B%22type%22:%22tempo%22,%22uid%22:%22tempo-query%22%7D,%22serviceName%22:%22checkoutservice%22%7D%5D&right=%5B%221642931011494%22,%221642934611494%22,%22Tempo%22,%7B%22query%22:%22bee1dd5237c8e117%22,%22queryType%22:%22traceId%22,%22refId%22:%22A%22%7D%5D"
tempo_1                     | level=error ts=2022-01-23T10:47:14.280004272Z caller=frontend_processor.go:70 msg="error processing requests" address=127.0.0.1:9095 err="rpc error: code = Unknown desc = context canceled"
tempo_1                     | level=error ts=2022-01-23T10:47:14.28024218Z caller=frontend_processor.go:70 msg="error processing requests" address=127.0.0.1:9095 err="rpc error: code = Unknown desc = context canceled"
tempo_1                     | level=info ts=2022-01-23T10:47:14.280543766Z caller=handler.go:72 tenant=single-tenant method=GET traceID=463711e40d6ecc8f url=/api/traces/bee1dd5237c8e117 duration=413.432985ms response_size=0 status=499
tempo_1                     | level=error ts=2022-01-23T10:47:14.280731384Z caller=frontend_processor.go:70 msg="error processing requests" address=127.0.0.1:9095 err="rpc error: code = Unknown desc = context canceled"
tempo_1                     | level=error ts=2022-01-23T10:47:14.280885505Z caller=frontend_processor.go:70 msg="error processing requests" address=127.0.0.1:9095 err="rpc error: code = Unknown desc = context canceled"
tempo_1                     | level=error ts=2022-01-23T10:47:14.281478586Z caller=frontend_processor.go:70 msg="error processing requests" address=127.0.0.1:9095 err="rpc error: code = Unknown desc = context canceled"

[joe-elliott]

Thanks for the contribution! I have wanted something like this in the past. Had one question regarding the status returned.

[joe-elliott]

I think this PR is ready to go. It just needs a small change for the linter:

Error: reponse is a misspelling of response (misspell)

[adityapwr]

apologies, I missed lint. I'll take care from now on.

[joe-elliott]

apologies, I missed lint. I'll take care from now on.

no worries! I forget to lint before pushing all the time 👍

[joe-elliott]

awesome! thanks for the contribution!