Skip to content

Commit

Permalink
Merge pull request #28 from ipfs/fix/update-README
Browse files Browse the repository at this point in the history 
Fix/update readme
  • Loading branch information
@frrist
frrist committed Apr 30, 2018
2 parents 5e73401 + 0b65b1a commit 804754e
Show file tree
Hide file tree
Showing 2 changed files with 93 additions and 109 deletions.
69 changes: 26 additions & 43 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -28,59 +28,42 @@ Once the pacakge is imported under the name `logging`, an instance of `EventLogg
var log = logging.Logger("subsystem name")
```

It can then be used to emit log messages, either plain printf-style messages at six standard levels or structured messages using `Event`, `EventBegin` and `EventBeginInContext` methods.
It can then be used to emit log messages, either plain printf-style messages at six standard levels or structured messages using `Start`, `StartFromParentState`, `Finish` and `FinishWithErr` methods.

## Examples
## Example

**Event**
```go
log.Event(ctx, "event name", logging.LoggableMap{"metaKey": metaValue})
```

**EventBegin**

In a method with named returns
```go
func (s *Session) GetBlock(ctx context.Context, c *cid.Cid) (blk blocks.Block, err error) {
eip := log.EventBegin(ctx, "Session.GetBlock", c)
defer func() {
if err != nil {
eip.SetError(err)

// Starts Span called "Session.GetBlock", associates with `ctx`
ctx = log.Start(ctx, "Session.GetBlock")

// defer so `blk` and `err` can be evaluated after call
defer func() {
// tag span associated with `ctx`
log.SetTags(ctx, map[string]interface{}{
"cid": c,
"block", blk,
})
// if err is non-nil tag the span with an error
log.FinishWithErr(ctx, err)
}()

if shouldStartSomething() {
// log message on span associated with `ctx`
log.LogKV(ctx, "startSomething", true)
}
eip.Done()
}()
...
}
```
As a one liner
```go
defer log.EventBegin(ctx, "bootstrapDial", ph.ID(), p.ID).Done()
```
## Tracing

