feat(elog) implement event logger

a wrapper around the util.Logger
metadata is loggable

License: MIT
Signed-off-by: Brian Tiger Chow <brian@perfmode.com>

cmd/ipfs2/main.go

@@ -9,6 +9,7 @@ import (
 	"runtime/pprof"
 	"syscall"
 
+	// TODO rm direct reference to go-logging
 	logging "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-logging"
 	ma "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-multiaddr"
 	manet "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-multiaddr/net"
@@ -22,10 +23,11 @@ import (
 	updates "github.com/jbenet/go-ipfs/updates"
 	u "github.com/jbenet/go-ipfs/util"
 	"github.com/jbenet/go-ipfs/util/debugerror"
+	elog "github.com/jbenet/go-ipfs/util/elog"
 )
 
 // log is the command logger
-var log = u.Logger("cmd/ipfs")
+var log = elog.Logger("cmd/ipfs")
 
 // signal to output help
 var errHelpRequested = errors.New("Help Requested")

util/elog/context.go

+package elog
+
+import (
+	"errors"
+
+	"github.com/jbenet/go-ipfs/Godeps/_workspace/src/code.google.com/p/go.net/context"
+)
+
+type key int
+
+const metadataKey key = 0
+
+func ContextWithMetadata(ctx context.Context, l Loggable) context.Context {
+	existing, err := MetadataFromContext(ctx)
+	if err != nil {
+		// context does not contain meta. just set the new metadata
+		child := context.WithValue(ctx, metadataKey, l.Loggable())
+		return child
+	}
+
+	merged := DeepMerge(existing, l.Loggable())
+	child := context.WithValue(ctx, metadataKey, merged)
+	return child
+}
+
+func MetadataFromContext(ctx context.Context) (Metadata, error) {
+	value := ctx.Value(metadataKey)
+	if value != nil {
+		metadata, ok := value.(Metadata)
+		if ok {
+			return metadata, nil
+		}
+	}
+	return nil, errors.New("context contains no metadata")
+}

util/elog/context_test.go

+package elog
+
+import (
+	"testing"
+
+	"github.com/jbenet/go-ipfs/Godeps/_workspace/src/code.google.com/p/go.net/context"
+)
+
+func TestContextContainsMetadata(t *testing.T) {
+	t.Parallel()
+
+	m := Metadata{"foo": "bar"}
+	ctx := ContextWithMetadata(context.Background(), m)
+	got, err := MetadataFromContext(ctx)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	_, exists := got["foo"]
+	if !exists {
+		t.Fail()
+	}
+}
+
+func TestContextWithPreexistingMetadata(t *testing.T) {
+	t.Parallel()
+
+	ctx := ContextWithMetadata(context.Background(), Metadata{"hello": "world"})
+	ctx = ContextWithMetadata(ctx, Metadata{"goodbye": "earth"})
+
+	got, err := MetadataFromContext(ctx)
+	if err != nil {
+		t.Fatal(err)
+	}
+
+	_, exists := got["hello"]
+	if !exists {
+		t.Fatal("original key not present")
+	}
+	_, exists = got["goodbye"]
+	if !exists {
+		t.Fatal("new key not present")
+	}
+}

util/elog/log.go

+package elog
+
+import (
+	"github.com/jbenet/go-ipfs/Godeps/_workspace/src/code.google.com/p/go.net/context"
+	logging "github.com/jbenet/go-ipfs/Godeps/_workspace/src/github.com/jbenet/go-logging"
+	"github.com/jbenet/go-ipfs/util"
+)
+
+var eloggers = map[string]*logging.Logger{}
+
+func init() {
+	SetupLogging()
+}
+
+type EventLogger interface {
+	StandardLogger
+	Event(ctx context.Context, event string, m ...Metadata)
+}
+
+type StandardLogger interface {
+	Critical(args ...interface{})
+	Criticalf(format string, args ...interface{})
+	Debug(args ...interface{})
+	Debugf(format string, args ...interface{})
+	Error(args ...interface{})
+	Errorf(format string, args ...interface{})
+	Fatal(args ...interface{})
+	Fatalf(format string, args ...interface{})
+	Info(args ...interface{})
+	Infof(format string, args ...interface{})
+	Notice(args ...interface{})
+	Noticef(format string, args ...interface{})
+	Panic(args ...interface{})
+	Panicf(format string, args ...interface{})
+	Warning(args ...interface{})
+	Warningf(format string, args ...interface{})
+}
+
+// Logger retrieves a particular event logger
+func Logger(system string) EventLogger {
+	return &eventLogger{util.Logger(system)}
+}
+
+// eventLogger implements the EventLogger and wraps a go-logging Logger
+type eventLogger struct {
+	*logging.Logger
+}
+
+func (el *eventLogger) Event(ctx context.Context, event string, metadata ...Metadata) {
+	existing, err := MetadataFromContext(ctx)
+	if err != nil {
+		existing = Metadata{}
+	}
+	accum := existing
+	for _, datum := range metadata {
+		accum = DeepMerge(accum, datum)
+	}
+	accum["event"] = event
+
+	str, err := accum.JsonString()
+	if err != nil {
+		return
+	}
+	el.Logger.Info(str)
+}
+
+// SetupLogging will initialize the logger backend and set the flags.
+func SetupLogging() {
+	// 	fmt := logging.DefaultFormatter
+
+	// 	f, err := os.Create("events.ipfslog")
+	// 	if err != nil {
+	// 		panic("failed to open file for event logger")
+	// 	}
+}

util/elog/metadata.go

+package elog
+
+import (
+	"encoding/json"
+	"errors"
+	"reflect"
+
+	"github.com/jbenet/go-ipfs/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid"
+)
+
+// Metadata is a convenience type for generic maps
+type Metadata map[string]interface{}
+
+// Loggable describes objects that can be marshalled into Metadata for logging
+type Loggable interface {
+	Loggable() Metadata
+}
+
+// UniqueEvent returns a Metadata with the string key and UUID value
+func UniqueEvent(key string) Metadata {
+	return Metadata{
+		key: uuid.New(),
+	}
+}
+
+// DeepMerge merges the second Metadata parameter into the first.
+// Nested Metadata are merged recursively. Primitives are over-written.
+func DeepMerge(b, a Metadata) Metadata {
+	out := Metadata{}
+	for k, v := range b {
+		out[k] = v
+	}
+	for k, v := range a {
+
+		maybe, err := Metadatify(v)
+		if err != nil {
+			// if the new value is not meta. just overwrite the dest vaue
+			out[k] = v
+			continue
+		}
+
+		// it is meta. What about dest?
+		outv, exists := out[k]
+		if !exists {
+			// the new value is meta, but there's no dest value. just write it
+			out[k] = v
+			continue
+		}
+
+		outMetadataValue, err := Metadatify(outv)
+		if err != nil {
+			// the new value is meta and there's a dest value, but the dest
+			// value isn't meta. just overwrite
+			out[k] = v
+			continue
+		}
+
+		// both are meta. merge them.
+		out[k] = DeepMerge(outMetadataValue, maybe)
+	}
+	return out
+}
+
+// Loggable implements the Loggable interface
+func (m Metadata) Loggable() Metadata {
+	// NB: method defined on value to avoid de-referencing nil Metadata
+	return m
+}
+
+func (m Metadata) JsonString() (string, error) {
+	// NB: method defined on value
+	b, err := json.Marshal(m)
+	return string(b), err
+}
+
+// Metadatify converts maps into Metadata
+func Metadatify(i interface{}) (Metadata, error) {
+	value := reflect.ValueOf(i)
+	if value.Kind() == reflect.Map {
+		m := map[string]interface{}{}
+		for _, k := range value.MapKeys() {
+			m[k.String()] = value.MapIndex(k).Interface()
+		}
+		return Metadata(m), nil
+	}
+	return nil, errors.New("is not a map")
+}

util/elog/metadata_test.go

+package elog
+
+import "testing"
+
+func TestOverwrite(t *testing.T) {
+	t.Parallel()
+
+	under := Metadata{
+		"a": Metadata{
+			"b": Metadata{
+				"c": Metadata{
+					"d":     "the original value",
+					"other": "SURVIVE",
+				},
+			},
+		},
+	}
+	over := Metadata{
+		"a": Metadata{
+			"b": Metadata{
+				"c": Metadata{
+					"d": "a new value",
+				},
+			},
+		},
+	}
+
+	out := DeepMerge(under, over)
+
+	dval := out["a"].(Metadata)["b"].(Metadata)["c"].(Metadata)["d"].(string)
+	if dval != "a new value" {
+		t.Fatal(dval)
+	}
+	surv := out["a"].(Metadata)["b"].(Metadata)["c"].(Metadata)["other"].(string)
+	if surv != "SURVIVE" {
+		t.Fatal(surv)
+	}
+}
+
+func TestMarshalJSON(t *testing.T) {
+	bs, _ := Metadata{"a": "b"}.JsonString()
+	t.Log(bs)
+}
+
+func TestMetadataIsLoggable(t *testing.T) {
+	func(l Loggable) {
+	}(Metadata{})
+}