func TestLogger(t *testing.T) { Convey("logger", t, func() { c := Use(logging.SetLevel(context.Background(), logging.Debug)) l := logging.Get(c) So(l, ShouldNotBeNil) l.Debugf("test %s", logging.Debug) l.Infof("test %s", logging.Info) l.Warningf("test %s", logging.Warning) l.Errorf("test %s", logging.Error) l.Errorf("test WAT: %s", logging.Level(9001)) ml := l.(*MemLogger) mld := ml.data So(len(*mld), ShouldEqual, 5) So((*mld)[0], ShouldResemble, LogEntry{logging.Debug, "test debug", nil}) So((*mld)[1], ShouldResemble, LogEntry{logging.Info, "test info", nil}) So((*mld)[2], ShouldResemble, LogEntry{logging.Warning, "test warning", nil}) So((*mld)[3], ShouldResemble, LogEntry{logging.Error, "test error", nil}) So((*mld)[4], ShouldResemble, LogEntry{logging.Error, "test WAT: unknown", nil}) }) Convey("logger context", t, func() { c := Use(context.Background()) l := logging.Get(c) So(l, ShouldNotBeNil) ml := l.(*MemLogger) l.Infof("totally works: %s", "yes") So(len(*ml.data), ShouldEqual, 1) So((*ml.data)[0], ShouldResemble, LogEntry{logging.Info, "totally works: yes", nil}) }) Convey("field data", t, func() { c := Use(context.Background()) data := map[string]interface{}{ "trombone": 50, "cat": "amazing", } c = logging.SetFields(c, logging.NewFields(data)) l := logging.Get(c) ml := l.(*MemLogger) l.Infof("Some unsuspecting log") So((*ml.data)[0].Data["trombone"], ShouldEqual, 50) So((*ml.data)[0].Data["cat"], ShouldEqual, "amazing") }) }
// proxyMessages forwards a set of pubsub messages to the endpoint proxy. func (a *application) proxyMessages(ctx context.Context, msgs []*pubsub.Message) error { log.Fields{ "size": len(msgs), }.Debugf(ctx, "Sending messages to Proxy.") // TODO: Batch messages together into larger pushes. // TODO: Validate messages. err := parallel.FanOutIn(func(c chan<- func() error) { for idx, msg := range msgs { msg := msg c <- func() error { ctx := log.SetFields(ctx, log.Fields{ "size": len(msg.Data), "messageID": msg.ID, }) err := a.proxySingleMessage(ctx, msg) // If we hit a transient error, set the message's element to nil, // causing it to not be ACKed. if err != nil { transient := luciErrors.IsTransient(err) log.Fields{ log.ErrorKey: err, "transient": transient, }.Errorf(ctx, "Error when pushing message.") if transient { msgs[idx] = nil } } return err } } }) merr, _ := err.(luciErrors.MultiError) log.Fields{ "errorStatus": err, "count": len(msgs), "errorCount": len(merr), }.Infof(ctx, "Sent messages to endpoint.") return err }
// ackMessages ACKs the supplied messages. If a message is nil, it will be // ignored. func (p *pubsubClient) ackMessages(ctx context.Context, messages []*pubsub.Message) (int, error) { messageIds := make([]string, 0, len(messages)) skipped := 0 for _, msg := range messages { if msg != nil { messageIds = append(messageIds, msg.AckID) } else { skipped++ } } if len(messageIds) == 0 { return 0, nil } startTime := clock.Now(ctx) ctx = log.SetFields(ctx, log.Fields{ "count": len(messageIds), "skipped": skipped, }) err := retryCall(ctx, "Ack()", func() error { return p.wrapTransient(p.service.Ack(p.subscription, messageIds)) }) duration := clock.Now(ctx).Sub(startTime) if err != nil { log.Fields{ log.ErrorKey: err, "duration": duration, }.Errorf(ctx, "Failed to ACK messages.") return 0, err } log.Fields{ "duration": duration, }.Debugf(ctx, "Successfully ACK messages.") return len(messageIds), nil }
// Main buffering function, which runs in a goroutine. func (m *meter) consumeWork() { // Acknowledge when this goroutine finishes. defer close(m.closeAckC) ctx := log.SetFilter(m.ctx, "meter") timerRunning := false flushTimer := clock.NewTimer(ctx) defer func() { flushTimer.Stop() }() flushCount := m.Count flushTime := m.Delay // Build our work buffer. workBufferSize := initialWorkBufferSize if flushCount > 0 { // Will never buffer more than this much Work. workBufferSize = flushCount } bufferedWork := make([]interface{}, 0, workBufferSize) log.Debugf(ctx, "Starting work loop.") active := true for active { flushRound := false select { case work, ok := <-m.workC: if !ok { log.Debugf(ctx, "Received instance close signal; terminating.") // Don't immediately exit the loop, since there may still be buffered // Work to flush. active = false flushRound = true break } // Count the work in this group. If we're not using a given metric, try // and avoid wasting time collecting it. bufferedWork = append(bufferedWork, work) // Handle work count threshold. We do this first, since it's trivial to // setup/compute. if flushCount > 0 && len(bufferedWork) >= flushCount { flushRound = true } // Start our flush timer, if it's not already ticking. Only waste time // doing this if we're not already flushing, since flushing will clear the // timer. if !flushRound && flushTime > 0 && !timerRunning { log.Infof(log.SetFields(ctx, log.Fields{ "flushInterval": flushTime, }), "Starting flush timer.") flushTimer.Reset(flushTime) timerRunning = true } // Invoke work callback, if one is set. if m.IngestCallback != nil { flushRound = m.IngestCallback(work) || flushRound } case <-m.flushNowC: flushRound = true case <-flushTimer.GetC(): log.Infof(ctx, "Flush timer has triggered.") timerRunning = false flushRound = true } // Should we flush? if flushRound { flushTimer.Stop() timerRunning = false if len(bufferedWork) > 0 { // Clone bufferedWork, since we re-use it. workToSend := make([]interface{}, len(bufferedWork)) copy(workToSend, bufferedWork) // Clear our Work slice for re-use. This does not resize the underlying // array, since it's likely to fill again. for idx := range bufferedWork { bufferedWork[idx] = nil } bufferedWork = bufferedWork[:0] // Callback with this work. m.Callback(workToSend) } } } }
func TestGoLogger(t *testing.T) { Convey(`A new Go Logger instance`, t, func() { // Regex to pull log information from "formatString". buf := bytes.Buffer{} l := New(&buf, gol.DEBUG) for _, entry := range []struct { L logging.Level F func(string, ...interface{}) T string }{ {logging.Debug, l.Debugf, "DEBU"}, {logging.Info, l.Infof, "INFO"}, {logging.Warning, l.Warningf, "WARN"}, {logging.Error, l.Errorf, "ERRO"}, } { Convey(fmt.Sprintf("Can log to: %s", entry.L), func() { entry.F("Test logging %s", entry.L) matches := lre.FindAllStringSubmatch(normalizeLog(buf.String()), -1) So(len(matches), ShouldEqual, 1) So(len(matches[0]), ShouldEqual, 4) So(matches[0][1], ShouldEqual, "gologger_test.go") So(matches[0][2], ShouldEqual, entry.T) So(matches[0][3], ShouldEqual, fmt.Sprintf("Test logging %s", entry.L)) }) } }) Convey(`A Go Logger instance installed in a Context at Info.`, t, func() { buf := bytes.Buffer{} lc := &LoggerConfig{ Format: standardConfig.Format, Out: &buf, Level: gol.DEBUG, } c := logging.SetLevel(lc.Use(context.Background()), logging.Info) Convey(`Should log through top-level Context methods.`, func() { for _, entry := range []struct { L logging.Level F func(context.Context, string, ...interface{}) T string }{ {logging.Info, logging.Infof, "INFO"}, {logging.Warning, logging.Warningf, "WARN"}, {logging.Error, logging.Errorf, "ERRO"}, } { Convey(fmt.Sprintf("Can log to: %s", entry.L), func() { entry.F(c, "Test logging %s", entry.L) matches := lre.FindAllStringSubmatch(normalizeLog(buf.String()), -1) So(len(matches), ShouldEqual, 1) So(len(matches[0]), ShouldEqual, 4) So(matches[0][1], ShouldEqual, "gologger_test.go") So(matches[0][2], ShouldEqual, entry.T) So(matches[0][3], ShouldEqual, fmt.Sprintf("Test logging %s", entry.L)) }) } }) Convey(`With Fields installed in the Context`, func() { c = logging.SetFields(c, logging.Fields{ logging.ErrorKey: "An error!", "reason": "test", }) Convey(`Should log Fields.`, func() { logging.Infof(c, "Here is a %s", "log") matches := lre.FindAllStringSubmatch(normalizeLog(buf.String()), -1) So(len(matches), ShouldEqual, 1) So(len(matches[0]), ShouldEqual, 4) So(matches[0][1], ShouldEqual, "gologger_test.go") So(matches[0][2], ShouldEqual, "INFO") So(matches[0][3], ShouldEqual, `Here is a log {"error":"An error!", "reason":"test"}`) }) Convey(`Should log fields installed immediately`, func() { logging.Fields{ "foo": "bar", "reason": "override", }.Infof(c, "Here is another %s", "log") matches := lre.FindAllStringSubmatch(normalizeLog(buf.String()), -1) So(len(matches), ShouldEqual, 1) So(len(matches[0]), ShouldEqual, 4) So(matches[0][1], ShouldEqual, "gologger_test.go") So(matches[0][2], ShouldEqual, "INFO") So(matches[0][3], ShouldEqual, `Here is another log {"error":"An error!", "foo":"bar", "reason":"override"}`) }) }) Convey(`Will not log to Debug, as it's below level.`, func() { logging.Debugf(c, "Hello!") So(buf.Len(), ShouldEqual, 0) }) }) }