**EventBeginInContext**
`go-log` wraps the [opentracing-go](https://github.com/opentracing/opentracing-go) methods - `StartSpan`, `Finish`, `LogKV`, and `SetTag`.

`go-log` implements its own tracer - `loggabletracer` - based on the [basictracer-go](https://github.com/opentracing/basictracer-go) implementation. If there is an active [`WriterGroup`](https://github.com/ipfs/go-log/blob/master/writer/option.go) the `loggabletracer` will [record](https://github.com/ipfs/go-log/blob/master/tracer/recorder.go) span data to the `WriterGroup`. An example of this can be seen in the [`log tail`](https://github.com/ipfs/go-ipfs/blob/master/core/commands/log.go) command of `go-ipfs`.

Third party tracers may be used by calling `opentracing.SetGlobalTracer()` with your desired tracing implementation. An example of this can be seen using the [`go-jaeger-plugin`](https://github.com/ipfs/go-jaeger-plugin) and the `go-ipfs` [tracer plugin](https://github.com/ipfs/go-ipfs/blob/master/plugin/tracer.go)

When an event spans more than one function call
Start and event in the context
```go
func (s *blockService) GetBlocks(ctx context.Context, ks []*cid.Cid) <-chan blocks.Block {
ctx = log.EventBeginInContext(ctx, "BlockService.GetBlocks")
return getBlocks(ctx, ks, s.blockstore, s.exchange)
}
```
Finish the event later
```go
func getBlocks(ctx context.Context, ks []*cid.Cid, bs blockstore.Blockstore, f exchange.Fetcher) <-chan blocks.Block {
...
go func() {
defer logging.MaybeFinishEvent(ctx)
...
select {
case out <- hit:
case <-ctx.Done():
return
}
}
```
## Contribute

Feel free to join in. All welcome. Open an [issue](https://github.com/ipfs/go-log/issues)!
Expand Down
133 changes: 67 additions & 66 deletions log.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -60,19 +60,86 @@ type EventLogger interface {
// DEPRECATED
EventBegin(ctx context.Context, event string, m ...Loggable) *EventInProgress

// Start starts an opentracing span with `name`, using
// any Span found within `ctx` as a ChildOfRef. If no such parent could be
// found, Start creates a root (parentless) Span.
//
// The return value is a context.Context object built around the
// returned Span.
//
// Example usage:
//
// SomeFunction(ctx context.Context, ...) {
// ctx := log.Start(ctx, "SomeFunction")
// defer log.Finish(ctx)
// ...
// }
Start(ctx context.Context, name string) context.Context

// StartFromParentState starts an opentracing span with `name`, using
// any Span found within `ctx` as a ChildOfRef. If no such parent could be
// found, StartSpanFromParentState creates a root (parentless) Span.
//
// StartFromParentState will attempt to deserialize a SpanContext from `parent`,
// using any Span found within to continue the trace
//
// The return value is a context.Context object built around the
// returned Span.
//
// An error is returned when `parent` cannot be deserialized to a SpanContext
//
// Example usage:
//
// SomeFunction(ctx context.Context, bParent []byte) {
// ctx := log.StartFromParentState(ctx, "SomeFunction", bParent)
// defer log.Finish(ctx)
// ...
// }
StartFromParentState(ctx context.Context, name string, parent []byte) (context.Context, error)

// Finish completes the span associated with `ctx`.
//
// Finish() must be the last call made to any span instance, and to do
// otherwise leads to undefined behavior.
// Finish will do its best to notify (log) when used in correctly
// .e.g called twice, or called on a spanless `ctx`
Finish(ctx context.Context)

// FinishWithErr completes the span associated with `ctx` and also calls
// SetErr if `err` is non-nil
//
// FinishWithErr() must be the last call made to any span instance, and to do
// otherwise leads to undefined behavior.
// FinishWithErr will do its best to notify (log) when used in correctly
// .e.g called twice, or called on a spanless `ctx`
FinishWithErr(ctx context.Context, err error)

// SetErr tags the span associated with `ctx` to reflect an error occured, and
// logs the value `err` under key `error`.
SetErr(ctx context.Context, err error)

// LogKV records key:value logging data about an event stored in `ctx`
// Eexample:
// log.LogKV(
// "error", "resolve failure",
// "type", "cache timeout",
// "waited.millis", 1500)
LogKV(ctx context.Context, alternatingKeyValues ...interface{})

// SetTag tags key `k` and value `v` on the span associated with `ctx`
SetTag(ctx context.Context, key string, value interface{})

// SetTags tags keys from the `tags` maps on the span associated with `ctx`
// Example:
// log.SetTags(ctx, map[string]{
// "type": bizStruct,
// "request": req,
// })
SetTags(ctx context.Context, tags map[string]interface{})

// SerializeContext takes the SpanContext instance stored in `ctx` and Seralizes
// it to bytes. An error is returned if the `ctx` cannot be serialized to
// a bytes array
SerializeContext(ctx context.Context) ([]byte, error)
}

Expand Down Expand Up @@ -100,46 +167,12 @@ type eventLogger struct {
// TODO add log-level
}

// Start starts an opentracing span with `operationName`, using
// any Span found within `ctx` as a ChildOfRef. If no such parent could be
// found, StartSpanFromContext creates a root (parentless) Span.
//
// The return value is a context.Context object built around the
// returned Span.
//
// Example usage:
//
// SomeFunction(ctx context.Context, ...) {
// ctx := log.Start(ctx, "SomeFunction")
// defer log.Finish(ctx)
// ...
// }
func (el *eventLogger) Start(ctx context.Context, operationName string) context.Context {
span, ctx := opentrace.StartSpanFromContext(ctx, operationName)
span.SetTag("system", el.system)
return ctx
}

// TODO: need clearer examples and description
// StartFromParentState starts an opentracing span with `operationName`, using
// any Span found within `ctx` as a ChildOfRef. If no such parent could be
// found, StartSpanFromContext creates a root (parentless) Span.
//
// StartFromParentState will attempt to deserialize a SpanContext from `parent`,
// using any Span found within to continue the trace
//
// The return value is a context.Context object built around the
// returned Span.
//
// An error is returned when `parent` cannot be deserialized to a SpanContext
//
// Example usage:
//
// SomeFunction(ctx context.Context, ...) {
// ctx := log.StartFromParentState(ctx, "SomeFunction", bParent)
// defer log.Finish(ctx)
// ...
// }
func (el *eventLogger) StartFromParentState(ctx context.Context, operationName string, parent []byte) (context.Context, error) {
sc, err := deserializeContext(parent)
if err != nil {
Expand All @@ -152,8 +185,6 @@ func (el *eventLogger) StartFromParentState(ctx context.Context, operationName s
return ctx, nil
}

// SerializeContext takes the SpanContext instance stored in `ctx`, and Seralizes
// it to bytes.
func (el *eventLogger) SerializeContext(ctx context.Context) ([]byte, error) {
gTracer := opentrace.GlobalTracer()
b := make([]byte, 0)
Expand All @@ -165,12 +196,6 @@ func (el *eventLogger) SerializeContext(ctx context.Context) ([]byte, error) {
return carrier.Bytes(), nil
}

// LogKV records key:value logging data about an event stored in `ctx`
// Eexample:
// log.LogKV(
// "error", "resolve failure",
// "type", "cache timeout",
// "waited.millis", 1500)
func (el *eventLogger) LogKV(ctx context.Context, alternatingKeyValues ...interface{}) {
span := opentrace.SpanFromContext(ctx)
if span == nil {
Expand All @@ -181,7 +206,6 @@ func (el *eventLogger) LogKV(ctx context.Context, alternatingKeyValues ...interf
span.LogKV(alternatingKeyValues...)
}

// SetTag tags key `k` and value `v` on the span associated with `ctx`
func (el *eventLogger) SetTag(ctx context.Context, k string, v interface{}) {
span := opentrace.SpanFromContext(ctx)
if span == nil {
Expand All @@ -192,12 +216,6 @@ func (el *eventLogger) SetTag(ctx context.Context, k string, v interface{}) {
span.SetTag(k, v)
}

// SetTags tags keys from the `tags` maps on the span associated with `ctx`
// Example:
// log.SetTags(ctx, map[string]{
// "tag": bizStruct,
// "bar": fizStruct,
// })
func (el *eventLogger) SetTags(ctx context.Context, tags map[string]interface{}) {
span := opentrace.SpanFromContext(ctx)
if span == nil {
Expand All @@ -210,8 +228,6 @@ func (el *eventLogger) SetTags(ctx context.Context, tags map[string]interface{})
}
}

// SetErr tags the span associated with `ctx` to reflect an error occured, and
// logs the value `err` under key `error`
func (el *eventLogger) SetErr(ctx context.Context, err error) {
span := opentrace.SpanFromContext(ctx)
if span == nil {
Expand All @@ -227,13 +243,6 @@ func (el *eventLogger) SetErr(ctx context.Context, err error) {
span.LogKV("error", err.Error())
}

// Finish completes the span associated with `ctx` by
// setting the end timestamp and finalizing the Span state.
//
// Finish() must be the last call made to any span instance, and to do
// otherwise leads to undefined behavior.
// Finish will do its best to notify (log) when used in correctly
// .e.g called twice, or called on a spanless `ctx`
func (el *eventLogger) Finish(ctx context.Context) {
span := opentrace.SpanFromContext(ctx)
if span == nil {
Expand All @@ -244,14 +253,6 @@ func (el *eventLogger) Finish(ctx context.Context) {
span.Finish()
}

// FinishWithErr completes the span associated with `ctx` by
// setting the end timestamp and finalizing the Span state, in addition to
// calling the `SetErr` method first
//
// FinishWithErr() must be the last call made to any span instance, and to do
// otherwise leads to undefined behavior.
// FinishWithErr will do its best to notify (log) when used in correctly
// .e.g called twice, or called on a spanless `ctx`
func (el *eventLogger) FinishWithErr(ctx context.Context, err error) {
el.SetErr(ctx, err)
el.Finish(ctx)
Expand Down

0 comments on commit 804754e

Please sign in to comment.