Пример #1
0
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")
	})
}
Пример #2
0
// 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
}
Пример #3
0
// 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
}
Пример #4
0
// 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)
			}
		}
	}
}
Пример #5
0
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)
		})
	})
}