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)
})
})
}
