venodr: update tsdb and go-kit/log

This commit is contained in:
Fabian Reinartz 2017-03-23 18:44:15 +01:00
parent 397f001ac5
commit a2e7b0b934
12 changed files with 269 additions and 223 deletions

View file

@ -15,7 +15,7 @@ import (
) )
const ( const (
// MagicChunks 4 bytes at the head of series file. // MagicChunks is 4 bytes at the head of series file.
MagicChunks = 0x85BD40DD MagicChunks = 0x85BD40DD
) )

View file

@ -141,11 +141,11 @@ func (c *compactor) match(bs []*BlockMeta) bool {
return uint64(bs[len(bs)-1].MaxTime-bs[0].MinTime) <= c.opts.maxBlockRange return uint64(bs[len(bs)-1].MaxTime-bs[0].MinTime) <= c.opts.maxBlockRange
} }
var entropy = rand.New(rand.NewSource(time.Now().UnixNano()))
func mergeBlockMetas(blocks ...Block) (res BlockMeta) { func mergeBlockMetas(blocks ...Block) (res BlockMeta) {
m0 := blocks[0].Meta() m0 := blocks[0].Meta()
entropy := rand.New(rand.NewSource(time.Now().UnixNano()))
res.Sequence = m0.Sequence res.Sequence = m0.Sequence
res.MinTime = m0.MinTime res.MinTime = m0.MinTime
res.MaxTime = blocks[len(blocks)-1].Meta().MaxTime res.MaxTime = blocks[len(blocks)-1].Meta().MaxTime
@ -258,10 +258,6 @@ func (c *compactor) populate(blocks []Block, indexw IndexWriter, chunkw ChunkWri
if err != nil { if err != nil {
return nil, err return nil, err
} }
// TODO(fabxc): find more transparent way of handling this.
if hb, ok := b.(*headBlock); ok {
all = hb.remapPostings(all)
}
s := newCompactionSeriesSet(b.Index(), b.Chunks(), all) s := newCompactionSeriesSet(b.Index(), b.Chunks(), all)
if i == 0 { if i == 0 {

30
vendor/github.com/fabxc/tsdb/db.go generated vendored
View file

@ -8,6 +8,7 @@ import (
"io/ioutil" "io/ioutil"
"os" "os"
"path/filepath" "path/filepath"
"runtime"
"strconv" "strconv"
"strings" "strings"
"sync" "sync"
@ -98,6 +99,7 @@ type DB struct {
// Mutex that must be held when modifying just the head blocks // Mutex that must be held when modifying just the head blocks
// or the general layout. // or the general layout.
// Must never be held when acquiring a blocks's mutex!
headmtx sync.RWMutex headmtx sync.RWMutex
heads []HeadBlock heads []HeadBlock
@ -154,7 +156,7 @@ func Open(dir string, l log.Logger, r prometheus.Registerer, opts *Options) (db
if l == nil { if l == nil {
l = log.NewLogfmtLogger(os.Stdout) l = log.NewLogfmtLogger(os.Stdout)
l = log.NewContext(l).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) l = log.With(l, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
} }
if opts == nil { if opts == nil {
@ -232,16 +234,17 @@ func (db *DB) retentionCutoff() (bool, error) {
db.mtx.RLock() db.mtx.RLock()
defer db.mtx.RUnlock() defer db.mtx.RUnlock()
// We only consider the already persisted blocks. Head blocks generally
// only account for a fraction of the total data.
db.headmtx.RLock() db.headmtx.RLock()
defer db.headmtx.RUnlock() lenp := len(db.blocks) - len(db.heads)
db.headmtx.RUnlock()
// We don't count the span covered by head blocks towards the if lenp == 0 {
// retention time as it generally makes up a fraction of it.
if len(db.blocks)-len(db.heads) == 0 {
return false, nil return false, nil
} }
last := db.blocks[len(db.blocks)-len(db.heads)-1] last := db.blocks[lenp-1]
mint := last.Meta().MaxTime - int64(db.opts.RetentionDuration) mint := last.Meta().MaxTime - int64(db.opts.RetentionDuration)
return retentionCutoff(db.dir, mint) return retentionCutoff(db.dir, mint)
@ -283,6 +286,7 @@ func (db *DB) compact() (changes bool, err error) {
return changes, errors.Wrap(err, "persist head block") return changes, errors.Wrap(err, "persist head block")
} }
changes = true changes = true
runtime.GC()
} }
// Check for compactions of multiple blocks. // Check for compactions of multiple blocks.
@ -291,6 +295,9 @@ func (db *DB) compact() (changes bool, err error) {
if err != nil { if err != nil {
return changes, errors.Wrap(err, "plan compaction") return changes, errors.Wrap(err, "plan compaction")
} }
if len(plans) == 0 {
break
}
select { select {
case <-db.stopc: case <-db.stopc:
@ -307,10 +314,7 @@ func (db *DB) compact() (changes bool, err error) {
return changes, errors.Wrapf(err, "compact %s", p) return changes, errors.Wrapf(err, "compact %s", p)
} }
changes = true changes = true
} runtime.GC()
// If we didn't compact anything, there's nothing left to do.
if len(plans) == 0 {
break
} }
} }
@ -362,7 +366,7 @@ func (db *DB) seqBlock(i int) (Block, bool) {
func (db *DB) reloadBlocks() error { func (db *DB) reloadBlocks() error {
var cs []io.Closer var cs []io.Closer
defer closeAll(cs...) defer func() { closeAll(cs...) }()
db.mtx.Lock() db.mtx.Lock()
defer db.mtx.Unlock() defer db.mtx.Unlock()
@ -419,7 +423,7 @@ func (db *DB) reloadBlocks() error {
// Close all blocks that we no longer need. They are closed after returning all // Close all blocks that we no longer need. They are closed after returning all
// locks to avoid questionable locking order. // locks to avoid questionable locking order.
for _, b := range db.blocks { for _, b := range db.blocks {
if nb := seqBlocks[b.Meta().Sequence]; nb != b { if nb, ok := seqBlocks[b.Meta().Sequence]; !ok || nb != b {
cs = append(cs, b) cs = append(cs, b)
} }
} }
@ -670,7 +674,7 @@ func (db *DB) cut(mint int64) (HeadBlock, error) {
return nil, err return nil, err
} }
db.blocks = append(db.blocks, newHead) db.blocks = append(db.blocks, newHead) // TODO(fabxc): this is a race!
db.heads = append(db.heads, newHead) db.heads = append(db.heads, newHead)
select { select {

99
vendor/github.com/fabxc/tsdb/head.go generated vendored
View file

@ -17,9 +17,13 @@ import (
"github.com/pkg/errors" "github.com/pkg/errors"
) )
// func init() {
// deadlock.Opts.OnPotentialDeadlock = func() { fmt.Println("found deadlock") }
// }
var ( var (
// ErrNotFound is returned if a looked up resource was not found. // ErrNotFound is returned if a looked up resource was not found.
ErrNotFound = fmt.Errorf("not found") ErrNotFound = errors.Errorf("not found")
// ErrOutOfOrderSample is returned if an appended sample has a // ErrOutOfOrderSample is returned if an appended sample has a
// timestamp larger than the most recent sample. // timestamp larger than the most recent sample.
@ -53,8 +57,7 @@ type headBlock struct {
values map[string]stringset // label names to possible values values map[string]stringset // label names to possible values
postings *memPostings // postings lists for terms postings *memPostings // postings lists for terms
metamtx sync.RWMutex meta BlockMeta
meta BlockMeta
} }
func createHeadBlock(dir string, seq int, l log.Logger, mint, maxt int64) (*headBlock, error) { func createHeadBlock(dir string, seq int, l log.Logger, mint, maxt int64) (*headBlock, error) {
@ -64,6 +67,9 @@ func createHeadBlock(dir string, seq int, l log.Logger, mint, maxt int64) (*head
if err := os.MkdirAll(tmp, 0777); err != nil { if err := os.MkdirAll(tmp, 0777); err != nil {
return nil, err return nil, err
} }
entropy := rand.New(rand.NewSource(time.Now().UnixNano()))
ulid, err := ulid.New(ulid.Now(), entropy) ulid, err := ulid.New(ulid.Now(), entropy)
if err != nil { if err != nil {
return nil, err return nil, err
@ -85,7 +91,7 @@ func createHeadBlock(dir string, seq int, l log.Logger, mint, maxt int64) (*head
// openHeadBlock creates a new empty head block. // openHeadBlock creates a new empty head block.
func openHeadBlock(dir string, l log.Logger) (*headBlock, error) { func openHeadBlock(dir string, l log.Logger) (*headBlock, error) {
wal, err := OpenWAL(dir, log.NewContext(l).With("component", "wal"), 5*time.Second) wal, err := OpenWAL(dir, log.With(l, "component", "wal"), 5*time.Second)
if err != nil { if err != nil {
return nil, err return nil, err
} }
@ -106,6 +112,7 @@ func openHeadBlock(dir string, l log.Logger) (*headBlock, error) {
r := wal.Reader() r := wal.Reader()
Outer:
for r.Next() { for r.Next() {
series, samples := r.At() series, samples := r.At()
@ -114,6 +121,10 @@ func openHeadBlock(dir string, l log.Logger) (*headBlock, error) {
h.meta.Stats.NumSeries++ h.meta.Stats.NumSeries++
} }
for _, s := range samples { for _, s := range samples {
if int(s.ref) >= len(h.series) {
l.Log("msg", "unknown series reference, abort WAL restore", "got", s.ref, "max", len(h.series)-1)
break Outer
}
h.series[s.ref].append(s.t, s.v) h.series[s.ref].append(s.t, s.v)
if !h.inBounds(s.t) { if !h.inBounds(s.t) {
@ -165,10 +176,19 @@ func (h *headBlock) Close() error {
} }
func (h *headBlock) Meta() BlockMeta { func (h *headBlock) Meta() BlockMeta {
h.metamtx.RLock() m := BlockMeta{
defer h.metamtx.RUnlock() ULID: h.meta.ULID,
Sequence: h.meta.Sequence,
MinTime: h.meta.MinTime,
MaxTime: h.meta.MaxTime,
Compaction: h.meta.Compaction,
}
return h.meta m.Stats.NumChunks = atomic.LoadUint64(&h.meta.Stats.NumChunks)
m.Stats.NumSeries = atomic.LoadUint64(&h.meta.Stats.NumSeries)
m.Stats.NumSamples = atomic.LoadUint64(&h.meta.Stats.NumSamples)
return m
} }
func (h *headBlock) Dir() string { return h.dir } func (h *headBlock) Dir() string { return h.dir }
@ -183,12 +203,35 @@ func (h *headBlock) Querier(mint, maxt int64) Querier {
if h.closed { if h.closed {
panic(fmt.Sprintf("block %s already closed", h.dir)) panic(fmt.Sprintf("block %s already closed", h.dir))
} }
// Reference on the original slice to use for postings mapping.
series := h.series[:]
return &blockQuerier{ return &blockQuerier{
mint: mint, mint: mint,
maxt: maxt, maxt: maxt,
index: h.Index(), index: h.Index(),
chunks: h.Chunks(), chunks: h.Chunks(),
postingsMapper: h.remapPostings, postingsMapper: func(p Postings) Postings {
ep := make([]uint32, 0, 64)
for p.Next() {
// Skip posting entries that include series added after we
// instantiated the querier.
if int(p.At()) >= len(series) {
break
}
ep = append(ep, p.At())
}
if err := p.Err(); err != nil {
return errPostings{err: errors.Wrap(err, "expand postings")}
}
sort.Slice(ep, func(i, j int) bool {
return labels.Compare(series[ep[i]].lset, series[ep[j]].lset) < 0
})
return newListPostings(ep)
},
} }
} }
@ -392,11 +435,8 @@ func (a *headAppender) Commit() error {
a.mtx.RUnlock() a.mtx.RUnlock()
a.metamtx.Lock() atomic.AddUint64(&a.meta.Stats.NumSamples, total)
defer a.metamtx.Unlock() atomic.AddUint64(&a.meta.Stats.NumSeries, uint64(len(a.newSeries)))
a.meta.Stats.NumSamples += total
a.meta.Stats.NumSeries += uint64(len(a.newSeries))
return nil return nil
} }
@ -551,28 +591,6 @@ func (h *headBlock) create(hash uint64, lset labels.Labels) *memSeries {
return s return s
} }
// remapPostings changes the order of the postings from their ID to the ordering
// of the series they reference.
// Returned postings have no longer monotonic IDs and MUST NOT be used for regular
// postings set operations, i.e. intersect and merge.
func (h *headBlock) remapPostings(p Postings) Postings {
// Expand the postings but only up until the point where the mapper
// covers existing metrics.
ep := make([]uint32, 0, 64)
for p.Next() {
ep = append(ep, p.At())
}
if err := p.Err(); err != nil {
return errPostings{err: errors.Wrap(err, "expand postings")}
}
sort.Slice(ep, func(i, j int) bool {
return labels.Compare(h.series[i].lset, h.series[j].lset) < 0
})
return newListPostings(ep)
}
type memSeries struct { type memSeries struct {
mtx sync.RWMutex mtx sync.RWMutex
@ -603,6 +621,9 @@ func (s *memSeries) cut() *memChunk {
} }
func (s *memSeries) append(t int64, v float64) bool { func (s *memSeries) append(t int64, v float64) bool {
s.mtx.Lock()
defer s.mtx.Unlock()
var c *memChunk var c *memChunk
if s.app == nil || s.head().samples > 2000 { if s.app == nil || s.head().samples > 2000 {

View file

@ -461,7 +461,7 @@ type SeriesIterator interface {
// If there's no value exactly at ts, it advances to the last value // If there's no value exactly at ts, it advances to the last value
// before tt. // before tt.
Seek(t int64) bool Seek(t int64) bool
// Values returns the current timestamp/value pair. // At returns the current timestamp/value pair.
At() (t int64, v float64) At() (t int64, v float64)
// Next advances the iterator by one. // Next advances the iterator by one.
Next() bool Next() bool
@ -674,7 +674,7 @@ func (b *BufferedSeriesIterator) Next() bool {
return ok return ok
} }
// Values returns the current element of the iterator. // At returns the current element of the iterator.
func (b *BufferedSeriesIterator) At() (int64, float64) { func (b *BufferedSeriesIterator) At() (int64, float64) {
return b.it.At() return b.it.At()
} }

12
vendor/github.com/fabxc/tsdb/wal.go generated vendored
View file

@ -61,6 +61,15 @@ const (
walSegmentSizeBytes = 256 * 1024 * 1024 // 256 MB walSegmentSizeBytes = 256 * 1024 * 1024 // 256 MB
) )
// The table gets initialized with sync.Once but may still cause a race
// with any other use of the crc32 package anywhere. Thus we initialize it
// before.
var castagnoliTable *crc32.Table
func init() {
castagnoliTable = crc32.MakeTable(crc32.Castagnoli)
}
// OpenWAL opens or creates a write ahead log in the given directory. // OpenWAL opens or creates a write ahead log in the given directory.
// The WAL must be read completely before new data is written. // The WAL must be read completely before new data is written.
func OpenWAL(dir string, logger log.Logger, flushInterval time.Duration) (*WAL, error) { func OpenWAL(dir string, logger log.Logger, flushInterval time.Duration) (*WAL, error) {
@ -84,7 +93,7 @@ func OpenWAL(dir string, logger log.Logger, flushInterval time.Duration) (*WAL,
donec: make(chan struct{}), donec: make(chan struct{}),
stopc: make(chan struct{}), stopc: make(chan struct{}),
segmentSize: walSegmentSizeBytes, segmentSize: walSegmentSizeBytes,
crc32: crc32.New(crc32.MakeTable(crc32.Castagnoli)), crc32: crc32.New(castagnoliTable),
} }
if err := w.initSegments(); err != nil { if err := w.initSegments(); err != nil {
return nil, err return nil, err
@ -214,6 +223,7 @@ func (w *WAL) tail() *os.File {
return w.files[len(w.files)-1] return w.files[len(w.files)-1]
} }
// Sync flushes the changes to disk.
func (w *WAL) Sync() error { func (w *WAL) Sync() error {
w.mtx.Lock() w.mtx.Lock()
defer w.mtx.Unlock() defer w.mtx.Unlock()

View file

@ -1,20 +1,22 @@
# package log # package log
`package log` provides a minimal interface for structured logging in services. `package log` provides a minimal interface for structured logging in services.
It may be wrapped to encode conventions, enforce type-safety, provide leveled logging, and so on. It may be wrapped to encode conventions, enforce type-safety, provide leveled
It can be used for both typical application log events, and log-structured data streams. logging, and so on. It can be used for both typical application log events,
and log-structured data streams.
## Structured logging ## Structured logging
Structured logging is, basically, conceding to the reality that logs are _data_, Structured logging is, basically, conceding to the reality that logs are
and warrant some level of schematic rigor. _data_, and warrant some level of schematic rigor. Using a stricter,
Using a stricter, key/value-oriented message format for our logs, key/value-oriented message format for our logs, containing contextual and
containing contextual and semantic information, semantic information, makes it much easier to get insight into the
makes it much easier to get insight into the operational activity of the systems we build. operational activity of the systems we build. Consequently, `package log` is
Consequently, `package log` is of the strong belief that of the strong belief that "[the benefits of structured logging outweigh the
"[the benefits of structured logging outweigh the minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)". minimal effort involved](https://www.thoughtworks.com/radar/techniques/structured-logging)".
Migrating from unstructured to structured logging is probably a lot easier than you'd expect. Migrating from unstructured to structured logging is probably a lot easier
than you'd expect.
```go ```go
// Unstructured // Unstructured
@ -37,17 +39,17 @@ logger.Log("question", "what is the meaning of life?", "answer", 42)
// question="what is the meaning of life?" answer=42 // question="what is the meaning of life?" answer=42
``` ```
### Log contexts ### Contextual Loggers
```go ```go
func main() { func main() {
var logger log.Logger var logger log.Logger
logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
logger = log.NewContext(logger).With("instance_id", 123) logger = log.With(logger, "instance_id", 123)
logger.Log("msg", "starting") logger.Log("msg", "starting")
NewWorker(log.NewContext(logger).With("component", "worker")).Run() NewWorker(log.With(logger, "component", "worker")).Run()
NewSlacker(log.NewContext(logger).With("component", "slacker")).Run() NewSlacker(log.With(logger, "component", "slacker")).Run()
} }
// Output: // Output:
@ -77,9 +79,8 @@ func main() {
// {"msg":"I sure like pie","ts":"2016/01/01 12:34:56"} // {"msg":"I sure like pie","ts":"2016/01/01 12:34:56"}
``` ```
Or, if, for legacy reasons, Or, if, for legacy reasons, you need to pipe all of your logging through the
you need to pipe all of your logging through the stdlib log package, stdlib log package, you can redirect Go kit logger to the stdlib logger.
you can redirect Go kit logger to the stdlib logger.
```go ```go
logger := kitlog.NewLogfmtLogger(kitlog.StdlibWriter{}) logger := kitlog.NewLogfmtLogger(kitlog.StdlibWriter{})
@ -94,7 +95,7 @@ logger.Log("legacy", true, "msg", "at least it's something")
```go ```go
var logger log.Logger var logger log.Logger
logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr)) logger = log.NewLogfmtLogger(log.NewSyncWriter(os.Stderr))
logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
logger.Log("msg", "hello") logger.Log("msg", "hello")
@ -104,7 +105,7 @@ logger.Log("msg", "hello")
## Supported output formats ## Supported output formats
- [Logfmt](https://brandur.org/logfmt) - [Logfmt](https://brandur.org/logfmt) ([see also](https://blog.codeship.com/logfmt-a-log-format-thats-easy-to-read-and-write))
- JSON - JSON
## Enhancements ## Enhancements
@ -117,27 +118,25 @@ type Logger interface {
} }
``` ```
This interface, and its supporting code like [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context), This interface, and its supporting code like is the product of much iteration
is the product of much iteration and evaluation. and evaluation. For more details on the evolution of the Logger interface,
For more details on the evolution of the Logger interface, see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1),
see [The Hunt for a Logger Interface](http://go-talks.appspot.com/github.com/ChrisHines/talks/structured-logging/structured-logging.slide#1), a talk by [Chris Hines](https://github.com/ChrisHines).
a talk by [Chris Hines](https://github.com/ChrisHines).
Also, please see Also, please see
[#63](https://github.com/go-kit/kit/issues/63), [#63](https://github.com/go-kit/kit/issues/63),
[#76](https://github.com/go-kit/kit/pull/76), [#76](https://github.com/go-kit/kit/pull/76),
[#131](https://github.com/go-kit/kit/issues/131), [#131](https://github.com/go-kit/kit/issues/131),
[#157](https://github.com/go-kit/kit/pull/157), [#157](https://github.com/go-kit/kit/pull/157),
[#164](https://github.com/go-kit/kit/issues/164), and [#164](https://github.com/go-kit/kit/issues/164), and
[#252](https://github.com/go-kit/kit/pull/252) [#252](https://github.com/go-kit/kit/pull/252)
to review historical conversations about package log and the Logger interface. to review historical conversations about package log and the Logger interface.
Value-add packages and suggestions, Value-add packages and suggestions,
like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/levels), like improvements to [the leveled logger](https://godoc.org/github.com/go-kit/kit/log/level),
are of course welcome. are of course welcome. Good proposals should
Good proposals should
- Be composable with [log.Context](https://godoc.org/github.com/go-kit/kit/log#Context), - Be composable with [contextual loggers](https://godoc.org/github.com/go-kit/kit/log#With),
- Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped context, and - Not break the behavior of [log.Caller](https://godoc.org/github.com/go-kit/kit/log#Caller) in any wrapped contextual loggers, and
- Be friendly to packages that accept only an unadorned log.Logger. - Be friendly to packages that accept only an unadorned log.Logger.
## Benchmarks & comparisons ## Benchmarks & comparisons

View file

@ -35,14 +35,15 @@
// idea to log simple values without formatting them. This practice allows // idea to log simple values without formatting them. This practice allows
// the chosen logger to encode values in the most appropriate way. // the chosen logger to encode values in the most appropriate way.
// //
// Log Context // Contextual Loggers
// //
// A log context stores keyvals that it includes in all log events. Building // A contextual logger stores keyvals that it includes in all log events.
// appropriate log contexts reduces repetition and aids consistency in the // Building appropriate contextual loggers reduces repetition and aids
// resulting log output. We can use a context to improve the RunTask example. // consistency in the resulting log output. With and WithPrefix add context to
// a logger. We can use With to improve the RunTask example.
// //
// func RunTask(task Task, logger log.Logger) string { // func RunTask(task Task, logger log.Logger) string {
// logger = log.NewContext(logger).With("taskID", task.ID) // logger = log.With(logger, "taskID", task.ID)
// logger.Log("event", "starting task") // logger.Log("event", "starting task")
// ... // ...
// taskHelper(task.Cmd, logger) // taskHelper(task.Cmd, logger)
@ -51,19 +52,18 @@
// } // }
// //
// The improved version emits the same log events as the original for the // The improved version emits the same log events as the original for the
// first and last calls to Log. The call to taskHelper highlights that a // first and last calls to Log. Passing the contextual logger to taskHelper
// context may be passed as a logger to other functions. Each log event // enables each log event created by taskHelper to include the task.ID even
// created by the called function will include the task.ID even though the // though taskHelper does not have access to that value. Using contextual
// function does not have access to that value. Using log contexts this way // loggers this way simplifies producing log output that enables tracing the
// simplifies producing log output that enables tracing the life cycle of // life cycle of individual tasks. (See the Contextual example for the full
// individual tasks. (See the Context example for the full code of the // code of the above snippet.)
// above snippet.)
// //
// Dynamic Context Values // Dynamic Contextual Values
// //
// A Valuer function stored in a log context generates a new value each time // A Valuer function stored in a contextual logger generates a new value each
// the context logs an event. The Valuer example demonstrates how this // time an event is logged. The Valuer example demonstrates how this feature
// feature works. // works.
// //
// Valuers provide the basis for consistently logging timestamps and source // Valuers provide the basis for consistently logging timestamps and source
// code location. The log package defines several valuers for that purpose. // code location. The log package defines several valuers for that purpose.
@ -72,7 +72,7 @@
// entries contain a timestamp and source location looks like this: // entries contain a timestamp and source location looks like this:
// //
// logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout)) // logger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout))
// logger = log.NewContext(logger).With("ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller) // logger = log.With(logger, "ts", log.DefaultTimestampUTC, "caller", log.DefaultCaller)
// //
// Concurrent Safety // Concurrent Safety
// //
@ -90,4 +90,27 @@
// handled atomically within the wrapped logger, but it typically serializes // handled atomically within the wrapped logger, but it typically serializes
// both the formatting and output logic. Use a SyncLogger if the formatting // both the formatting and output logic. Use a SyncLogger if the formatting
// logger may perform multiple writes per log event. // logger may perform multiple writes per log event.
//
// Error Handling
//
// This package relies on the practice of wrapping or decorating loggers with
// other loggers to provide composable pieces of functionality. It also means
// that Logger.Log must return an error because some
// implementations—especially those that output log data to an io.Writer—may
// encounter errors that cannot be handled locally. This in turn means that
// Loggers that wrap other loggers should return errors from the wrapped
// logger up the stack.
//
// Fortunately, the decorator pattern also provides a way to avoid the
// necessity to check for errors every time an application calls Logger.Log.
// An application required to panic whenever its Logger encounters
// an error could initialize its logger as follows.
//
// fmtlogger := log.NewLogfmtLogger(log.NewSyncWriter(os.Stdout))
// logger := log.LoggerFunc(func(keyvals ...interface{}) error {
// if err := fmtlogger.Log(keyvals...); err != nil {
// panic(err)
// }
// return nil
// })
package log package log

View file

@ -6,7 +6,7 @@ import "errors"
// log event from keyvals, a variadic sequence of alternating keys and values. // log event from keyvals, a variadic sequence of alternating keys and values.
// Implementations must be safe for concurrent use by multiple goroutines. In // Implementations must be safe for concurrent use by multiple goroutines. In
// particular, any implementation of Logger that appends to keyvals or // particular, any implementation of Logger that appends to keyvals or
// modifies any of its elements must make a copy first. // modifies or retains any of its elements must make a copy first.
type Logger interface { type Logger interface {
Log(keyvals ...interface{}) error Log(keyvals ...interface{}) error
} }
@ -15,62 +15,100 @@ type Logger interface {
// the missing value. // the missing value.
var ErrMissingValue = errors.New("(MISSING)") var ErrMissingValue = errors.New("(MISSING)")
// NewContext returns a new Context that logs to logger. // With returns a new contextual logger with keyvals prepended to those passed
func NewContext(logger Logger) *Context { // to calls to Log. If logger is also a contextual logger created by With or
if c, ok := logger.(*Context); ok { // WithPrefix, keyvals is appended to the existing context.
return c //
// The returned Logger replaces all value elements (odd indexes) containing a
// Valuer with their generated value for each call to its Log method.
func With(logger Logger, keyvals ...interface{}) Logger {
if len(keyvals) == 0 {
return logger
}
l := newContext(logger)
kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
return &context{
logger: l.logger,
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
keyvals: kvs[:len(kvs):len(kvs)],
hasValuer: l.hasValuer || containsValuer(keyvals),
} }
return &Context{logger: logger}
} }
// Context must always have the same number of stack frames between calls to // WithPrefix returns a new contextual logger with keyvals prepended to those
// passed to calls to Log. If logger is also a contextual logger created by
// With or WithPrefix, keyvals is prepended to the existing context.
//
// The returned Logger replaces all value elements (odd indexes) containing a
// Valuer with their generated value for each call to its Log method.
func WithPrefix(logger Logger, keyvals ...interface{}) Logger {
if len(keyvals) == 0 {
return logger
}
l := newContext(logger)
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
n := len(l.keyvals) + len(keyvals)
if len(keyvals)%2 != 0 {
n++
}
kvs := make([]interface{}, 0, n)
kvs = append(kvs, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
kvs = append(kvs, l.keyvals...)
return &context{
logger: l.logger,
keyvals: kvs,
hasValuer: l.hasValuer || containsValuer(keyvals),
}
}
// context is the Logger implementation returned by With and WithPrefix. It
// wraps a Logger and holds keyvals that it includes in all log events. Its
// Log method calls bindValues to generate values for each Valuer in the
// context keyvals.
//
// A context must always have the same number of stack frames between calls to
// its Log method and the eventual binding of Valuers to their value. This // its Log method and the eventual binding of Valuers to their value. This
// requirement comes from the functional requirement to allow a context to // requirement comes from the functional requirement to allow a context to
// resolve application call site information for a log.Caller stored in the // resolve application call site information for a Caller stored in the
// context. To do this we must be able to predict the number of logging // context. To do this we must be able to predict the number of logging
// functions on the stack when bindValues is called. // functions on the stack when bindValues is called.
// //
// Three implementation details provide the needed stack depth consistency. // Two implementation details provide the needed stack depth consistency.
// The first two of these details also result in better amortized performance,
// and thus make sense even without the requirements regarding stack depth.
// The third detail, however, is subtle and tied to the implementation of the
// Go compiler.
// //
// 1. NewContext avoids introducing an additional layer when asked to // 1. newContext avoids introducing an additional layer when asked to
// wrap another Context. // wrap another context.
// 2. With avoids introducing an additional layer by returning a newly // 2. With and WithPrefix avoid introducing an additional layer by
// constructed Context with a merged keyvals rather than simply // returning a newly constructed context with a merged keyvals rather
// wrapping the existing Context. // than simply wrapping the existing context.
// 3. All of Context's methods take pointer receivers even though they type context struct {
// do not mutate the Context.
//
// Before explaining the last detail, first some background. The Go compiler
// generates wrapper methods to implement the auto dereferencing behavior when
// calling a value method through a pointer variable. These wrapper methods
// are also used when calling a value method through an interface variable
// because interfaces store a pointer to the underlying concrete value.
// Calling a pointer receiver through an interface does not require generating
// an additional function.
//
// If Context had value methods then calling Context.Log through a variable
// with type Logger would have an extra stack frame compared to calling
// Context.Log through a variable with type Context. Using pointer receivers
// avoids this problem.
// A Context wraps a Logger and holds keyvals that it includes in all log
// events. When logging, a Context replaces all value elements (odd indexes)
// containing a Valuer with their generated value for each call to its Log
// method.
type Context struct {
logger Logger logger Logger
keyvals []interface{} keyvals []interface{}
hasValuer bool hasValuer bool
} }
func newContext(logger Logger) *context {
if c, ok := logger.(*context); ok {
return c
}
return &context{logger: logger}
}
// Log replaces all value elements (odd indexes) containing a Valuer in the // Log replaces all value elements (odd indexes) containing a Valuer in the
// stored context with their generated value, appends keyvals, and passes the // stored context with their generated value, appends keyvals, and passes the
// result to the wrapped Logger. // result to the wrapped Logger.
func (l *Context) Log(keyvals ...interface{}) error { func (l *context) Log(keyvals ...interface{}) error {
kvs := append(l.keyvals, keyvals...) kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 { if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue) kvs = append(kvs, ErrMissingValue)
@ -86,53 +124,6 @@ func (l *Context) Log(keyvals ...interface{}) error {
return l.logger.Log(kvs...) return l.logger.Log(kvs...)
} }
// With returns a new Context with keyvals appended to those of the receiver.
func (l *Context) With(keyvals ...interface{}) *Context {
if len(keyvals) == 0 {
return l
}
kvs := append(l.keyvals, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
return &Context{
logger: l.logger,
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
keyvals: kvs[:len(kvs):len(kvs)],
hasValuer: l.hasValuer || containsValuer(keyvals),
}
}
// WithPrefix returns a new Context with keyvals prepended to those of the
// receiver.
func (l *Context) WithPrefix(keyvals ...interface{}) *Context {
if len(keyvals) == 0 {
return l
}
// Limiting the capacity of the stored keyvals ensures that a new
// backing array is created if the slice must grow in Log or With.
// Using the extra capacity without copying risks a data race that
// would violate the Logger interface contract.
n := len(l.keyvals) + len(keyvals)
if len(keyvals)%2 != 0 {
n++
}
kvs := make([]interface{}, 0, n)
kvs = append(kvs, keyvals...)
if len(kvs)%2 != 0 {
kvs = append(kvs, ErrMissingValue)
}
kvs = append(kvs, l.keyvals...)
return &Context{
logger: l.logger,
keyvals: kvs,
hasValuer: l.hasValuer || containsValuer(keyvals),
}
}
// LoggerFunc is an adapter to allow use of ordinary functions as Loggers. If // LoggerFunc is an adapter to allow use of ordinary functions as Loggers. If
// f is a function with the appropriate signature, LoggerFunc(f) is a Logger // f is a function with the appropriate signature, LoggerFunc(f) is a Logger
// object that calls f. // object that calls f.

View file

@ -39,7 +39,7 @@ func TimestampKey(key string) StdlibAdapterOption {
return func(a *StdlibAdapter) { a.timestampKey = key } return func(a *StdlibAdapter) { a.timestampKey = key }
} }
// FileKey sets the key for the file and line field. By default, it's "file". // FileKey sets the key for the file and line field. By default, it's "caller".
func FileKey(key string) StdlibAdapterOption { func FileKey(key string) StdlibAdapterOption {
return func(a *StdlibAdapter) { a.fileKey = key } return func(a *StdlibAdapter) { a.fileKey = key }
} }
@ -55,7 +55,7 @@ func NewStdlibAdapter(logger Logger, options ...StdlibAdapterOption) io.Writer {
a := StdlibAdapter{ a := StdlibAdapter{
Logger: logger, Logger: logger,
timestampKey: "ts", timestampKey: "ts",
fileKey: "file", fileKey: "caller",
messageKey: "msg", messageKey: "msg",
} }
for _, option := range options { for _, option := range options {

View file

@ -6,9 +6,9 @@ import (
"github.com/go-stack/stack" "github.com/go-stack/stack"
) )
// A Valuer generates a log value. When passed to Context.With in a value // A Valuer generates a log value. When passed to With or WithPrefix in a
// element (odd indexes), it represents a dynamic value which is re-evaluated // value element (odd indexes), it represents a dynamic value which is re-
// with each log event. // evaluated with each log event.
type Valuer func() interface{} type Valuer func() interface{}
// bindValues replaces all value elements (odd indexes) containing a Valuer // bindValues replaces all value elements (odd indexes) containing a Valuer
@ -39,16 +39,6 @@ func Timestamp(t func() time.Time) Valuer {
return func() interface{} { return t() } return func() interface{} { return t() }
} }
var (
// DefaultTimestamp is a Valuer that returns the current wallclock time,
// respecting time zones, when bound.
DefaultTimestamp Valuer = func() interface{} { return time.Now().Format(time.RFC3339) }
// DefaultTimestampUTC is a Valuer that returns the current time in UTC
// when bound.
DefaultTimestampUTC Valuer = func() interface{} { return time.Now().UTC().Format(time.RFC3339) }
)
// Caller returns a Valuer that returns a file and line from a specified depth // Caller returns a Valuer that returns a file and line from a specified depth
// in the callstack. Users will probably want to use DefaultCaller. // in the callstack. Users will probably want to use DefaultCaller.
func Caller(depth int) Valuer { func Caller(depth int) Valuer {
@ -56,6 +46,18 @@ func Caller(depth int) Valuer {
} }
var ( var (
// DefaultTimestamp is a Valuer that returns the current wallclock time,
// respecting time zones, when bound.
DefaultTimestamp = Valuer(func() interface{} {
return time.Now().Format(time.RFC3339Nano)
})
// DefaultTimestampUTC is a Valuer that returns the current time in UTC
// when bound.
DefaultTimestampUTC = Valuer(func() interface{} {
return time.Now().UTC().Format(time.RFC3339Nano)
})
// DefaultCaller is a Valuer that returns the file and line where the Log // DefaultCaller is a Valuer that returns the file and line where the Log
// method was invoked. It can only be used with log.With. // method was invoked. It can only be used with log.With.
DefaultCaller = Caller(3) DefaultCaller = Caller(3)

12
vendor/vendor.json vendored
View file

@ -368,10 +368,10 @@
"revisionTime": "2016-09-30T00:14:02Z" "revisionTime": "2016-09-30T00:14:02Z"
}, },
{ {
"checksumSHA1": "8wTICzej/k4pCcYtSw+fmD6oZZE=", "checksumSHA1": "L4bnnz4uVgDueUvcTKkZJ+IqPbw=",
"path": "github.com/fabxc/tsdb", "path": "github.com/fabxc/tsdb",
"revision": "2ef3682560a31bd03f0ba70eb6ec509512ad0de8", "revision": "70909ca8ad875aa6f01e1801d185b3f3bab2fda3",
"revisionTime": "2017-03-20T10:37:06Z" "revisionTime": "2017-03-21T11:21:02Z"
}, },
{ {
"checksumSHA1": "uVzWuLvF646YjiKomsc2CR1ua58=", "checksumSHA1": "uVzWuLvF646YjiKomsc2CR1ua58=",
@ -399,10 +399,10 @@
"revisionTime": "2016-08-27T06:11:18Z" "revisionTime": "2016-08-27T06:11:18Z"
}, },
{ {
"checksumSHA1": "7Ta13bcuAlF1esPxSPljmpsSUwc=", "checksumSHA1": "ZSRtnAM/vH1sl0jxr4HztYI/4vs=",
"path": "github.com/go-kit/kit/log", "path": "github.com/go-kit/kit/log",
"revision": "3db037d8577b40174b37b73b62469aa9363020f6", "revision": "04dd4f741c6e76cc170a4d7913f4c625952e6f58",
"revisionTime": "2017-01-10T08:27:22Z" "revisionTime": "2017-03-20T09:05:36Z"
}, },
{ {
"checksumSHA1": "KxX/Drph+byPXBFIXaCZaCOAnrU=", "checksumSHA1": "KxX/Drph+byPXBFIXaCZaCOAnrU=",