Skip to content
This repository has been archived by the owner on Aug 23, 2023. It is now read-only.

Replaced Macaron logger with custom logger enabling query statistics #1634

Merged
merged 8 commits into from
Feb 7, 2020

Conversation

fkaleo
Copy link
Contributor

@fkaleo fkaleo commented Jan 27, 2020

Disabled Macaron logger. Replaced with a custom logger that only logs errors and render queries. Query information is embedded to enable useful statistics, such as the query, orgID, sourceIP, etc.

Example log:
ts=2020-01-27T11:03:23.961343521Z traceID=49a071d27275ff00 msg="POST /render?format=json&from=-6h&maxDataPoints=413&target=aliasByNode%28metrictank.stats.docker-env.default.%2A.metrics_active.gauge32%2C+3%2C4%29&until=now (200) 81.505189ms" orgID=1 sourceIP="172.21.0.1"

Fixes #1538

@fkaleo fkaleo requested a review from replay January 27, 2020 11:22
@Dieterbe
Copy link
Contributor

does it log the parameters too if they came in as POST fields?

ctx.Resp = &LoggingResponseWriter{
ResponseWriter: ctx.Resp,
}
rw := ctx.Resp.(*LoggingResponseWriter)
Copy link
Contributor

Choose a reason for hiding this comment

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

instead of directly assigning &LoggingResponseWriter{... to ctx.Resp and then having to type assert, wouldn't it be nicer to initialize that into a variable which then gets assigned into ctx.Resp like

rw = LoggingResponseWriter{
			ResponseWriter: ctx.Resp,
		}
ctx.Resp = &rw

Not sure if that's just me, but if possible I prefer to avoid type assertions.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Thanks! Fixed in 3e51444

@replay
Copy link
Contributor

replay commented Jan 27, 2020

We have instances which receive >=300 requests on /render per second, so i think it's worth it to try to save allocations in this logging logic. There are currently a lot of temporary string variables getting allocated which then get concatenated into the logline if they're !="", you could use something like strings.Builder and just directly write those string values and then pool the builders in a sync.Pool to reduce the number of allocations.

}

func colorLog(statusCode int, log string) string {
if statusCode >= 200 && statusCode <= 202 {
Copy link
Contributor

Choose a reason for hiding this comment

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

shouldn't all 2xx get the same color

Copy link
Contributor

Choose a reason for hiding this comment

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

color? we don't want colored logs?

Copy link
Contributor

Choose a reason for hiding this comment

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

Doesn't hurt to have colors... I don't think the colors would matter much for us, especially not looking at the logs in Loki because I suspect that the colors won't be visible there. But when considering how to increase Metrictank adoption I think colored logs might make a better first impression when somebody looks at MT for the first time.

Copy link
Member

Choose a reason for hiding this comment

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

dont add colors.

Most logging frameworks only use colors when they detect that the logs are being written to a terminal, because only terminals know how to show colors. If you add the control characters when outputing to destinations that dont support terminal control colors, the control characters are just rendered as text and make the log lines hard to read.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Doesn't hurt to have colors... I don't think the colors would matter much for us, especially not looking at the logs in Loki because I suspect that the colors won't be visible there. But when considering how to increase Metrictank adoption I think colored logs might make a better first impression when somebody looks at MT for the first time.

Grafana renders colors when pulling logs from Loki.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Removed color logging in d979e98

Copy link
Contributor

Choose a reason for hiding this comment

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

And how does it know what color to use? I would hope it does this by looking at labels or the log level, rather then by looking for terminal control chars. The former seems simpler and better. Typically one filters by log level or keyword anyway, that's what I think we should encourage at least

@fkaleo
Copy link
Contributor Author

fkaleo commented Jan 28, 2020

does it log the parameters too if they came in as POST fields?

yes it does, it transforms them into URL parameters

paramsAsString += "?"
paramsAsString += ctx.Req.Form.Encode()
}
content += fmt.Sprintf(" msg=\"%s %s%s (%v) %v\" orgID=%d", ctx.Req.Method, ctx.Req.URL.Path, paramsAsString, rw.Status(), time.Since(start), ctx.OrgId)
Copy link
Member

Choose a reason for hiding this comment

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

I feel that the statuscode and request duration should be named fields in the log, rather then being put in 'msg'. Also, is I feel that 'request' would be a better field name than 'msg'

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I agree. I did it that way to copy Cortex's way.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

I'd like to preserve that compatibility with Cortex if that's ok with you?

@fkaleo
Copy link
Contributor Author

fkaleo commented Jan 31, 2020

We have instances which receive >=300 requests on /render per second, so i think it's worth it to try to save allocations in this logging logic. There are currently a lot of temporary string variables getting allocated which then get concatenated into the logline if they're !="", you could use something like strings.Builder and just directly write those string values and then pool the builders in a sync.Pool to reduce the number of allocations.

Using a strings.Builder since 001eef8 however I am not sure a sync.Pool would help much as allocating a new strings.Builder is probably as cheap as reusing an existing one on which we called .Reset()

)

var (
logHeaders = false
Copy link
Contributor

Choose a reason for hiding this comment

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

what's with this variable? should this be configurable?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

perhaps in the future, disabled by default for now.

@replay
Copy link
Contributor

replay commented Feb 7, 2020

When adding config options they must also be added to metrictank-sample.ini (point 8 https://github.com/grafana/metrictank/blob/master/docs/CONTRIBUTING.md#when-contributing-prs) and then you can run scripts/dev/sync-configs.sh to sync the change to the other versions of the MT config in the repo

Copy link
Contributor

@replay replay left a comment

Choose a reason for hiding this comment

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

LGTM

@fkaleo fkaleo merged commit 5eedf84 into master Feb 7, 2020
@fkaleo fkaleo deleted the custom_logger branch February 7, 2020 21:21
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

Implement Metrictank query logging
4 participants