From 4d91e791c014d8b85601a241d57d60f37537064c Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Thu, 9 Apr 2015 18:45:39 -0700 Subject: [PATCH 1/3] Disassociate instance id from application This moves the instance id out of the app so that it is associated with an instantiation of the runtime. The instance id is stored on the background context. This allows allow contexts using the main background context to include an instance id for log messages. It also simplifies the application slightly. Signed-off-by: Stephen J Day --- cmd/registry/main.go | 23 +++++++++++------------ context/context.go | 27 +++++++++++++++++++++++++-- registry/handlers/app.go | 28 ++++++---------------------- 3 files changed, 42 insertions(+), 36 deletions(-) diff --git a/cmd/registry/main.go b/cmd/registry/main.go index dc2a5326..7ad59ec6 100644 --- a/cmd/registry/main.go +++ b/cmd/registry/main.go @@ -15,7 +15,7 @@ import ( "github.com/Sirupsen/logrus/formatters/logstash" "github.com/bugsnag/bugsnag-go" "github.com/docker/distribution/configuration" - ctxu "github.com/docker/distribution/context" + "github.com/docker/distribution/context" _ "github.com/docker/distribution/health" _ "github.com/docker/distribution/registry/auth/silly" _ "github.com/docker/distribution/registry/auth/token" @@ -28,7 +28,6 @@ import ( "github.com/docker/distribution/version" gorhandlers "github.com/gorilla/handlers" "github.com/yvasiyarov/gorelic" - "golang.org/x/net/context" ) var showVersion bool @@ -67,9 +66,9 @@ func main() { } if config.HTTP.TLS.Certificate == "" { - ctxu.GetLogger(app).Infof("listening on %v", config.HTTP.Addr) + context.GetLogger(app).Infof("listening on %v", config.HTTP.Addr) if err := http.ListenAndServe(config.HTTP.Addr, handler); err != nil { - ctxu.GetLogger(app).Fatalln(err) + context.GetLogger(app).Fatalln(err) } } else { tlsConf := &tls.Config{ @@ -82,23 +81,23 @@ func main() { for _, ca := range config.HTTP.TLS.ClientCAs { caPem, err := ioutil.ReadFile(ca) if err != nil { - ctxu.GetLogger(app).Fatalln(err) + context.GetLogger(app).Fatalln(err) } if ok := pool.AppendCertsFromPEM(caPem); !ok { - ctxu.GetLogger(app).Fatalln(fmt.Errorf("Could not add CA to pool")) + context.GetLogger(app).Fatalln(fmt.Errorf("Could not add CA to pool")) } } for _, subj := range pool.Subjects() { - ctxu.GetLogger(app).Debugf("CA Subject: %s", string(subj)) + context.GetLogger(app).Debugf("CA Subject: %s", string(subj)) } tlsConf.ClientAuth = tls.RequireAndVerifyClientCert tlsConf.ClientCAs = pool } - ctxu.GetLogger(app).Infof("listening on %v, tls", config.HTTP.Addr) + context.GetLogger(app).Infof("listening on %v, tls", config.HTTP.Addr) server := &http.Server{ Addr: config.HTTP.Addr, Handler: handler, @@ -106,7 +105,7 @@ func main() { } if err := server.ListenAndServeTLS(config.HTTP.TLS.Certificate, config.HTTP.TLS.Key); err != nil { - ctxu.GetLogger(app).Fatalln(err) + context.GetLogger(app).Fatalln(err) } } } @@ -190,7 +189,7 @@ func configureLogging(ctx context.Context, config *configuration.Configuration) if config.Log.Level == "" && config.Log.Formatter == "" { // If no config for logging is set, fallback to deprecated "Loglevel". log.SetLevel(logLevel(config.Loglevel)) - ctx = ctxu.WithLogger(ctx, ctxu.GetLogger(ctx, "version")) + ctx = context.WithLogger(ctx, context.GetLogger(ctx, "version")) return ctx, nil } @@ -224,8 +223,8 @@ func configureLogging(ctx context.Context, config *configuration.Configuration) fields = append(fields, k) } - ctx = ctxu.WithValues(ctx, config.Log.Fields) - ctx = ctxu.WithLogger(ctx, ctxu.GetLogger(ctx, fields...)) + ctx = context.WithValues(ctx, config.Log.Fields) + ctx = context.WithLogger(ctx, context.GetLogger(ctx, fields...)) } return ctx, nil diff --git a/context/context.go b/context/context.go index 296d9ac3..45a35ad1 100644 --- a/context/context.go +++ b/context/context.go @@ -1,6 +1,7 @@ package context import ( + "code.google.com/p/go-uuid/uuid" "golang.org/x/net/context" ) @@ -9,9 +10,31 @@ type Context interface { context.Context } -// Background returns a non-nil, empty Context. +// instanceContext is a context that provides only an instance id. It is +// provided as the main background context. +type instanceContext struct { + Context + id string // id of context, logged as "instance.id" +} + +func (ic *instanceContext) Value(key interface{}) interface{} { + if key == "instance.id" { + return ic.id + } + + return ic.Context.Value(key) +} + +var background = &instanceContext{ + Context: context.Background(), + id: uuid.New(), +} + +// Background returns a non-nil, empty Context. The background context +// provides a single key, "instance.id" that is globally unique to the +// process. func Background() Context { - return context.Background() + return background } // WithValue returns a copy of parent in which the value associated with key is diff --git a/registry/handlers/app.go b/registry/handlers/app.go index fac93382..059af260 100644 --- a/registry/handlers/app.go +++ b/registry/handlers/app.go @@ -8,7 +8,6 @@ import ( "os" "time" - "code.google.com/p/go-uuid/uuid" "github.com/docker/distribution" "github.com/docker/distribution/configuration" ctxu "github.com/docker/distribution/context" @@ -32,11 +31,8 @@ import ( // fields should be protected. type App struct { context.Context - Config configuration.Configuration - // InstanceID is a unique id assigned to the application on each creation. - // Provides information in the logs and context to identify restarts. - InstanceID string + Config configuration.Configuration router *mux.Router // main application router, configured with dispatchers driver storagedriver.StorageDriver // driver maintains the app global storage driver instance. @@ -52,29 +48,17 @@ type App struct { redis *redis.Pool } -// Value intercepts calls context.Context.Value, returning the current app id, -// if requested. -func (app *App) Value(key interface{}) interface{} { - switch key { - case "app.id": - return app.InstanceID - } - - return app.Context.Value(key) -} - // NewApp takes a configuration and returns a configured app, ready to serve // requests. The app only implements ServeHTTP and can be wrapped in other // handlers accordingly. func NewApp(ctx context.Context, configuration configuration.Configuration) *App { app := &App{ - Config: configuration, - Context: ctx, - InstanceID: uuid.New(), - router: v2.RouterWithPrefix(configuration.HTTP.Prefix), + Config: configuration, + Context: ctx, + router: v2.RouterWithPrefix(configuration.HTTP.Prefix), } - app.Context = ctxu.WithLogger(app.Context, ctxu.GetLogger(app, "app.id")) + app.Context = ctxu.WithLogger(app.Context, ctxu.GetLogger(app, "instance.id")) // Register the handler dispatchers. app.register(v2.RouteNameBase, func(ctx *Context, r *http.Request) http.Handler { @@ -200,7 +184,7 @@ func (app *App) configureEvents(configuration *configuration.Configuration) { app.events.source = notifications.SourceRecord{ Addr: hostname, - InstanceID: app.InstanceID, + InstanceID: ctxu.GetStringValue(app, "instance.id"), } } From d8ac79f6436de368fc31360e000c28421239f692 Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Thu, 9 Apr 2015 18:48:05 -0700 Subject: [PATCH 2/3] Contextual tracing support for logs This adds WithTrace function to the context package that allows users to trace a time span between a trace allocation and returned function call. The resulting context includes ids that will allow for future dapper-like analysis. Please see the godoc addition for details. Signed-off-by: Stephen J Day --- context/trace.go | 99 +++++++++++++++++++++++++++++++++++++++++++ context/trace_test.go | 85 +++++++++++++++++++++++++++++++++++++ 2 files changed, 184 insertions(+) create mode 100644 context/trace.go create mode 100644 context/trace_test.go diff --git a/context/trace.go b/context/trace.go new file mode 100644 index 00000000..1115fc1f --- /dev/null +++ b/context/trace.go @@ -0,0 +1,99 @@ +package context + +import ( + "runtime" + "time" + + "code.google.com/p/go-uuid/uuid" +) + +// WithTrace allocates a traced timing span in a new context. This allows a +// caller to track the time between calling WithTrace and the returned done +// function. When the done function is called, a log message is emitted with a +// "trace.duration" field, corresponding to the elapased time and a +// "trace.func" field, corresponding to the function that called WithTrace. +// +// The logging keys "trace.id" and "trace.parent.id" are provided to implement +// dapper-like tracing. This function should be complemented with a WithSpan +// method that could be used for tracing distributed RPC calls. +// +// The main benefit of this function is to post-process log messages or +// intercept them in a hook to provide timing data. Trace ids and parent ids +// can also be linked to provide call tracing, if so required. +// +// Here is an example of the usage: +// +// func timedOperation(ctx Context) { +// ctx, done := WithTrace(ctx) +// defer done("this will be the log message") +// // ... function body ... +// } +// +// If the function ran for roughly 1s, such a usage would emit a log message +// as follows: +// +// INFO[0001] this will be the log message trace.duration=1.004575763s trace.func=github.com/docker/distribution/context.traceOperation trace.id= ... +// +// Notice that the function name is automatically resolved, along with the +// package and a trace id is emitted that can be linked with parent ids. +func WithTrace(ctx Context) (Context, func(format string, a ...interface{})) { + if ctx == nil { + ctx = Background() + } + + pc, file, line, _ := runtime.Caller(1) + f := runtime.FuncForPC(pc) + ctx = &traced{ + Context: ctx, + id: uuid.New(), + start: time.Now(), + parent: GetStringValue(ctx, "trace.id"), + fnname: f.Name(), + file: file, + line: line, + } + + return ctx, func(format string, a ...interface{}) { + GetLogger(ctx, "trace.duration", "trace.id", "trace.parent.id", + "trace.func", "trace.file", "trace.line"). + Infof(format, a...) // info may be too chatty. + } +} + +// traced represents a context that is traced for function call timing. It +// also provides fast lookup for the various attributes that are available on +// the trace. +type traced struct { + Context + id string + parent string + start time.Time + fnname string + file string + line int +} + +func (ts *traced) Value(key interface{}) interface{} { + switch key { + case "trace.start": + return ts.start + case "trace.duration": + return time.Since(ts.start) + case "trace.id": + return ts.id + case "trace.parent.id": + if ts.parent == "" { + return nil // must return nil to signal no parent. + } + + return ts.parent + case "trace.func": + return ts.fnname + case "trace.file": + return ts.file + case "trace.line": + return ts.line + } + + return ts.Context.Value(key) +} diff --git a/context/trace_test.go b/context/trace_test.go new file mode 100644 index 00000000..4b969fbb --- /dev/null +++ b/context/trace_test.go @@ -0,0 +1,85 @@ +package context + +import ( + "runtime" + "testing" + "time" +) + +// TestWithTrace ensures that tracing has the expected values in the context. +func TestWithTrace(t *testing.T) { + pc, file, _, _ := runtime.Caller(0) // get current caller. + f := runtime.FuncForPC(pc) + + base := []valueTestCase{ + { + key: "trace.id", + notnilorempty: true, + }, + + { + key: "trace.file", + expected: file, + notnilorempty: true, + }, + { + key: "trace.line", + notnilorempty: true, + }, + { + key: "trace.start", + notnilorempty: true, + }, + } + + ctx, done := WithTrace(Background()) + defer done("this will be emitted at end of test") + + checkContextForValues(t, ctx, append(base, valueTestCase{ + key: "trace.func", + expected: f.Name(), + })) + + traced := func() { + parentID := ctx.Value("trace.id") // ensure the parent trace id is correct. + + pc, _, _, _ := runtime.Caller(0) // get current caller. + f := runtime.FuncForPC(pc) + ctx, done := WithTrace(ctx) + defer done("this should be subordinate to the other trace") + time.Sleep(time.Second) + checkContextForValues(t, ctx, append(base, valueTestCase{ + key: "trace.func", + expected: f.Name(), + }, valueTestCase{ + key: "trace.parent.id", + expected: parentID, + })) + } + traced() + + time.Sleep(time.Second) +} + +type valueTestCase struct { + key string + expected interface{} + notnilorempty bool // just check not empty/not nil +} + +func checkContextForValues(t *testing.T, ctx Context, values []valueTestCase) { + + for _, testcase := range values { + v := ctx.Value(testcase.key) + if testcase.notnilorempty { + if v == nil || v == "" { + t.Fatalf("value was nil or empty for %q: %#v", testcase.key, v) + } + continue + } + + if v != testcase.expected { + t.Fatalf("unexpected value for key %q: %v != %v", testcase.key, v, testcase.expected) + } + } +} From 730ce83cdf266b618861e0830476e67fb2ea694f Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Thu, 9 Apr 2015 18:50:57 -0700 Subject: [PATCH 3/3] Trace function calls to Base storage driver Signed-off-by: Stephen J Day --- registry/storage/driver/base/base.go | 28 ++++++++++++++++++++++++++++ 1 file changed, 28 insertions(+) diff --git a/registry/storage/driver/base/base.go b/registry/storage/driver/base/base.go index 0365ba3c..ba7a859d 100644 --- a/registry/storage/driver/base/base.go +++ b/registry/storage/driver/base/base.go @@ -40,6 +40,7 @@ package base import ( "io" + "github.com/docker/distribution/context" storagedriver "github.com/docker/distribution/registry/storage/driver" ) @@ -51,6 +52,9 @@ type Base struct { // GetContent wraps GetContent of underlying storage driver. func (base *Base) GetContent(path string) ([]byte, error) { + _, done := context.WithTrace(context.Background()) + defer done("Base.GetContent") + if !storagedriver.PathRegexp.MatchString(path) { return nil, storagedriver.InvalidPathError{Path: path} } @@ -60,6 +64,9 @@ func (base *Base) GetContent(path string) ([]byte, error) { // PutContent wraps PutContent of underlying storage driver. func (base *Base) PutContent(path string, content []byte) error { + _, done := context.WithTrace(context.Background()) + defer done("Base.PutContent") + if !storagedriver.PathRegexp.MatchString(path) { return storagedriver.InvalidPathError{Path: path} } @@ -69,6 +76,9 @@ func (base *Base) PutContent(path string, content []byte) error { // ReadStream wraps ReadStream of underlying storage driver. func (base *Base) ReadStream(path string, offset int64) (io.ReadCloser, error) { + _, done := context.WithTrace(context.Background()) + defer done("Base.ReadStream") + if offset < 0 { return nil, storagedriver.InvalidOffsetError{Path: path, Offset: offset} } @@ -82,6 +92,9 @@ func (base *Base) ReadStream(path string, offset int64) (io.ReadCloser, error) { // WriteStream wraps WriteStream of underlying storage driver. func (base *Base) WriteStream(path string, offset int64, reader io.Reader) (nn int64, err error) { + _, done := context.WithTrace(context.Background()) + defer done("Base.WriteStream") + if offset < 0 { return 0, storagedriver.InvalidOffsetError{Path: path, Offset: offset} } @@ -95,6 +108,9 @@ func (base *Base) WriteStream(path string, offset int64, reader io.Reader) (nn i // Stat wraps Stat of underlying storage driver. func (base *Base) Stat(path string) (storagedriver.FileInfo, error) { + _, done := context.WithTrace(context.Background()) + defer done("Base.Stat") + if !storagedriver.PathRegexp.MatchString(path) { return nil, storagedriver.InvalidPathError{Path: path} } @@ -104,6 +120,9 @@ func (base *Base) Stat(path string) (storagedriver.FileInfo, error) { // List wraps List of underlying storage driver. func (base *Base) List(path string) ([]string, error) { + _, done := context.WithTrace(context.Background()) + defer done("Base.List") + if !storagedriver.PathRegexp.MatchString(path) && path != "/" { return nil, storagedriver.InvalidPathError{Path: path} } @@ -113,6 +132,9 @@ func (base *Base) List(path string) ([]string, error) { // Move wraps Move of underlying storage driver. func (base *Base) Move(sourcePath string, destPath string) error { + _, done := context.WithTrace(context.Background()) + defer done("Base.Move") + if !storagedriver.PathRegexp.MatchString(sourcePath) { return storagedriver.InvalidPathError{Path: sourcePath} } else if !storagedriver.PathRegexp.MatchString(destPath) { @@ -124,6 +146,9 @@ func (base *Base) Move(sourcePath string, destPath string) error { // Delete wraps Delete of underlying storage driver. func (base *Base) Delete(path string) error { + _, done := context.WithTrace(context.Background()) + defer done("Base.Move") + if !storagedriver.PathRegexp.MatchString(path) { return storagedriver.InvalidPathError{Path: path} } @@ -133,6 +158,9 @@ func (base *Base) Delete(path string) error { // URLFor wraps URLFor of underlying storage driver. func (base *Base) URLFor(path string, options map[string]interface{}) (string, error) { + _, done := context.WithTrace(context.Background()) + defer done("Base.URLFor") + if !storagedriver.PathRegexp.MatchString(path) { return "", storagedriver.InvalidPathError{Path: path} }