Thanos: query-frontend: 302/304 logged as error

[Jakob3xD]

Thanos, Prometheus and Golang version used:
Thanos Docker: v0.15.0

What happened:
When accessing the query-frontend I can see http 30* reposes logged as error.

What you expected to happen:
304 / 302 should not be logged as error?

How to reproduce it (as minimally and precisely as possible):
304/302 Repose happens when accessing the frontend URL without any suffix. (query-frontend.example.com)
When using a suffix like /graph everything works fine.

Full logs to relevant components:

Logs

level=debug ts=2020-09-16T09:06:32.624357516Z caller=main.go:103 msg="maxprocs: Updating GOMAXPROCS=[4]: determined from CPU quota"
level=info ts=2020-09-16T09:06:32.62521462Z caller=main.go:152 msg="Tracing will be disabled"
level=info ts=2020-09-16T09:06:32.630513034Z caller=query-frontend.go:221 msg="starting query frontend"
level=info ts=2020-09-16T09:06:32.630635804Z caller=intrumentation.go:48 msg="changing probe status" status=ready
level=info ts=2020-09-16T09:06:32.631192499Z caller=intrumentation.go:60 msg="changing probe status" status=healthy
level=info ts=2020-09-16T09:06:32.631351644Z caller=http.go:57 service=http/server component=query-frontend msg="listening for requests and metrics" address=0.0.0.0:80
level=debug ts=2020-09-16T09:11:27.150148397Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB2XPKEMS7D7XHS5EDQ0AX2 http.code=499 http.time_ms=63.399 msg="finished call"
level=debug ts=2020-09-16T09:11:27.151076425Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB2XPKEGRA89P0V1DEWYTKS http.code=499 http.time_ms=64.372 msg="finished call"
level=debug ts=2020-09-16T09:11:27.449224849Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB2XPXFNW5J4GTPSGYJKGE7 http.code=200 http.time_ms=41.355 msg="finished call"
level=debug ts=2020-09-16T09:11:28.384125046Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB2XQVQQFRB7QTQYJ1GYX8V http.code=200 http.time_ms=9.092 msg="finished call"
level=debug ts=2020-09-16T09:11:28.910093219Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB2XRC8MSTW4G5CPM5RQ7YN http.code=200 http.time_ms=5.467 msg="finished call"
level=error ts=2020-09-16T09:18:14.954257553Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3A4X3VNXQMZ5Y11HNX65P http.code=302 http.time_ms=6.052 msg="finished call"
level=debug ts=2020-09-16T09:18:15.268396497Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3A5731WWRRPMX3J0MSRN1 http.code=499 http.time_ms=1.285 msg="finished call"
level=debug ts=2020-09-16T09:18:15.268387879Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3A56VJS4ZZX1BJ8AKMHPH http.code=499 http.time_ms=9 msg="finished call"
level=debug ts=2020-09-16T09:18:15.268857014Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3A56RZQ5ZFNB2RFCDGH7K http.code=499 http.time_ms=12.093 msg="finished call"
level=debug ts=2020-09-16T09:18:15.658672911Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3A5K4Z2KG2VW1V9S9TEVK http.code=200 http.time_ms=6.382 msg="finished call"
level=error ts=2020-09-16T09:18:20.087631371Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3A9XPB743JERY9FEM5PZB http.code=302 http.time_ms=1.604 msg="finished call"
level=debug ts=2020-09-16T09:18:20.296476516Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3AA48BY1ZD1A650R2K6NB http.code=499 http.time_ms=0.218 msg="finished call"
level=debug ts=2020-09-16T09:18:20.297872549Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3AA49C6GM2HMHM24M10QS http.code=499 http.time_ms=0.629 msg="finished call"
level=debug ts=2020-09-16T09:18:20.601504563Z caller=http.go:34 protocol=http http.component=server http.method=query-frontend http.request.id=01EJB3AADMQS3FYJ2MY8VFGP33 http.code=200 http.time_ms=5.351 msg="finished call"

[yeya24]

Yes, I agree 302 shouldn't be logged. @yashrsharma44 What do you think?

[yashrsharma44]

@yeya24 Thanks for pointing out the error, will have a look!

[yashrsharma44]

Yeah, I remember taking a decision of just handling [200,300) and [400,500) at a debug level, and rest at the error level. We can make a change once we decide which the level of [300,400) requests :thinking:
Ref - https://github.com/thanos-io/thanos/blob/master/pkg/logging/options.go#L97

Would encourage the new contributors to take this issue once discussed, it is a pretty small fix :nerd_face:

[aribalam]

I would like to take this up!

[daksh-sagar]

@yashrsharma44 I would like to give it a go as well. What should be the level of logging for 3xx codes though?