Skip to content

Commit 56a4d36

Browse files
myleshortonmyleshorton
authored
Merge pull request #5099 from getlantern/issue5096
Issue5096
2 parents 9154a52 + 4cf6126 commit 56a4d36

File tree

8 files changed

+145
-98
lines changed

8 files changed

+145
-98
lines changed

‎src/github.com/getlantern/errors/errors.go

Lines changed: 29 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -93,6 +93,18 @@ type Error interface {
9393
error
9494
context.Contextual
9595

96+
// ErrorClean returns a non-parameterized version of the error whenever
97+
// possible. For example, if the error text is:
98+
//
99+
// unable to dial www.google.com caused by: i/o timeout
100+
//
101+
// ErrorClean might return:
102+
//
103+
// unable to dial %v caused by: %v
104+
//
105+
// This can be useful when performing analytics on the error.
106+
ErrorClean() string
107+
96108
// MultiLinePrinter implements the interface golog.MultiLine
97109
MultiLinePrinter() func(buf *bytes.Buffer) bool
98110

@@ -138,7 +150,7 @@ func NewOffset(offset int, desc string, args ...interface{}) Error {
138150
break
139151
}
140152
}
141-
e := buildError(fmt.Sprintf(desc, args...), nil, Wrap(cause))
153+
e := buildError(desc, fmt.Sprintf(desc, args...), nil, Wrap(cause))
142154
e.attachStack(2 + offset)
143155
return e
144156
}
@@ -202,9 +214,13 @@ func (e *structured) RootCause() error {
202214
return e.cause.RootCause()
203215
}
204216

217+
func (e *structured) ErrorClean() string {
218+
return e.data["error"].(string)
219+
}
220+
205221
// Error satisfies the error interface
206222
func (e *structured) Error() string {
207-
return e.data["error"].(string) + e.hiddenID
223+
return e.data["error_text"].(string) + e.hiddenID
208224
}
209225

210226
func (e *structured) MultiLinePrinter() func(buf *bytes.Buffer) bool {
@@ -276,15 +292,16 @@ func wrapSkipFrames(err error, skip int) Error {
276292
}
277293

278294
// Create a new *structured
279-
return buildError(err.Error(), err, cause)
295+
return buildError("", "", err, cause)
280296
}
281297

282298
func (e *structured) attachStack(skip int) {
283299
call := stack.Caller(skip)
284300
e.callStack = stack.Trace().TrimBelow(call)
301+
e.data["error_location"] = fmt.Sprintf("%+n (%s:%d)", call, call, call)
285302
}
286303

