diff --git a/src/github.com/getlantern/balancer/balancer.go b/src/github.com/getlantern/balancer/balancer.go index f966212b39..bdbde2c64c 100644 --- a/src/github.com/getlantern/balancer/balancer.go +++ b/src/github.com/getlantern/balancer/balancer.go @@ -30,11 +30,12 @@ var ( // Balancer balances connections among multiple Dialers. type Balancer struct { + // make sure to align on 64bit boundary + lastDialTime int64 // Time.UnixNano() st Strategy mu sync.RWMutex dialers dialerHeap trusted dialerHeap - lastDialTime int64 // Time.UnixNano() } // New creates a new Balancer using the supplied Strategy and Dialers. @@ -101,11 +102,17 @@ func (b *Balancer) Dial(network, addr string) (net.Conn, error) { trustedOnly = true } + var lastDialer *dialer for i := 0; i < dialAttempts; i++ { d, pickErr := b.pickDialer(trustedOnly) if pickErr != nil { return nil, pickErr } + if d == lastDialer { + log.Debugf("Skip dialing %s://%s with same dailer %s", network, addr, d.Label) + continue + } + lastDialer = d log.Tracef("Dialing %s://%s with %s", network, addr, d.Label) conn, err := d.dial(network, addr) if err != nil { diff --git a/src/github.com/getlantern/balancer/balancer_test.go b/src/github.com/getlantern/balancer/balancer_test.go index 7dbccfd096..cc11285e41 100644 --- a/src/github.com/getlantern/balancer/balancer_test.go +++ b/src/github.com/getlantern/balancer/balancer_test.go @@ -57,6 +57,27 @@ func TestSingleDialer(t *testing.T) { } } +func TestRetryOnBadDialer(t *testing.T) { + addr, l := echoServer() + defer func() { _ = l.Close() }() + + d1Attempts := int32(0) + dialer1 := newCondDialer(1, func() bool { atomic.AddInt32(&d1Attempts, 1); return true }) + d2Attempts := int32(0) + dialer2 := newCondDialer(2, func() bool { atomic.AddInt32(&d2Attempts, 1); return true }) + + b := New(Sticky, dialer1) + _, err := b.Dial("tcp", addr) + if assert.Error(t, err, "Dialing bad dialer should fail") { + assert.EqualValues(t, 1, atomic.LoadInt32(&d1Attempts), "should try same dialer only once") + } + b.Reset(dialer1, dialer2) + _, err = b.Dial("tcp", addr) + if assert.Error(t, err, "Dialing bad dialer should fail") { + assert.EqualValues(t, dialAttempts, atomic.LoadInt32(&d1Attempts)+atomic.LoadInt32(&d2Attempts), "should try enough times when there are more then 1 dialer") + } +} + func TestRandomDialer(t *testing.T) { addr, l := echoServer() defer func() { _ = l.Close() }() diff --git a/src/github.com/getlantern/chained/dialer.go b/src/github.com/getlantern/chained/dialer.go index bdb5d4762f..bd6c2096fb 100644 --- a/src/github.com/getlantern/chained/dialer.go +++ b/src/github.com/getlantern/chained/dialer.go @@ -49,7 +49,7 @@ func (d *dialer) Dial(network, addr string) (net.Conn, error) { // that we should send a CONNECT request and tunnel all traffic through // that. if network == "connect" { - log.Debugf("Sending CONNECT REQUEST") + log.Tracef("Sending CONNECT REQUEST") if err := d.sendCONNECT("tcp", addr, conn); err != nil { // We discard this error, since we are only interested in sendCONNECT _ = conn.Close() diff --git a/src/github.com/getlantern/errors/errors.go b/src/github.com/getlantern/errors/errors.go index a98905296b..4896addecd 100644 --- a/src/github.com/getlantern/errors/errors.go +++ b/src/github.com/getlantern/errors/errors.go @@ -93,6 +93,18 @@ type Error interface { error context.Contextual + // ErrorClean returns a non-parameterized version of the error whenever + // possible. For example, if the error text is: + // + // unable to dial www.google.com caused by: i/o timeout + // + // ErrorClean might return: + // + // unable to dial %v caused by: %v + // + // This can be useful when performing analytics on the error. + ErrorClean() string + // MultiLinePrinter implements the interface golog.MultiLine MultiLinePrinter() func(buf *bytes.Buffer) bool @@ -138,7 +150,7 @@ func NewOffset(offset int, desc string, args ...interface{}) Error { break } } - e := buildError(fmt.Sprintf(desc, args...), nil, Wrap(cause)) + e := buildError(desc, fmt.Sprintf(desc, args...), nil, Wrap(cause)) e.attachStack(2 + offset) return e } @@ -202,9 +214,13 @@ func (e *structured) RootCause() error { return e.cause.RootCause() } +func (e *structured) ErrorClean() string { + return e.data["error"].(string) +} + // Error satisfies the error interface func (e *structured) Error() string { - return e.data["error"].(string) + e.hiddenID + return e.data["error_text"].(string) + e.hiddenID } func (e *structured) MultiLinePrinter() func(buf *bytes.Buffer) bool { @@ -276,15 +292,16 @@ func wrapSkipFrames(err error, skip int) Error { } // Create a new *structured - return buildError(err.Error(), err, cause) + return buildError("", "", err, cause) } func (e *structured) attachStack(skip int) { call := stack.Caller(skip) e.callStack = stack.Trace().TrimBelow(call) + e.data["error_location"] = fmt.Sprintf("%+n (%s:%d)", call, call, call) } -func buildError(desc string, wrapped error, cause Error) *structured { +func buildError(desc string, fullText string, wrapped error, cause Error) *structured { e := &structured{ data: make(context.Map), // 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 { } } } - e.data["error"] = hidden.Clean(desc) + + cleanedDesc := hidden.Clean(desc) + e.data["error"] = cleanedDesc + if fullText != "" { + e.data["error_text"] = hidden.Clean(fullText) + } else { + e.data["error_text"] = cleanedDesc + } e.data["error_type"] = errorType return e diff --git a/src/github.com/getlantern/errors/errors_test.go b/src/github.com/getlantern/errors/errors_test.go index 367da9ade9..a5d5afbc79 100644 --- a/src/github.com/getlantern/errors/errors_test.go +++ b/src/github.com/getlantern/errors/errors_test.go @@ -54,6 +54,10 @@ func TestNewWithCause(t *testing.T) { cause := buildCause() outer := New("Hello %v", cause) assert.Equal(t, "Hello World", hidden.Clean(outer.Error())) + assert.Equal(t, "Hello %v", outer.(*structured).ErrorClean()) + assert.Equal(t, + "github.com/getlantern/errors.TestNewWithCause (errors_test.go:999)", + replaceNumbers.ReplaceAllString(outer.(*structured).data["error_location"].(string), "999")) assert.Equal(t, cause, outer.(*structured).cause) // Make sure that stacktrace prints out okay diff --git a/src/github.com/getlantern/flashlight/app/app.go b/src/github.com/getlantern/flashlight/app/app.go index f734047dcd..d2a2959a19 100644 --- a/src/github.com/getlantern/flashlight/app/app.go +++ b/src/github.com/getlantern/flashlight/app/app.go @@ -57,7 +57,7 @@ func (app *App) LogPanicAndExit(msg string) { panic("Error initializing logging") } - <-logging.Configure("", "dummy-device-id-for-panic", flashlight.Version, flashlight.RevisionDate, 0, 0) + <-logging.Configure("", "dummy-device-id-for-panic", flashlight.Version, flashlight.RevisionDate, 0, 0, 0) log.Error(msg) diff --git a/src/github.com/getlantern/flashlight/client/client.go b/src/github.com/getlantern/flashlight/client/client.go index c49e2b2d9e..15c39284a6 100644 --- a/src/github.com/getlantern/flashlight/client/client.go +++ b/src/github.com/getlantern/flashlight/client/client.go @@ -202,7 +202,9 @@ func (client *Client) proxiedDialer(orig func(network, addr string) (net.Conn, e log.Tracef("Rewriting %v to %v", addr, rewritten) return net.Dial(network, rewritten) } + start := time.Now() conn, err := proxied(network, addr) + log.Debugf("Dialing proxy takes %v for %s", time.Since(start), addr) return conn, op.FailIf(err) } } diff --git a/src/github.com/getlantern/flashlight/client/handler.go b/src/github.com/getlantern/flashlight/client/handler.go index 2764f62112..83e577570a 100644 --- a/src/github.com/getlantern/flashlight/client/handler.go +++ b/src/github.com/getlantern/flashlight/client/handler.go @@ -138,16 +138,15 @@ func pipeData(clientConn net.Conn, connOut net.Conn, op *ops.Op, closeFunc func( } func respondOK(writer io.Writer, req *http.Request) error { - log.Debugf("Responding OK to %v", req.URL) return respondHijacked(writer, req, http.StatusOK) } func respondBadGatewayHijacked(writer io.Writer, req *http.Request) error { + log.Debugf("Responding %v", http.StatusBadGateway) return respondHijacked(writer, req, http.StatusBadGateway) } func respondHijacked(writer io.Writer, req *http.Request, statusCode int) error { - log.Debugf("Responding %v to %v", statusCode, req.URL) defer func() { if err := req.Body.Close(); err != nil { log.Debugf("Error closing body of OK response: %s", err) diff --git a/src/github.com/getlantern/flashlight/config/global.go b/src/github.com/getlantern/flashlight/config/global.go index 6dee88a4f4..4bbfebdaa4 100644 --- a/src/github.com/getlantern/flashlight/config/global.go +++ b/src/github.com/getlantern/flashlight/config/global.go @@ -16,11 +16,12 @@ type Global struct { CloudConfigCA string // AutoUpdateCA is the CA key to pin for auto-updates. - AutoUpdateCA string - UpdateServerURL string - BordaReportInterval time.Duration - BordaSamplePercentage float64 - Client *client.ClientConfig + AutoUpdateCA string + UpdateServerURL string + BordaReportInterval time.Duration + BordaSamplePercentage float64 + LogglySamplePercentage float64 + Client *client.ClientConfig // ProxiedSites are domains that get routed through Lantern rather than accessed directly. ProxiedSites *proxiedsites.Config diff --git a/src/github.com/getlantern/flashlight/flashlight.go b/src/github.com/getlantern/flashlight/flashlight.go index 44705cfc3e..4058440af4 100644 --- a/src/github.com/getlantern/flashlight/flashlight.go +++ b/src/github.com/getlantern/flashlight/flashlight.go @@ -45,7 +45,8 @@ var ( // BuildDate is the date the code was actually built. BuildDate string // The actual date and time the binary was built. - cfgMutex sync.Mutex + cfgMutex sync.Mutex + configureLoggingOnce sync.Once ) func bestPackageVersion() string { @@ -141,7 +142,9 @@ func applyClientConfig(client *client.Client, cfg *config.Global, deviceID strin } else if cfg.Client != nil { fronted.Configure(certs, cfg.Client.MasqueradeSets, filepath.Join(appdir.General("Lantern"), "masquerade_cache")) } - logging.Configure(cfg.CloudConfigCA, deviceID, Version, RevisionDate, cfg.BordaReportInterval, cfg.BordaSamplePercentage) + configureLoggingOnce.Do(func() { + logging.Configure(cfg.CloudConfigCA, deviceID, Version, RevisionDate, cfg.BordaReportInterval, cfg.BordaSamplePercentage, cfg.LogglySamplePercentage) + }) } func getTrustedCACerts(cfg *config.Global) (pool *x509.CertPool, err error) { diff --git a/src/github.com/getlantern/flashlight/logging/logging.go b/src/github.com/getlantern/flashlight/logging/logging.go index 60bfb5b479..bc3b495334 100644 --- a/src/github.com/getlantern/flashlight/logging/logging.go +++ b/src/github.com/getlantern/flashlight/logging/logging.go @@ -16,8 +16,10 @@ import ( "github.com/getlantern/appdir" borda "github.com/getlantern/borda/client" + "github.com/getlantern/errors" "github.com/getlantern/go-loggly" "github.com/getlantern/golog" + "github.com/getlantern/hidden" "github.com/getlantern/jibber_jabber" "github.com/getlantern/osversion" "github.com/getlantern/rotator" @@ -49,11 +51,12 @@ var ( errorOut io.Writer debugOut io.Writer - duplicates = make(map[string]bool) - dupLock sync.Mutex - bordaClient *borda.Client + logglyRateLimit = 5 * time.Minute + lastReported = make(map[string]time.Time) + lastReportedLock sync.Mutex + logglyKeyTranslations = map[string]string{ "device_id": "instanceid", "os_name": "osName", @@ -102,7 +105,8 @@ func EnableFileLogging() error { // Returns a bool channel for optional blocking. func Configure(cloudConfigCA string, deviceID string, version string, revisionDate string, - bordaReportInterval time.Duration, bordaSamplePercentage float64) (success chan bool) { + bordaReportInterval time.Duration, bordaSamplePercentage float64, + logglySamplePercentage float64) (success chan bool) { success = make(chan bool, 1) // Note: Returning from this function must always add a result to the @@ -130,7 +134,7 @@ func Configure(cloudConfigCA string, deviceID string, // Using a goroutine because we'll be using waitforserver and at this time // the proxy is not yet ready. go func() { - enableLoggly(cloudConfigCA) + enableLoggly(cloudConfigCA, logglySamplePercentage, deviceID) // Won't block, but will allow optional blocking on receiver success <- true }() @@ -214,7 +218,13 @@ func timestamped(orig io.Writer) io.Writer { }) } -func enableLoggly(cloudConfigCA string) { +func enableLoggly(cloudConfigCA string, logglySamplePercentage float64, deviceID string) { + if !includeInSample(deviceID, logglySamplePercentage) { + log.Debugf("DeviceID %v not being sampled for Loggly", deviceID) + return + } + log.Debugf("DeviceID %v will report errors to Loggly", deviceID) + rt, err := proxied.ChainedPersistent(cloudConfigCA) if err != nil { log.Errorf("Could not create HTTP client, not logging to Loggly: %v", err) @@ -227,22 +237,6 @@ func enableLoggly(cloudConfigCA string) { golog.RegisterReporter(le.Report) } -func isDuplicate(msg string) bool { - dupLock.Lock() - defer dupLock.Unlock() - - if duplicates[msg] { - return true - } - - // Implement a crude cap on the size of the map - if len(duplicates) < 1000 { - duplicates[msg] = true - } - - return false -} - // flushable interface describes writers that can be flushed type flushable interface { flush() @@ -253,42 +247,49 @@ type logglyErrorReporter struct { client *loggly.Client } -func (r logglyErrorReporter) Report(err error, fullMessage string, ctx map[string]interface{}) { - fmt.Fprintln(os.Stderr, "Message: "+fullMessage) - if isDuplicate(fullMessage) { - log.Debugf("Not logging duplicate: %v", fullMessage) +func (r logglyErrorReporter) Report(err error, location string, ctx map[string]interface{}) { + // Remove hidden errors info + fullMessage := hidden.Clean(err.Error()) + if !shouldReport(location) { + log.Debugf("Not reporting duplicate at %v to Loggly: %v", location, fullMessage) + return } - - // extract last 2 (at most) chunks of fullMessage to message, without prefix, - // so we can group logs with same reason in Loggly - lastColonPos := -1 - colonsSeen := 0 - for p := len(fullMessage) - 2; p >= 0; p-- { - if fullMessage[p] == ':' { - lastChar := fullMessage[p+1] - // to prevent colon in "http://" and "x.x.x.x:80" be treated as seperator - if !(lastChar == '/' || lastChar >= '0' && lastChar <= '9') { - lastColonPos = p - colonsSeen++ - if colonsSeen == 2 { - break + log.Debugf("Reporting error at %v to Loggly: %v", location, fullMessage) + + // extract last 2 (at most) chunks of fullMessage to message, so we can group + // logs with same reason in Loggly + var message string + switch e := err.(type) { + case errors.Error: + message = e.ErrorClean() + default: + lastColonPos := -1 + colonsSeen := 0 + for p := len(fullMessage) - 2; p >= 0; p-- { + if fullMessage[p] == ':' { + lastChar := fullMessage[p+1] + // to prevent colon in "http://" and "x.x.x.x:80" be treated as seperator + if !(lastChar == '/' || lastChar >= '0' && lastChar <= '9') { + lastColonPos = p + colonsSeen++ + if colonsSeen == 2 { + break + } } } } + if colonsSeen >= 2 { + message = strings.TrimSpace(fullMessage[lastColonPos+1:]) + } else { + message = fullMessage + } } - message := strings.TrimSpace(fullMessage[lastColonPos+1:]) // Loggly doesn't group fields with more than 100 characters if len(message) > 100 { message = message[0:100] } - firstColonPos := strings.IndexRune(fullMessage, ':') - if firstColonPos == -1 { - firstColonPos = 0 - } - prefix := fullMessage[0:firstColonPos] - translatedCtx := make(map[string]interface{}, len(ctx)) for key, value := range ctx { tkey, found := logglyKeyTranslations[key] @@ -302,7 +303,7 @@ func (r logglyErrorReporter) Report(err error, fullMessage string, ctx map[strin m := loggly.Message{ "extra": translatedCtx, - "locationInfo": prefix, + "locationInfo": location, "message": message, "fullMessage": fullMessage, } @@ -313,6 +314,17 @@ func (r logglyErrorReporter) Report(err error, fullMessage string, ctx map[strin } } +func shouldReport(location string) bool { + now := time.Now() + lastReportedLock.Lock() + defer lastReportedLock.Unlock() + shouldReport := now.Sub(lastReported[location]) > logglyRateLimit + if shouldReport { + lastReported[location] = now + } + return shouldReport +} + // flush forces output, since it normally flushes based on an interval func (r *logglyErrorReporter) flush() { if err := r.client.Flush(); err != nil { @@ -352,6 +364,11 @@ func (t *nonStopWriter) flush() { } func enableBorda(bordaReportInterval time.Duration, bordaSamplePercentage float64, deviceID string) { + if !includeInSample(deviceID, bordaSamplePercentage) { + log.Debugf("DeviceID %v not being sampled for Borda", deviceID) + return + } + rt := proxied.ChainedThenFronted() bordaClient = borda.NewClient(&borda.Options{ @@ -374,27 +391,6 @@ func enableBorda(bordaReportInterval time.Duration, bordaSamplePercentage float6 } }) - // Sample a subset of device IDs. - // DeviceID is expected to be a Base64 encoded 48-bit (6 byte) MAC address - deviceIDBytes, base64Err := base64.StdEncoding.DecodeString(deviceID) - if base64Err != nil { - log.Debugf("Error decoding base64 deviceID %v: %v", deviceID, base64Err) - return - } - var deviceIDInt uint64 - if len(deviceIDBytes) != 6 { - log.Debugf("Unexpected DeviceID length %v: %d", deviceID, len(deviceIDBytes)) - return - } - // Pad and decode to int - paddedDeviceIDBytes := append(deviceIDBytes, 0, 0) - // Use BigEndian because Mac address has most significant bytes on left - deviceIDInt = binary.BigEndian.Uint64(paddedDeviceIDBytes) - if deviceIDInt%uint64(1/bordaSamplePercentage) != 0 { - log.Debugf("DeviceID %v not being sampled", deviceID) - return - } - reporter := func(failure error, ctx map[string]interface{}) { values := map[string]float64{} if failure != nil { @@ -410,3 +406,25 @@ func enableBorda(bordaReportInterval time.Duration, bordaSamplePercentage float6 ops.RegisterReporter(reporter) } + +func includeInSample(deviceID string, samplePercentage float64) bool { + if samplePercentage == 0 { + return false + } + + // Sample a subset of device IDs. + // DeviceID is expected to be a Base64 encoded 48-bit (6 byte) MAC address + deviceIDBytes, base64Err := base64.StdEncoding.DecodeString(deviceID) + if base64Err != nil { + log.Debugf("Error decoding base64 deviceID %v: %v", deviceID, base64Err) + return false + } + if len(deviceIDBytes) != 6 { + log.Debugf("Unexpected DeviceID length %v: %d", deviceID, len(deviceIDBytes)) + return false + } + // Pad and decode to int + paddedDeviceIDBytes := append(deviceIDBytes, 0, 0) + deviceIDInt := binary.BigEndian.Uint64(paddedDeviceIDBytes) + return deviceIDInt%uint64(1/samplePercentage) == 0 +} diff --git a/src/github.com/getlantern/flashlight/logging/logging_test.go b/src/github.com/getlantern/flashlight/logging/logging_test.go index 4d80e398bc..aa2b39947e 100644 --- a/src/github.com/getlantern/flashlight/logging/logging_test.go +++ b/src/github.com/getlantern/flashlight/logging/logging_test.go @@ -2,6 +2,8 @@ package logging import ( "bytes" + "encoding/base64" + "encoding/binary" "encoding/json" "fmt" "regexp" @@ -60,31 +62,44 @@ func TestLoggly(t *testing.T) { golog.RegisterReporter(r.Report) log := golog.LoggerFor("test") - log.Error("") - log.Debug(buf.String()) - if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") { - assert.Equal(t, "ERROR test", result["locationInfo"]) - assert.Regexp(t, regexp.MustCompile("logging_test.go:([0-9]+)"), result["message"]) + origLogglyRateLimit := logglyRateLimit + defer func() { + logglyRateLimit = origLogglyRateLimit + }() + logglyRateLimit = 100 * time.Millisecond + for i := 0; i < 2; i++ { + buf.Reset() + log.Error("short message") + if i == 1 { + assert.Equal(t, 0, buf.Len(), "duplicate shouldn't have been reported") + time.Sleep(logglyRateLimit) + } else { + if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") { + assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"]) + assert.Equal(t, "short message", result["message"]) + } + } } buf.Reset() - log.Error("short message") + log.Error("") + log.Debugf("**************** %v", buf.String()) if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") { - assert.Equal(t, "ERROR test", result["locationInfo"]) - assert.Regexp(t, regexp.MustCompile("logging_test.go:([0-9]+) short message"), result["message"]) + assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"]) + assert.Equal(t, "", result["message"]) } buf.Reset() log.Error("message with: reason") if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") { - assert.Equal(t, "ERROR test", result["locationInfo"]) - assert.Regexp(t, "logging_test.go:([0-9]+) message with: reason", result["message"]) + assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"]) + assert.Equal(t, "message with: reason", result["message"], "message should be last 2 chunks") } buf.Reset() log.Error("deep reason: message with: reason") if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") { - assert.Equal(t, "ERROR test", result["locationInfo"]) + assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"]) assert.Equal(t, "message with: reason", result["message"], "message should be last 2 chunks") } @@ -97,7 +112,7 @@ func TestLoggly(t *testing.T) { buf.Reset() log.Error("deep reason: an url 127.0.0.1:8787 in message: reason") if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") { - assert.Equal(t, "ERROR test", result["locationInfo"]) + assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"]) assert.Equal(t, "an url 127.0.0.1:8787 in message: reason", result["message"], "should not truncate url") } @@ -106,9 +121,21 @@ func TestLoggly(t *testing.T) { longMsg := longPrefix + strings.Repeat("o", 100) + "ng reason" log.Error(longMsg) if assert.NoError(t, json.Unmarshal(buf.Bytes(), &result), "Unmarshal error") { - assert.Equal(t, "ERROR test", result["locationInfo"]) - - assert.Regexp(t, regexp.MustCompile("logging_test.go:([0-9]+) "+longPrefix+"(o+)"), result["message"]) + assert.Regexp(t, "test: logging_test.go:([0-9]+)", result["locationInfo"]) + assert.Regexp(t, regexp.MustCompile(longPrefix+"(o+)"), result["message"]) assert.Equal(t, 100, len(result["message"].(string))) } } + +func TestIncludeInSample(t *testing.T) { + included := 0 + b := make([]byte, 8) + for i := uint64(0); i < 100; i++ { + binary.BigEndian.PutUint64(b, i) + if includeInSample(base64.StdEncoding.EncodeToString(b[2:]), 0.01) { + included++ + } + } + // TODO: yes, this is wrong, but we are sampling + assert.Equal(t, 4, included, "4% should have been included") +} diff --git a/src/github.com/getlantern/flashlight/main/flags.go b/src/github.com/getlantern/flashlight/main/flags.go index f8b4753e5b..d622fe2a82 100644 --- a/src/github.com/getlantern/flashlight/main/flags.go +++ b/src/github.com/getlantern/flashlight/main/flags.go @@ -6,29 +6,30 @@ import ( ) var ( - addr = flag.String("addr", "", "ip:port on which to listen for requests. When running as a client proxy, we'll listen with http, when running as a server proxy we'll listen with https (required)") - configdir = flag.String("configdir", "", "directory in which to store configuration, including flashlight.yaml (defaults to current directory)") - cloudconfig = flag.String("cloudconfig", "", "optional http(s) URL to a cloud-based source for configuration updates") - cloudconfigca = flag.String("cloudconfigca", "", "optional PEM encoded certificate used to verify TLS connections to fetch cloudconfig") - frontedconfig = flag.String("frontedconfig", "", "optional http(s) URL to a cloud-based source for configuration updates") - registerat = flag.String("registerat", "", "base URL for peer DNS registry at which to register (e.g. https://peerscanner.getiantem.org)") - country = flag.String("country", "xx", "2 digit country code under which to report stats. Defaults to xx.") - cpuprofile = flag.String("cpuprofile", "", "write cpu profile to given file") - memprofile = flag.String("memprofile", "", "write heap profile to given file") - uiaddr = flag.String("uiaddr", "127.0.0.1:16823", "if specified, indicates host:port the UI HTTP server should be started on") - proxyAll = flag.Bool("proxyall", false, "set to true to proxy all traffic through Lantern network") - stickyConfig = flag.Bool("stickyconfig", false, "set to true to only use the local config file") - headless = flag.Bool("headless", false, "if true, lantern will run with no ui") - startup = flag.Bool("startup", false, "if true, Lantern was automatically run on system startup") - clearProxySettings = flag.Bool("clear-proxy-settings", false, "if true, Lantern removes proxy settings from the system.") - pprofAddr = flag.String("pprofaddr", "", "pprof address to listen on, not activate pprof if empty") - forceProxyAddr = flag.String("force-proxy-addr", "", "if specified, force chained proxying to use this address instead of the configured one") - forceAuthToken = flag.String("force-auth-token", "", "if specified, force chained proxying to use this auth token instead of the configured one") - readableconfig = flag.Bool("readableconfig", false, "if specified, disables obfuscation of the config yaml so that it remains human readable") - staging = flag.Bool("staging", false, "if true, run Lantern against our staging infrastructure") - bordaReportInterval = flag.Duration("borda-report-interval", 5*time.Minute, "How frequently to report errors to borda. Set to 0 to disable reporting.") - bordaSamplePercentage = flag.Float64("borda-sample-percentage", 0.01, "The percentage of devices to report to Borda (0.01 = 1%)") - help = flag.Bool("help", false, "Get usage help") + addr = flag.String("addr", "", "ip:port on which to listen for requests. When running as a client proxy, we'll listen with http, when running as a server proxy we'll listen with https (required)") + configdir = flag.String("configdir", "", "directory in which to store configuration, including flashlight.yaml (defaults to current directory)") + cloudconfig = flag.String("cloudconfig", "", "optional http(s) URL to a cloud-based source for configuration updates") + cloudconfigca = flag.String("cloudconfigca", "", "optional PEM encoded certificate used to verify TLS connections to fetch cloudconfig") + frontedconfig = flag.String("frontedconfig", "", "optional http(s) URL to a cloud-based source for configuration updates") + registerat = flag.String("registerat", "", "base URL for peer DNS registry at which to register (e.g. https://peerscanner.getiantem.org)") + country = flag.String("country", "xx", "2 digit country code under which to report stats. Defaults to xx.") + cpuprofile = flag.String("cpuprofile", "", "write cpu profile to given file") + memprofile = flag.String("memprofile", "", "write heap profile to given file") + uiaddr = flag.String("uiaddr", "127.0.0.1:16823", "if specified, indicates host:port the UI HTTP server should be started on") + proxyAll = flag.Bool("proxyall", false, "set to true to proxy all traffic through Lantern network") + stickyConfig = flag.Bool("stickyconfig", false, "set to true to only use the local config file") + headless = flag.Bool("headless", false, "if true, lantern will run with no ui") + startup = flag.Bool("startup", false, "if true, Lantern was automatically run on system startup") + clearProxySettings = flag.Bool("clear-proxy-settings", false, "if true, Lantern removes proxy settings from the system.") + pprofAddr = flag.String("pprofaddr", "", "pprof address to listen on, not activate pprof if empty") + forceProxyAddr = flag.String("force-proxy-addr", "", "if specified, force chained proxying to use this address instead of the configured one") + forceAuthToken = flag.String("force-auth-token", "", "if specified, force chained proxying to use this auth token instead of the configured one") + readableconfig = flag.Bool("readableconfig", false, "if specified, disables obfuscation of the config yaml so that it remains human readable") + staging = flag.Bool("staging", false, "if true, run Lantern against our staging infrastructure") + bordaReportInterval = flag.Duration("borda-report-interval", 5*time.Minute, "How frequently to report errors to borda. Set to 0 to disable reporting.") + bordaSamplePercentage = flag.Float64("borda-sample-percentage", 0.01, "The percentage of devices to report to Borda (0.01 = 1%)") + logglySamplePercentage = flag.Float64("loggly-sample-percentage", 0.02, "The percentage of devices to report to Loggly (0.02 = 2%)") + help = flag.Bool("help", false, "Get usage help") ) // flagsAsMap returns a map of all flags that were provided at runtime diff --git a/src/github.com/getlantern/golog/golog.go b/src/github.com/getlantern/golog/golog.go index 39d6d07205..baf9198051 100644 --- a/src/github.com/getlantern/golog/golog.go +++ b/src/github.com/getlantern/golog/golog.go @@ -78,11 +78,11 @@ type MultiLine interface { } // ErrorReporter is a function to which the logger will report errors. -// It the given error and corresponding logText along with associated ops +// It the given error and corresponding message along with associated ops // context. This should return quickly as it executes on the critical code // path. The recommended approach is to buffer as much as possible and discard // new reports if the buffer becomes saturated. -type ErrorReporter func(err error, logText string, ctx map[string]interface{}) +type ErrorReporter func(err error, linePrefix string, ctx map[string]interface{}) type Logger interface { // Debug logs to stdout @@ -170,11 +170,9 @@ func (l *logger) linePrefix(skipFrames int) string { return fmt.Sprintf("%s%s:%d ", l.prefix, filepath.Base(file), line) } -func (l *logger) print(out io.Writer, buf *bytes.Buffer, skipFrames int, severity string, arg interface{}) { - if buf == nil { - buf = bufferPool.Get() - defer bufferPool.Put(buf) - } +func (l *logger) print(out io.Writer, skipFrames int, severity string, arg interface{}) string { + buf := bufferPool.Get() + defer bufferPool.Put(buf) linePrefix := l.linePrefix(skipFrames) writeHeader := func() { @@ -214,16 +212,18 @@ func (l *logger) print(out io.Writer, buf *bytes.Buffer, skipFrames int, severit if l.printStack { l.doPrintStack() } + + return linePrefix } -func (l *logger) printf(out io.Writer, buf *bytes.Buffer, skipFrames int, severity string, err error, message string, args ...interface{}) { - if buf == nil { - buf = bufferPool.Get() - defer bufferPool.Put(buf) - } +func (l *logger) printf(out io.Writer, skipFrames int, severity string, err error, message string, args ...interface{}) string { + buf := bufferPool.Get() + defer bufferPool.Put(buf) + + linePrefix := l.linePrefix(skipFrames) buf.WriteString(severity) buf.WriteString(" ") - buf.WriteString(l.linePrefix(skipFrames)) + buf.WriteString(linePrefix) fmt.Fprintf(buf, message, args...) printContext(buf, err) buf.WriteByte('\n') @@ -235,14 +235,15 @@ func (l *logger) printf(out io.Writer, buf *bytes.Buffer, skipFrames int, severi if l.printStack { l.doPrintStack() } + return linePrefix } func (l *logger) Debug(arg interface{}) { - l.print(GetOutputs().DebugOut, nil, 4, "DEBUG", arg) + l.print(GetOutputs().DebugOut, 4, "DEBUG", arg) } func (l *logger) Debugf(message string, args ...interface{}) { - l.printf(GetOutputs().DebugOut, nil, 4, "DEBUG", nil, message, args...) + l.printf(GetOutputs().DebugOut, 4, "DEBUG", nil, message, args...) } func (l *logger) Error(arg interface{}) error { @@ -257,10 +258,8 @@ func (l *logger) errorSkipFrames(arg interface{}, skipFrames int) error { default: err = fmt.Errorf("%v", e) } - buf := bufferPool.Get() - defer bufferPool.Put(buf) - l.print(GetOutputs().ErrorOut, buf, skipFrames+4, "ERROR", err) - return report(err, buf.String()) + linePrefix := l.print(GetOutputs().ErrorOut, skipFrames+4, "ERROR", err) + return report(err, linePrefix) } func (l *logger) Errorf(message string, args ...interface{}) error { @@ -268,24 +267,24 @@ func (l *logger) Errorf(message string, args ...interface{}) error { } func (l *logger) Fatal(arg interface{}) { - l.print(GetOutputs().ErrorOut, nil, 4, "FATAL", arg) + l.print(GetOutputs().ErrorOut, 4, "FATAL", arg) os.Exit(1) } func (l *logger) Fatalf(message string, args ...interface{}) { - l.printf(GetOutputs().ErrorOut, nil, 4, "FATAL", nil, message, args...) + l.printf(GetOutputs().ErrorOut, 4, "FATAL", nil, message, args...) os.Exit(1) } func (l *logger) Trace(arg interface{}) { if l.traceOn { - l.print(GetOutputs().DebugOut, nil, 4, "TRACE", arg) + l.print(GetOutputs().DebugOut, 4, "TRACE", arg) } } func (l *logger) Tracef(message string, args ...interface{}) { if l.traceOn { - l.printf(GetOutputs().DebugOut, nil, 4, "TRACE", nil, message, args...) + l.printf(GetOutputs().DebugOut, 4, "TRACE", nil, message, args...) } } @@ -320,9 +319,9 @@ func (l *logger) newTraceWriter() io.Writer { line, err := br.ReadString('\n') if err == nil { // Log the line (minus the trailing newline) - l.print(GetOutputs().DebugOut, nil, 6, "TRACE", line[:len(line)-1]) + l.print(GetOutputs().DebugOut, 6, "TRACE", line[:len(line)-1]) } else { - l.printf(GetOutputs().DebugOut, nil, 6, "TRACE", nil, "TraceWriter closed due to unexpected error: %v", err) + l.printf(GetOutputs().DebugOut, 6, "TRACE", nil, "TraceWriter closed due to unexpected error: %v", err) return } } @@ -342,7 +341,7 @@ func (w *errorWriter) Write(p []byte) (n int, err error) { if s[len(s)-1] == '\n' { s = s[:len(s)-1] } - w.l.print(GetOutputs().ErrorOut, nil, 6, "ERROR", s) + w.l.print(GetOutputs().ErrorOut, 6, "ERROR", s) return len(p), nil } @@ -398,7 +397,7 @@ func printContext(buf *bytes.Buffer, err interface{}) { buf.WriteByte(']') } -func report(err error, text string) error { +func report(err error, linePrefix string) error { var reportersCopy []ErrorReporter reportersMutex.RLock() if len(reporters) > 0 { @@ -411,7 +410,7 @@ func report(err error, text string) error { ctx := ops.AsMap(err, true) for _, reporter := range reportersCopy { // We include globals when reporting - reporter(err, hidden.Clean(text), ctx) + reporter(err, linePrefix, ctx) } } return err diff --git a/src/github.com/getlantern/golog/golog_test.go b/src/github.com/getlantern/golog/golog_test.go index 7d72d3b223..e33a2b5b78 100644 --- a/src/github.com/getlantern/golog/golog_test.go +++ b/src/github.com/getlantern/golog/golog_test.go @@ -19,7 +19,7 @@ import ( var ( expectedLog = "SEVERITY myprefix: golog_test.go:999 Hello world\nSEVERITY myprefix: golog_test.go:999 Hello true [cvarA=a cvarB=b op=name root_op=name]\n" - expectedErrorLog = `ERROR myprefix: golog_test.go:999 Hello world [cvarC=c cvarD=d error=Hello world error_type=errors.Error op=name root_op=name] + expectedErrorLog = `ERROR myprefix: golog_test.go:999 Hello world [cvarC=c cvarD=d error=Hello %v error_location=github.com/getlantern/golog.TestError (golog_test.go:999) error_text=Hello world error_type=errors.Error op=name root_op=name] ERROR myprefix: golog_test.go:999 at github.com/getlantern/golog.TestError (golog_test.go:999) ERROR myprefix: golog_test.go:999 at testing.tRunner (testing.go:999) ERROR myprefix: golog_test.go:999 at runtime.goexit (asm_amd999.s:999) @@ -28,7 +28,7 @@ ERROR myprefix: golog_test.go:999 at github.com/getlantern/golog.errorReturner ERROR myprefix: golog_test.go:999 at github.com/getlantern/golog.TestError (golog_test.go:999) ERROR myprefix: golog_test.go:999 at testing.tRunner (testing.go:999) ERROR myprefix: golog_test.go:999 at runtime.goexit (asm_amd999.s:999) -ERROR myprefix: golog_test.go:999 Hello true [cvarA=a cvarB=b cvarC=c error=Hello true error_type=errors.Error op=name999 root_op=name999] +ERROR myprefix: golog_test.go:999 Hello true [cvarA=a cvarB=b cvarC=c error=%v %v error_location=github.com/getlantern/golog.TestError (golog_test.go:999) error_text=Hello true error_type=errors.Error op=name999 root_op=name999] ERROR myprefix: golog_test.go:999 at github.com/getlantern/golog.TestError (golog_test.go:999) ERROR myprefix: golog_test.go:999 at testing.tRunner (testing.go:999) ERROR myprefix: golog_test.go:999 at runtime.goexit (asm_amd999.s:999)