logging: Add ability to deduplicate log messages #48
Conversation
logging/logging.go
Outdated
|
|
||
| "golang.org/x/net/context" | ||
|
|
||
| log "github.com/Sirupsen/logrus" | ||
| "github.com/weaveworks/common/user" | ||
| ) | ||
|
|
||
| const ( | ||
| DEFAULT_DEDUPE_INTERVAL = time.Minute |
This comment was marked as abuse.
This comment was marked as abuse.
Sorry, something went wrong.
| // already seen, increment count and do not log | ||
| ec.count++ | ||
| f.seen[key] = ec | ||
| return false |
This comment was marked as abuse.
This comment was marked as abuse.
Sorry, something went wrong.
logging/logging.go
Outdated
| // 00:01:00 INFO Repeated 3 times: User 123 did xyz | ||
| // The interval argument controls how many seconds to wait for additional messages to arrive before reporting. | ||
| // Increase it to deduplicate more aggressively, decrease it to lower latency from a log occurring to it appearing. | ||
| // Set it to 0 to pick a sensible default value (reccomended). |
This comment was marked as abuse.
This comment was marked as abuse.
Sorry, something went wrong.
logging/logging.go
Outdated
| // you would get: | ||
| // 00:00:00 INFO User 123 did xyz | ||
| // 00:01:00 INFO Repeated 3 times: User 123 did xyz | ||
| // The interval argument controls how many seconds to wait for additional messages to arrive before reporting. |
This comment was marked as abuse.
This comment was marked as abuse.
Sorry, something went wrong.
| // We use a special Formatter to either format the log using the original formatter, or to return "" | ||
| // so nothing will be written for that event. The repeated entries are later logged along with a field flag | ||
| // that tells the formatter to ignore the message. | ||
| stdLogger := log.StandardLogger() |
This comment was marked as abuse.
This comment was marked as abuse.
Sorry, something went wrong.
This comment was marked as abuse.
This comment was marked as abuse.
Sorry, something went wrong.
This comment was marked as abuse.
This comment was marked as abuse.
Sorry, something went wrong.
|
IIRC the motivator for this was the 429 logs coming from cortex. |
|
Yes, this would mean each series is still logged, though if the same series were logged more than once per minute it would still help. We could:
|
Motivating example is to not excessively log the same http 4xx code over and over from the same ip, as this doesn't add info and bloats our log volume. This requires some abuse of logrus to work, but we do this via a formatter which can either emit the original message, or the empty string to log no message (this is harmless). Later, a seperate goroutine will emit a new log that logs the original log and how many times it occurred. We always log the first time we see a given message, then start a timer. If we see the message again at least once in that time frame, we log at the end of the time frame how many times. Note this means we can say "repeated once", which is a little confusing but preferable to displaying the original message unchanged but time delayed, which can be very misleading as there's no indication of the time delay.
|
@jml PTAL, and what are your thoughts on #48 (comment)? |
First, that merging this PR as-is is an incremental improvement so we should just do it. I think @ekimekim's analysis is spot on. The recent change adds both the series name (e.g. I'd be happy to refactor the logging code in Cortex to work with whatever we decide. I wonder if we can get away with something simpler than a 'fields to ignore' that massively complicates things, e.g.
|
|
Does that help at all? |
Sounds like a good use case for a DEBUG level log instead of an INFO, surely? As an aside, do we have the capability to, say, log at DEBUG at the service but only forward INFO and above to loggly? Then we could still get debug logs with kubectl if needed. Anyway, merging this. |
This reverts commit a23f449. It has never de-duplicated a single line for us in production.
This reverts commit a23f449. It has never de-duplicated a single line for us in production.
Revert "logging: Add ability to deduplicate log messages (#48)"
Use strings.Replacer instead of hand-rolled escapeString
Motivating example is to not excessively log the same http 4xx code over and over from the same ip,
as this doesn't add info and bloats our log volume.
This requires some abuse of logrus to work, but we do this via a formatter which can either emit the original message,
or the empty string to log no message (this is harmless). Later, a seperate goroutine will emit a new log
that logs the original log and how many times it occurred.
We always log the first time we see a given message, then start a timer. If we see the message again at least once in that
time frame, we log at the end of the time frame how many times.
Note this means we can say "repeated once", which is a little confusing but preferable to displaying the original message
unchanged but time delayed, which can be very misleading as there's no indication of the time delay.
Fixes https://github.com/weaveworks/service-conf/issues/968