287-
func buildError(desc string, wrapped error, cause Error) *structured {
304+
func buildError(desc string, fullText string, wrapped error, cause Error) *structured {
288305
e := &structured{
289306
data: make(context.Map),
290307
// We capture the current context to allow it to propagate to higher layers.
@@ -308,7 +325,14 @@ func buildError(desc string, wrapped error, cause Error) *structured {
308325
}
309326
}
310327
}
311-
e.data["error"] = hidden.Clean(desc)
328+
329+
cleanedDesc := hidden.Clean(desc)
330+
e.data["error"] = cleanedDesc
331+
if fullText != "" {
332+
e.data["error_text"] = hidden.Clean(fullText)
333+
} else {
334+
e.data["error_text"] = cleanedDesc
335+
}
312336
e.data["error_type"] = errorType
313337

314338
return e

‎src/github.com/getlantern/errors/errors_test.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -54,6 +54,10 @@ func TestNewWithCause(t *testing.T) {
5454
cause := buildCause()
5555
outer := New("Hello %v", cause)
5656
assert.Equal(t, "Hello World", hidden.Clean(outer.Error()))
57+
assert.Equal(t, "Hello %v", outer.(*structured).ErrorClean())
58+
assert.Equal(t,
59+
"github.com/getlantern/errors.TestNewWithCause (errors_test.go:999)",
60+
replaceNumbers.ReplaceAllString(outer.(*structured).data["error_location"].(string), "999"))
5761
assert.Equal(t, cause, outer.(*structured).cause)
5862

5963
// Make sure that stacktrace prints out okay

‎src/github.com/getlantern/flashlight/flashlight.go

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,8 @@ var (
4444
// BuildDate is the date the code was actually built.
4545
BuildDate string // The actual date and time the binary was built.
4646

47-
cfgMutex sync.Mutex
47+
cfgMutex sync.Mutex
48+
configureLoggingOnce sync.Once
4849
)
4950

5051
func bestPackageVersion() string {
@@ -153,7 +154,9 @@ func applyClientConfig(client *client.Client, cfg *config.Config, deviceID strin
153154
} else {
154155
fronted.Configure(certs, cfg.Client.MasqueradeSets, filepath.Join(appdir.General("Lantern"), "masquerade_cache"))
155156
}
156-
logging.Configure(cfg.CloudConfigCA, deviceID, Version, RevisionDate, cfg.BordaReportInterval, cfg.BordaSamplePercentage, cfg.LogglySamplePercentage)
157+
configureLoggingOnce.Do(func() {
158+
logging.Configure(cfg.CloudConfigCA, deviceID, Version, RevisionDate, cfg.BordaReportInterval, cfg.BordaSamplePercentage, cfg.LogglySamplePercentage)
159+
})
157160
// Update client configuration
158161
client.Configure(cfg.Client, deviceID)
159162
}

‎src/github.com/getlantern/flashlight/logging/logging.go

Lines changed: 50 additions & 45 deletions
Original file line numberDiff line numberDiff line change
@@ -16,8 +16,10 @@ import (
1616

1717
"github.com/getlantern/appdir"
1818
borda "github.com/getlantern/borda/client"
19+
"github.com/getlantern/errors"
1920
"github.com/getlantern/go-loggly"
2021
"github.com/getlantern/golog"
22+
"github.com/getlantern/hidden"
2123
"github.com/getlantern/jibber_jabber"
2224
"github.com/getlantern/osversion"
2325
"github.com/getlantern/rotator"
@@ -49,11 +51,12 @@ var (
4951
errorOut io.Writer
5052
debugOut io.Writer
5153

52-
duplicates = make(map[string]bool)
53-
dupLock sync.Mutex
54-
5554
bordaClient *borda.Client
5655

56+
logglyRateLimit = 5 * time.Minute
57+
lastReported = make(map[string]time.Time)
58+
lastReportedLock sync.Mutex
59+
5760
logglyKeyTranslations = map[string]string{
5861
"device_id": "instanceid",
5962
"os_name": "osName",
@@ -234,22 +237,6 @@ func enableLoggly(cloudConfigCA string, logglySamplePercentage float64, deviceID
234237
golog.RegisterReporter(le.Report)
235238
}
236239

237-
func isDuplicate(msg string) bool {
238-
dupLock.Lock()
239-
defer dupLock.Unlock()
240-
241-
if duplicates[msg] {
242-
return true
243-
}
244-
245-
// Implement a crude cap on the size of the map
246-
if len(duplicates) < 1000 {
247-
duplicates[msg] = true
248-
}
249-
250-
return false
251-
}
252-
253240
// flushable interface describes writers that can be flushed
254241
type flushable interface {
255242
flush()
@@ -260,42 +247,49 @@ type logglyErrorReporter struct {
260247
client *loggly.Client
261248
}
262249

263-
func (r logglyErrorReporter) Report(err error, fullMessage string, ctx map[string]interface{}) {
264-
fmt.Fprintln(os.Stderr, "Message: "+fullMessage)
265-
if isDuplicate(fullMessage) {
266-
log.Debugf("Not logging duplicate: %v", fullMessage)
250+
func (r logglyErrorReporter) Report(err error, location string, ctx map[string]interface{}) {
251+
// Remove hidden errors info
252+
fullMessage := hidden.Clean(err.Error())
253+
if !shouldReport(location) {
254+
log.Debugf("Not reporting duplicate at %v to Loggly: %v", location, fullMessage)
255+
return
267256
}
268-
269-
// extract last 2 (at most) chunks of fullMessage to message, without prefix,
270-
// so we can group logs with same reason in Loggly
271-
lastColonPos := -1
272-
colonsSeen := 0
273-
for p := len(fullMessage) - 2; p >= 0; p-- {
274-
if fullMessage[p] == ':' {
275-
lastChar := fullMessage[p+1]
276-
// to prevent colon in "http://" and "x.x.x.x:80" be treated as seperator
277-
if !(lastChar == '/' || lastChar >= '0' && lastChar <= '9') {
278-
lastColonPos = p
279-
colonsSeen++
280-
if colonsSeen == 2 {
281-
break
257+
log.Debugf("Reporting error at %v to Loggly: %v", location, fullMessage)
258+
259+
// extract last 2 (at most) chunks of fullMessage to message, so we can group
260+
// logs with same reason in Loggly
261+
var message string
262+
switch e := err.(type) {
263+
case errors.Error:
264+
message = e.ErrorClean()
265+
default:
266+
lastColonPos := -1
267+
colonsSeen := 0
268+
for p := len(fullMessage) - 2; p >= 0; p-- {
269+
if fullMessage[p] == ':' {
270+
lastChar := fullMessage[p+1]
271+
// to prevent colon in "http://" and "x.x.x.x:80" be treated as seperator
272+
if !(lastChar == '/' || lastChar >= '0' && lastChar <= '9') {
273+
lastColonPos = p
274+
colonsSeen++
275+
if colonsSeen == 2 {
276+
break
277+
}
282278
}
283279
}
284280
}
281+
if colonsSeen >= 2 {
282+
message = strings.TrimSpace(fullMessage[lastColonPos+1:])
283+
} else {
284+
message = fullMessage
285+
}
285286
}
286-
message := strings.TrimSpace(fullMessage[lastColonPos+1:])
287287

288288
// Loggly doesn't group fields with more than 100 characters
289289
if len(message) > 100 {
290290
message = message[0:100]
291291
}
292292

293-
firstColonPos := strings.IndexRune(fullMessage, ':')
294-
if firstColonPos == -1 {
295-
firstColonPos = 0
296-
}
297-
prefix := fullMessage[0:firstColonPos]
298-
299293
translatedCtx := make(map[string]interface{}, len(ctx))
300294
for key, value := range ctx {
301295
tkey, found := logglyKeyTranslations[key]
@@ -309,7 +303,7 @@ func (r logglyErrorReporter) Report(err error, fullMessage string, ctx map[strin
309303

310304
m := loggly.Message{
311305
"extra": translatedCtx,
312-
"locationInfo": prefix,
306+
"locationInfo": location,
313307
"message": message,
314308
"fullMessage": fullMessage,
315309
}
@@ -320,6 +314,17 @@ func (r logglyErrorReporter) Report(err error, fullMessage string, ctx map[strin
320314
}
321315
}
322316

317+
func shouldReport(location string) bool {
318+
now := time.Now()
319+
lastReportedLock.Lock()
320+
defer lastReportedLock.Unlock()
321+
shouldReport := now.Sub(lastReported[location]) > logglyRateLimit
322+
if shouldReport {
323+
lastReported[location] = now
324+
}
325+
return shouldReport
326+
}
327+
323328
// flush forces output, since it normally flushes based on an interval
324329
func (r *logglyErrorReporter) flush() {
325330
if err := r.client.Flush(); err != nil {

‎src/github.com/getlantern/flashlight/logging/logging_test.go

Lines changed: 27 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -62,31 +62,44 @@ func TestLoggly(t *testing.T) {
6262
golog.RegisterReporter(r.Report)
6363
log := golog.LoggerFor("test")
6464

65-
log.Error("")
66-
log.Debug(buf.String())
67-
if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") {
68-
assert.Equal(t, "ERROR test", result["locationInfo"])
69-
assert.Regexp(t, regexp.MustCompile("logging_test.go:([0-9]+)"), result["message"])
65+
origLogglyRateLimit := logglyRateLimit
66+
defer func() {
67+
logglyRateLimit = origLogglyRateLimit
68+
}()
69+
logglyRateLimit = 100 * time.Millisecond
70+
for i := 0; i < 2; i++ {
71+
buf.Reset()
72+
log.Error("short message")
73+
if i == 1 {
74+
assert.Equal(t, 0, buf.Len(), "duplicate shouldn't have been reported")
75+
time.Sleep(logglyRateLimit)
76+
} else {
77+
if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") {
78+
assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"])
79+
assert.Equal(t, "short message", result["message"])
80+
}
81+
}
7082
}
7183

7284
buf.Reset()
73-
log.Error("short message")
85+
log.Error("")
86+
log.Debugf("**************** %v", buf.String())
7487
if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") {
75-
assert.Equal(t, "ERROR test", result["locationInfo"])
76-
assert.Regexp(t, regexp.MustCompile("logging_test.go:([0-9]+) short message"), result["message"])
88+
assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"])
89+
assert.Equal(t, "", result["message"])
7790
}
7891

7992
buf.Reset()
8093
log.Error("message with: reason")
8194
if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") {
82-
assert.Equal(t, "ERROR test", result["locationInfo"])
83-
assert.Regexp(t, "logging_test.go:([0-9]+) message with: reason", result["message"])
95+
assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"])
96+
assert.Equal(t, "message with: reason", result["message"], "message should be last 2 chunks")
8497
}
8598

8699
buf.Reset()
87100
log.Error("deep reason: message with: reason")
88101
if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") {
89-
assert.Equal(t, "ERROR test", result["locationInfo"])
102+
assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"])
90103
assert.Equal(t, "message with: reason", result["message"], "message should be last 2 chunks")
91104
}
92105

@@ -99,7 +112,7 @@ func TestLoggly(t *testing.T) {
99112
buf.Reset()
100113
log.Error("deep reason: an url 127.0.0.1:8787 in message: reason")
101114
if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") {
102-
assert.Equal(t, "ERROR test", result["locationInfo"])
115+
assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"])
103116
assert.Equal(t, "an url 127.0.0.1:8787 in message: reason", result["message"], "should not truncate url")
104117
}
105118

@@ -108,9 +121,8 @@ func TestLoggly(t *testing.T) {
108121
longMsg := longPrefix + strings.Repeat("o", 100) + "ng reason"
109122
log.Error(longMsg)
110123
if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") {
111-
assert.Equal(t, "ERROR test", result["locationInfo"])
112-
113-
assert.Regexp(t, regexp.MustCompile("logging_test.go:([0-9]+) "+longPrefix+"(o+)"), result["message"])
124+
assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"])
125+
assert.Regexp(t, regexp.MustCompile(longPrefix+"(o+)"), result["message"])
114126
assert.Equal(t, 100, len(result["message"].(string)))
115127
}
116128
}

‎src/github.com/getlantern/flashlight/main/flags.go

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,7 @@ var (
2828
staging = flag.Bool("staging", false, "if true, run Lantern against our staging infrastructure")
2929
bordaReportInterval = flag.Duration("borda-report-interval", 5*time.Minute, "How frequently to report errors to borda. Set to 0 to disable reporting.")
3030
bordaSamplePercentage = flag.Float64("borda-sample-percentage", 0.01, "The percentage of devices to report to Borda (0.01 = 1%)")
31-
logglySamplePercentage = flag.Float64("loggly-sample-percentage", 0.005, "The percentage of devices to report to Loggly (0.005 = 0.5%)")
31+
logglySamplePercentage = flag.Float64("loggly-sample-percentage", 0.02, "The percentage of devices to report to Loggly (0.02 = 2%)")
3232
help = flag.Bool("help", false, "Get usage help")
3333
)
3434

0 commit comments

Comments
 (0)