-
Notifications
You must be signed in to change notification settings - Fork 593
Commit
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
Merge branch 'next' into chore/go-kong-0.18.0
- Loading branch information
Showing
8 changed files
with
321 additions
and
10 deletions.
There are no files selected for viewing
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,134 @@ | ||
| package util | ||
|
|
||
| import ( | ||
| "io" | ||
| "time" | ||
|
|
||
| "github.com/sirupsen/logrus" | ||
| ) | ||
|
|
||
| // ----------------------------------------------------------------------------- | ||
| // Public - Reduced Redudancy Debug Logging | ||
| // ----------------------------------------------------------------------------- | ||
|
|
||
| // MakeDebugLoggerWithReducedRedudancy is a logrus.Logger that "stifles" repetitive logs. | ||
| // | ||
| // The "stifling" mechanism is triggered by one of two conditions the result of which is | ||
| // that the "stifled" log entry will be dropped entirely. | ||
| // | ||
| // The conditions checked are: | ||
| // | ||
| // 1. This logger will drop log entries where an identical log entry has posted within the | ||
| // last "redundantLogEntryBackoff". For example, you could set this to "time.Second * 3" | ||
| // and the result would be that if the logger had already logged an identical message | ||
| // within the previous 3 seconds it will be dropped. | ||
| // | ||
| // 2. This logger will "stifle" redudant entries which are logged consecutively a number of | ||
| // times equal to the provided "redudantLogEntryAllowedConsecutively" number. For example, | ||
| // you could set this to 3 and then if the last 3 log entries emitted were the same message | ||
| // further entries of the same message would be dropped. | ||
| // | ||
| // The caller can choose to set either argument to "0" to disable that check, but setting both | ||
| // to zero will result in no redundancy reduction. | ||
| // | ||
| // NOTE: Please consider this logger a "debug" only logging implementation. | ||
| // This logger was originally created to help reduce the noise coming from the controller | ||
| // during integration tests for better human readability, so keep in mind it was built for | ||
| // testing environments if you're currently reading this and you're considering using it | ||
| // somewhere that would produce production environment logs: there's significant | ||
| // performance overhead triggered by the logging hooks this adds. | ||
| func MakeDebugLoggerWithReducedRedudancy(writer io.Writer, formatter logrus.Formatter, | ||
| redudantLogEntryAllowedConsecutively int, redundantLogEntryBackoff time.Duration, | ||
| ) *logrus.Logger { | ||
| // setup the logger with debug level logging | ||
| log := logrus.New() | ||
| log.Level = logrus.DebugLevel | ||
| log.Formatter = formatter | ||
| log.Out = writer | ||
|
|
||
| // set up the reduced redudancy logging hook | ||
| log.Hooks.Add(newReducedRedundancyLogHook(redundantLogEntryBackoff, redudantLogEntryAllowedConsecutively, formatter)) | ||
| return log | ||
| } | ||
|
|
||
| // ----------------------------------------------------------------------------- | ||
| // Private - Reduced Redudancy Debug Logging | ||
| // ----------------------------------------------------------------------------- | ||
|
|
||
| // reducedRedudancyLogHook is a logrus.Hook that reduces redudant log entries. | ||
| type reducedRedudancyLogHook struct { | ||
| backoff time.Duration | ||
| consecutiveAllowed int | ||
| consecutivePosted int | ||
| formatter logrus.Formatter | ||
| lastMessage string | ||
| timeWindow map[string]bool | ||
| timeWindowStart time.Time | ||
| } | ||
|
|
||
| func newReducedRedundancyLogHook( | ||
| backoff time.Duration, | ||
| consecutive int, | ||
| formatter logrus.Formatter, | ||
| ) *reducedRedudancyLogHook { | ||
| return &reducedRedudancyLogHook{ | ||
| backoff: backoff, | ||
| consecutiveAllowed: consecutive, | ||
| formatter: formatter, | ||
| timeWindowStart: time.Now(), | ||
| timeWindow: map[string]bool{}, | ||
| } | ||
| } | ||
|
|
||
| func (r *reducedRedudancyLogHook) Fire(entry *logrus.Entry) error { | ||
| defer func() { r.lastMessage = entry.Message }() | ||
|
|
||
| // to make this hook work we override the logger formatter to the nilFormatter | ||
| // for some entries, but we also need to reset it here to ensure the default. | ||
| entry.Logger.Formatter = r.formatter | ||
|
|
||
| // if the current entry has the exact same message as the last entry, check the | ||
| // consecutive posting rules for this entry to see whether it should be dropped. | ||
| if r.consecutiveAllowed > 0 && entry.Message == r.lastMessage { | ||
| r.consecutivePosted++ | ||
| if r.consecutivePosted >= r.consecutiveAllowed { | ||
| entry.Logger.SetFormatter(&nilFormatter{}) | ||
| return nil | ||
| } | ||
| } else { | ||
| r.consecutivePosted = 0 | ||
| } | ||
|
|
||
| // determine whether or not the previous time window is still valid and if not create | ||
| // a new time window and return. | ||
| if time.Now().After(r.timeWindowStart.Add(r.backoff)) { | ||
| r.timeWindow = map[string]bool{} | ||
| r.timeWindowStart = time.Now() | ||
| return nil | ||
| } | ||
|
|
||
| // if we're here then the time window is still valid, we need to determine if the | ||
| // current entry would be considered redundant during this time window. | ||
| // if the entry has not yet been seen during this time window, we record it so that | ||
| // future checks can find it. | ||
| if _, ok := r.timeWindow[entry.Message]; ok { | ||
| entry.Logger.SetFormatter(&nilFormatter{}) | ||
| } | ||
| r.timeWindow[entry.Message] = true | ||
|
|
||
| return nil | ||
| } | ||
|
|
||
| func (r *reducedRedudancyLogHook) Levels() []logrus.Level { | ||
| return logrus.AllLevels | ||
| } | ||
|
|
||
| // ----------------------------------------------------------------------------- | ||
| // Private - Nil Logging Formatter | ||
| // ----------------------------------------------------------------------------- | ||
|
|
||
| type nilFormatter struct{} | ||
|
|
||
| func (n *nilFormatter) Format(entry *logrus.Entry) ([]byte, error) { | ||
| return nil, nil | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| Original file line number | Diff line number | Diff line change |
|---|---|---|
| @@ -0,0 +1,127 @@ | ||
| package util | ||
|
|
||
| import ( | ||
| "bytes" | ||
| "encoding/json" | ||
| "strings" | ||
| "testing" | ||
| "time" | ||
|
|
||
| "github.com/sirupsen/logrus" | ||
| "github.com/stretchr/testify/assert" | ||
| "github.com/stretchr/testify/require" | ||
| ) | ||
|
|
||
| func TestDebugLoggerStiflesConsecutiveEntries(t *testing.T) { | ||
| // initialize the debug logger with no backoff time, but a limit of 3 consecutive redudant entries | ||
| buf := new(bytes.Buffer) | ||
| log := MakeDebugLoggerWithReducedRedudancy(buf, &logrus.JSONFormatter{}, 3, time.Millisecond*0) | ||
| assert.True(t, log.IsLevelEnabled(logrus.DebugLevel)) | ||
| assert.False(t, log.IsLevelEnabled(logrus.TraceLevel)) | ||
|
|
||
| // spam the logger with redudant entries and validate that only 3 entries (the limit) were actually emitted | ||
| for i := 0; i < 100; i++ { | ||
| log.Info("test") | ||
| } | ||
| lines := strings.Split(strings.TrimSpace(buf.String()), "\n") | ||
| assert.Len(t, lines, 3) | ||
|
|
||
| // validate the logging data integrity | ||
| for _, line := range lines { | ||
| var entry map[string]string | ||
| require.NoError(t, json.Unmarshal([]byte(line), &entry)) | ||
| assert.Equal(t, "test", entry["msg"]) | ||
| } | ||
| } | ||
|
|
||
| func TestDebugLoggerResetsConsecutiveEntries(t *testing.T) { | ||
| // initialize the debug logger with no backoff time, but a limit of 5 consecutive redudant entries | ||
| buf := new(bytes.Buffer) | ||
| log := MakeDebugLoggerWithReducedRedudancy(buf, &logrus.JSONFormatter{}, 5, time.Millisecond*0) | ||
| assert.True(t, log.IsLevelEnabled(logrus.DebugLevel)) | ||
| assert.False(t, log.IsLevelEnabled(logrus.TraceLevel)) | ||
|
|
||
| // spam the logger with redudant entries and validate that only 3 entries (the limit) were actually emitted | ||
| for i := 0; i < 100; i++ { | ||
| if i%5 == 0 { | ||
| log.Info("break") | ||
| continue | ||
| } | ||
| log.Info("test") | ||
| } | ||
| lines := strings.Split(strings.TrimSpace(buf.String()), "\n") | ||
| assert.Len(t, lines, 100) | ||
|
|
||
| // validate the logging data integrity | ||
| for i, line := range lines { | ||
| var entry map[string]string | ||
| require.NoError(t, json.Unmarshal([]byte(line), &entry)) | ||
| if i%5 == 0 { | ||
| assert.Equal(t, "break", entry["msg"]) | ||
| } else { | ||
| assert.Equal(t, "test", entry["msg"]) | ||
| } | ||
| } | ||
| } | ||
|
|
||
| func TestDebugLoggerStiflesEntriesWhichAreTooFrequent(t *testing.T) { | ||
| // initialize the debug logger with no consecutive entry backoff, but a time backoff of 30m | ||
| buf := new(bytes.Buffer) | ||
| log := MakeDebugLoggerWithReducedRedudancy(buf, &logrus.JSONFormatter{}, 0, time.Minute*30) | ||
|
|
||
| // spam the logger, but validate that only one entry gets printed within the backoff timeframe | ||
| for i := 0; i < 100; i++ { | ||
| log.Debug("unique") | ||
| } | ||
| lines := strings.Split(strings.TrimSpace(buf.String()), "\n") | ||
| assert.Len(t, lines, 1) | ||
|
|
||
| // validate the log entry | ||
| var entry map[string]string | ||
| require.NoError(t, json.Unmarshal([]byte(lines[0]), &entry)) | ||
| assert.Equal(t, "unique", entry["msg"]) | ||
| } | ||
|
|
||
| func TestDebugLoggerStopsStiflingEntriesAfterBackoffExpires(t *testing.T) { | ||
| // setup backoffs and determine start/stop times | ||
| start := time.Now() | ||
| backoff := time.Millisecond * 100 | ||
| stop := start.Add(backoff) | ||
|
|
||
| // initialize the debug logger with no consecutive entry backoff, but a time based backoff | ||
| buf := new(bytes.Buffer) | ||
| log := MakeDebugLoggerWithReducedRedudancy(buf, &logrus.JSONFormatter{}, 0, backoff) | ||
|
|
||
| // spam the logger and validate that the testing environment didn't take longer than 100ms to process this | ||
| for i := 0; i < 100; i++ { | ||
| log.Debug("unique") | ||
| } | ||
| assert.True(t, time.Now().Before(stop), | ||
| "validate that the resource contention in the testing environment is not overt") | ||
|
|
||
| // verify that a new backoff period started and that all lines beyond the original were stifled | ||
| lines := strings.Split(strings.TrimSpace(buf.String()), "\n") | ||
| require.Len(t, lines, 1) | ||
|
|
||
| // validate the log data integrity | ||
| var entry map[string]interface{} | ||
| require.NoError(t, json.Unmarshal([]byte(lines[0]), &entry)) | ||
| assert.Equal(t, "unique", entry["msg"]) | ||
|
|
||
| // wait until the backoff time is up and validate that it will allow one entry of the previous | ||
| // redundant log entry to be emitted now that the backoff is over. | ||
| time.Sleep(backoff) | ||
| for i := 0; i < 1; i++ { | ||
| log.Debug("second-unique") | ||
| } | ||
|
|
||
| // verify that a new backoff period started and that all lines beyond the original were stifled | ||
| lines = strings.Split(strings.TrimSpace(buf.String()), "\n") | ||
| require.Len(t, lines, 2) | ||
|
|
||
| // validate the log data integrity | ||
| require.NoError(t, json.Unmarshal([]byte(lines[0]), &entry)) | ||
| assert.Equal(t, "unique", entry["msg"]) | ||
| require.NoError(t, json.Unmarshal([]byte(lines[1]), &entry)) | ||
| assert.Equal(t, "second-unique", entry["msg"]) | ||
| } |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Oops, something went wrong.