Integrate contextual logging with regsitry app

This changeset integrates contextual logging into the registry web application.
Idiomatic context use is attempted within the current webapp layout. The
functionality is centered around making lifecycle objects (application and
request context) into contexts themselves. Relevant data has been moved into
the context where appropriate.  We still have some work to do to factor out the
registry.Context object and the dispatching functionality to remove some
awkward portions.

The api tests were slightly refactored to use a test environment to eliminate
common code.

Signed-off-by: Stephen J Day <stephen.day@docker.com>

cmd/registry/main.go

@@ -10,17 +10,18 @@ import (
 
 	log "github.com/Sirupsen/logrus"
 	"github.com/bugsnag/bugsnag-go"
-	"github.com/gorilla/handlers"
-	"github.com/yvasiyarov/gorelic"
-
 	_ "github.com/docker/distribution/auth/silly"
 	_ "github.com/docker/distribution/auth/token"
 	"github.com/docker/distribution/configuration"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/registry"
 	_ "github.com/docker/distribution/storagedriver/filesystem"
 	_ "github.com/docker/distribution/storagedriver/inmemory"
 	_ "github.com/docker/distribution/storagedriver/s3"
 	"github.com/docker/distribution/version"
+	"github.com/gorilla/handlers"
+	"github.com/yvasiyarov/gorelic"
+	"golang.org/x/net/context"
 )
 
 var showVersion bool
@@ -38,29 +39,34 @@ func main() {
 		return
 	}
 
+	ctx := context.Background()
+
 	config, err := resolveConfiguration()
 	if err != nil {
 		fatalf("configuration error: %v", err)
 	}
 
-	app := registry.NewApp(*config)
+	log.SetLevel(logLevel(config.Loglevel))
+	ctx = context.WithValue(ctx, "version", version.Version)
+	ctx = ctxu.WithLogger(ctx, ctxu.GetLogger(ctx, "version"))
+
+	app := registry.NewApp(ctx, *config)
 	handler := configureReporting(app)
 	handler = handlers.CombinedLoggingHandler(os.Stdout, handler)
-	log.SetLevel(logLevel(config.Loglevel))
 
 	if config.HTTP.Debug.Addr != "" {
 		go debugServer(config.HTTP.Debug.Addr)
 	}
 
 	if config.HTTP.TLS.Certificate == "" {
-		log.Infof("listening on %v", config.HTTP.Addr)
+		ctxu.GetLogger(app).Infof("listening on %v", config.HTTP.Addr)
 		if err := http.ListenAndServe(config.HTTP.Addr, handler); err != nil {
-			log.Fatalln(err)
+			ctxu.GetLogger(app).Fatalln(err)
 		}
 	} else {
-		log.Infof("listening on %v, tls", config.HTTP.Addr)
+		ctxu.GetLogger(app).Infof("listening on %v, tls", config.HTTP.Addr)
 		if err := http.ListenAndServeTLS(config.HTTP.Addr, config.HTTP.TLS.Certificate, config.HTTP.TLS.Key, handler); err != nil {
-			log.Fatalln(err)
+			ctxu.GetLogger(app).Fatalln(err)
 		}
 	}
 }

registry/api_test.go

@@ -22,26 +22,15 @@ import (
 	"github.com/docker/distribution/testutil"
 	"github.com/docker/libtrust"
 	"github.com/gorilla/handlers"
+	"golang.org/x/net/context"
 )
 
 // TestCheckAPI hits the base endpoint (/v2/) ensures we return the specified
 // 200 OK response.
 func TestCheckAPI(t *testing.T) {
-	config := configuration.Configuration{
+	env := newTestEnv(t)
-		Storage: configuration.Storage{
-			"inmemory": configuration.Parameters{},
-		},
-	}
 
-	app := NewApp(config)
+	baseURL, err := env.builder.BuildBaseURL()
-	server := httptest.NewServer(handlers.CombinedLoggingHandler(os.Stderr, app))
-	builder, err := v2.NewURLBuilderFromString(server.URL)
-
-	if err != nil {
-		t.Fatalf("error creating url builder: %v", err)
-	}
-
-	baseURL, err := builder.BuildBaseURL()
 	if err != nil {
 		t.Fatalf("unexpected error building base url: %v", err)
 	}
@@ -73,20 +62,7 @@ func TestLayerAPI(t *testing.T) {
 	// TODO(stevvooe): This test code is complete junk but it should cover the
 	// complete flow. This must be broken down and checked against the
 	// specification *before* we submit the final to docker core.
-
+	env := newTestEnv(t)
-	config := configuration.Configuration{
-		Storage: configuration.Storage{
-			"inmemory": configuration.Parameters{},
-		},
-	}
-
-	app := NewApp(config)
-	server := httptest.NewServer(handlers.CombinedLoggingHandler(os.Stderr, app))
-	builder, err := v2.NewURLBuilderFromString(server.URL)
-
-	if err != nil {
-		t.Fatalf("error creating url builder: %v", err)
-	}
 
 	imageName := "foo/bar"
 	// "build" our layer file
@@ -99,7 +75,7 @@ func TestLayerAPI(t *testing.T) {
 
 	// -----------------------------------
 	// Test fetch for non-existent content
-	layerURL, err := builder.BuildBlobURL(imageName, layerDigest)
+	layerURL, err := env.builder.BuildBlobURL(imageName, layerDigest)
 	if err != nil {
 		t.Fatalf("error building url: %v", err)
 	}
@@ -122,7 +98,7 @@ func TestLayerAPI(t *testing.T) {
 
 	// ------------------------------------------
 	// Start an upload and cancel
-	uploadURLBase := startPushLayer(t, builder, imageName)
+	uploadURLBase := startPushLayer(t, env.builder, imageName)
 
 	req, err := http.NewRequest("DELETE", uploadURLBase, nil)
 	if err != nil {
@@ -145,8 +121,8 @@ func TestLayerAPI(t *testing.T) {
 
 	// -----------------------------------------
 	// Do layer push with an empty body and different digest
-	uploadURLBase = startPushLayer(t, builder, imageName)
+	uploadURLBase = startPushLayer(t, env.builder, imageName)
-	resp, err = doPushLayer(t, builder, imageName, layerDigest, uploadURLBase, bytes.NewReader([]byte{}))
+	resp, err = doPushLayer(t, env.builder, imageName, layerDigest, uploadURLBase, bytes.NewReader([]byte{}))
 	if err != nil {
 		t.Fatalf("unexpected error doing bad layer push: %v", err)
 	}
@@ -161,8 +137,8 @@ func TestLayerAPI(t *testing.T) {
 		t.Fatalf("unexpected error digesting empty buffer: %v", err)
 	}
 
-	uploadURLBase = startPushLayer(t, builder, imageName)
+	uploadURLBase = startPushLayer(t, env.builder, imageName)
-	pushLayer(t, builder, imageName, zeroDigest, uploadURLBase, bytes.NewReader([]byte{}))
+	pushLayer(t, env.builder, imageName, zeroDigest, uploadURLBase, bytes.NewReader([]byte{}))
 
 	// -----------------------------------------
 	// Do layer push with an empty body and correct digest
@@ -174,16 +150,16 @@ func TestLayerAPI(t *testing.T) {
 		t.Fatalf("unexpected error digesting empty tar: %v", err)
 	}
 
-	uploadURLBase = startPushLayer(t, builder, imageName)
+	uploadURLBase = startPushLayer(t, env.builder, imageName)
-	pushLayer(t, builder, imageName, emptyDigest, uploadURLBase, bytes.NewReader(emptyTar))
+	pushLayer(t, env.builder, imageName, emptyDigest, uploadURLBase, bytes.NewReader(emptyTar))
 
 	// ------------------------------------------
 	// Now, actually do successful upload.
 	layerLength, _ := layerFile.Seek(0, os.SEEK_END)
 	layerFile.Seek(0, os.SEEK_SET)
 
-	uploadURLBase = startPushLayer(t, builder, imageName)
+	uploadURLBase = startPushLayer(t, env.builder, imageName)
-	pushLayer(t, builder, imageName, layerDigest, uploadURLBase, layerFile)
+	pushLayer(t, env.builder, imageName, layerDigest, uploadURLBase, layerFile)
 
 	// ------------------------
 	// Use a head request to see if the layer exists.
@@ -223,28 +199,12 @@ func TestLayerAPI(t *testing.T) {
 }
 
 func TestManifestAPI(t *testing.T) {
-	pk, err := libtrust.GenerateECP256PrivateKey()
+	env := newTestEnv(t)
-	if err != nil {
-		t.Fatalf("unexpected error generating private key: %v", err)
-	}
-
-	config := configuration.Configuration{
-		Storage: configuration.Storage{
-			"inmemory": configuration.Parameters{},
-		},
-	}
-
-	app := NewApp(config)
-	server := httptest.NewServer(handlers.CombinedLoggingHandler(os.Stderr, app))
-	builder, err := v2.NewURLBuilderFromString(server.URL)
-	if err != nil {
-		t.Fatalf("unexpected error creating url builder: %v", err)
-	}
 
 	imageName := "foo/bar"
 	tag := "thetag"
 
-	manifestURL, err := builder.BuildManifestURL(imageName, tag)
+	manifestURL, err := env.builder.BuildManifestURL(imageName, tag)
 	if err != nil {
 		t.Fatalf("unexpected error getting manifest url: %v", err)
 	}
@@ -260,7 +220,7 @@ func TestManifestAPI(t *testing.T) {
 	checkResponse(t, "getting non-existent manifest", resp, http.StatusNotFound)
 	checkBodyHasErrorCodes(t, "getting non-existent manifest", resp, v2.ErrorCodeManifestUnknown)
 
-	tagsURL, err := builder.BuildTagsURL(imageName)
+	tagsURL, err := env.builder.BuildTagsURL(imageName)
 	if err != nil {
 		t.Fatalf("unexpected error building tags url: %v", err)
 	}
@@ -324,13 +284,13 @@ func TestManifestAPI(t *testing.T) {
 		expectedLayers[dgst] = rs
 		unsignedManifest.FSLayers[i].BlobSum = dgst
 
-		uploadURLBase := startPushLayer(t, builder, imageName)
+		uploadURLBase := startPushLayer(t, env.builder, imageName)
-		pushLayer(t, builder, imageName, dgst, uploadURLBase, rs)
+		pushLayer(t, env.builder, imageName, dgst, uploadURLBase, rs)
 	}
 
 	// -------------------
 	// Push the signed manifest with all layers pushed.
-	signedManifest, err := manifest.Sign(unsignedManifest, pk)
+	signedManifest, err := manifest.Sign(unsignedManifest, env.pk)
 	if err != nil {
 		t.Fatalf("unexpected error signing manifest: %v", err)
 	}
@@ -386,6 +346,46 @@ func TestManifestAPI(t *testing.T) {
 	}
 }
 
+type testEnv struct {
+	pk      libtrust.PrivateKey
+	ctx     context.Context
+	config  configuration.Configuration
+	app     *App
+	server  *httptest.Server
+	builder *v2.URLBuilder
+}
+
+func newTestEnv(t *testing.T) *testEnv {
+	ctx := context.Background()
+	config := configuration.Configuration{
+		Storage: configuration.Storage{
+			"inmemory": configuration.Parameters{},
+		},
+	}
+
+	app := NewApp(ctx, config)
+	server := httptest.NewServer(handlers.CombinedLoggingHandler(os.Stderr, app))
+	builder, err := v2.NewURLBuilderFromString(server.URL)
+
+	if err != nil {
+		t.Fatalf("error creating url builder: %v", err)
+	}
+
+	pk, err := libtrust.GenerateECP256PrivateKey()
+	if err != nil {
+		t.Fatalf("unexpected error generating private key: %v", err)
+	}
+
+	return &testEnv{
+		pk:      pk,
+		ctx:     ctx,
+		config:  config,
+		app:     app,
+		server:  server,
+		builder: builder,
+	}
+}
+
 func putManifest(t *testing.T, msg, url string, v interface{}) *http.Response {
 	var body []byte
 	if sm, ok := v.(*manifest.SignedManifest); ok {

registry/app.go

@@ -7,10 +7,10 @@ import (
 	"os"
 
 	"code.google.com/p/go-uuid/uuid"
-	log "github.com/Sirupsen/logrus"
 	"github.com/docker/distribution/api/v2"
 	"github.com/docker/distribution/auth"
 	"github.com/docker/distribution/configuration"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/storage"
 	"github.com/docker/distribution/storage/notifications"
 	"github.com/docker/distribution/storagedriver"
@@ -23,6 +23,7 @@ import (
 // on this object that will be accessible from all requests. Any writable
 // fields should be protected.
 type App struct {
+	context.Context
 	Config configuration.Configuration
 
 	// InstanceID is a unique id assigned to the application on each creation.
@@ -43,16 +44,30 @@ type App struct {
 	layerHandler storage.LayerHandler // allows dispatch of layer serving to external provider
 }
 
+// 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(configuration configuration.Configuration) *App {
+func NewApp(ctx context.Context, configuration configuration.Configuration) *App {
 	app := &App{
 		Config:     configuration,
+		Context:    ctx,
 		InstanceID: uuid.New(),
 		router:     v2.Router(),
 	}
 
+	app.Context = ctxu.WithLogger(app.Context, ctxu.GetLogger(app, "app.id"))
+
 	// Register the handler dispatchers.
 	app.register(v2.RouteNameBase, func(ctx *Context, r *http.Request) http.Handler {
 		return http.HandlerFunc(apiBase)
@@ -118,11 +133,11 @@ func (app *App) configureEvents(configuration *configuration.Configuration) {
 	var sinks []notifications.Sink
 	for _, endpoint := range configuration.Notifications.Endpoints {
 		if endpoint.Disabled {
-			log.Infof("endpoint %s disabled, skipping", endpoint.Name)
+			ctxu.GetLogger(app).Infof("endpoint %s disabled, skipping", endpoint.Name)
 			continue
 		}
 
-		log.Infof("configuring endpoint %v (%v), timeout=%s, headers=%v", endpoint.Name, endpoint.URL, endpoint.Timeout, endpoint.Headers)
+		ctxu.GetLogger(app).Infof("configuring endpoint %v (%v), timeout=%s, headers=%v", endpoint.Name, endpoint.URL, endpoint.Timeout, endpoint.Headers)
 		endpoint := notifications.NewEndpoint(endpoint.Name, endpoint.URL, notifications.EndpointConfig{
 			Timeout:   endpoint.Timeout,
 			Threshold: endpoint.Threshold,
@@ -190,27 +205,29 @@ func (ssrw *singleStatusResponseWriter) WriteHeader(status int) {
 	ssrw.ResponseWriter.WriteHeader(status)
 }
 
-// WithRequest adds an http request to the given context and requents
+func (ssrw *singleStatusResponseWriter) Flush() {
-// a new context with an "http.request" value.
+	if flusher, ok := ssrw.ResponseWriter.(http.Flusher); ok {
-func WithRequest(ctx context.Context, r *http.Request) context.Context {
+		flusher.Flush()
-	return context.WithValue(ctx, "http.request", r)
+	}
 }
 
 // dispatcher returns a handler that constructs a request specific context and
 // handler, using the dispatch factory function.
 func (app *App) dispatcher(dispatch dispatchFunc) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		context := app.context(r)
+		context := app.context(w, r)
 
-		if err := app.authorized(w, r, context, context.vars["name"]); err != nil {
+		defer func() {
+			ctxu.GetResponseLogger(context).Infof("response completed")
+		}()
+
+		if err := app.authorized(w, r, context); err != nil {
 			return
 		}
 
 		// decorate the authorized repository with an event bridge.
 		context.Repository = notifications.Listen(
 			context.Repository, app.eventBridge(context, r))
-
-		context.log = log.WithField("name", context.Repository.Name())
 		handler := dispatch(context, r)
 
 		ssrw := &singleStatusResponseWriter{ResponseWriter: w}
@@ -230,24 +247,34 @@ func (app *App) dispatcher(dispatch dispatchFunc) http.Handler {
 
 // context constructs the context object for the application. This only be
 // called once per request.
-func (app *App) context(r *http.Request) *Context {
+func (app *App) context(w http.ResponseWriter, r *http.Request) *Context {
-	vars := mux.Vars(r)
+	ctx := ctxu.WithRequest(app, r)
+	ctx, w = ctxu.WithResponseWriter(ctx, w)
+	ctx = ctxu.WithVars(ctx, r)
+	ctx = ctxu.WithLogger(ctx, ctxu.GetRequestLogger(ctx))
+	ctx = ctxu.WithLogger(ctx, ctxu.GetLogger(ctx,
+		"vars.name",
+		"vars.tag",
+		"vars.digest",
+		"vars.tag",
+		"vars.uuid"))
+
 	context := &Context{
 		App:        app,
-		RequestID:  uuid.New(),
+		Context:    ctx,
 		urlBuilder: v2.NewURLBuilderFromRequest(r),
 	}
 
-	// Store vars for underlying handlers.
-	context.vars = vars
-
 	return context
 }
 
 // authorized checks if the request can proceed with access to the requested
 // repository. If it succeeds, the repository will be available on the
 // context. An error will be if access is not available.
-func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Context, repo string) error {
+func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Context) error {
+	ctxu.GetLogger(context).Debug("authorizing request")
+	repo := getName(context)
+
 	if app.accessController == nil {
 		// No access controller, so we simply provide access.
 		context.Repository = app.registry.Repository(repo)
@@ -308,7 +335,7 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont
 		}
 	}
 
-	authCtx, err := app.accessController.Authorized(WithRequest(nil, r), accessRecords...)
+	ctx, err := app.accessController.Authorized(context.Context, accessRecords...)
 	if err != nil {
 		switch err := err.(type) {
 		case auth.Challenge:
@@ -323,16 +350,14 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont
 			// the configuration or whatever is backing the access
 			// controller. Just return a bad request with no information
 			// to avoid exposure. The request should not proceed.
-			context.log.Errorf("error checking authorization: %v", err)
+			ctxu.GetLogger(context).Errorf("error checking authorization: %v", err)
 			w.WriteHeader(http.StatusBadRequest)
 		}
 
 		return err
 	}
 
-	// The authorized context should contain an auth.UserInfo
+	context.Context = ctx
-	// object. If it doesn't, just use the zero value for now.
-	context.AuthUserInfo, _ = authCtx.Value("auth.user").(auth.UserInfo)
 
 	// At this point, the request should have access to the repository under
 	// the requested operation. Make is available on the context.
@@ -345,9 +370,9 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont
 // correct actor and source.
 func (app *App) eventBridge(ctx *Context, r *http.Request) notifications.Listener {
 	actor := notifications.ActorRecord{
-		Name: ctx.AuthUserInfo.Name,
+		Name: getUserName(ctx, r),
 	}
-	request := notifications.NewRequestRecord(ctx.RequestID, r)
+	request := notifications.NewRequestRecord(ctxu.GetRequestID(ctx), r)
 
 	return notifications.NewBridge(ctx.urlBuilder, app.events.source, actor, request, app.events.sink)
 }

registry/app_test.go

@@ -12,6 +12,7 @@ import (
 	"github.com/docker/distribution/configuration"
 	"github.com/docker/distribution/storage"
 	"github.com/docker/distribution/storagedriver/inmemory"
+	"golang.org/x/net/context"
 )
 
 // TestAppDispatcher builds an application with a test dispatcher and ensures
@@ -22,6 +23,7 @@ func TestAppDispatcher(t *testing.T) {
 	driver := inmemory.New()
 	app := &App{
 		Config:   configuration.Configuration{},
+		Context:  context.Background(),
 		router:   v2.Router(),
 		driver:   driver,
 		registry: storage.NewRegistryWithDriver(driver),
@@ -37,19 +39,19 @@ func TestAppDispatcher(t *testing.T) {
 	varCheckingDispatcher := func(expectedVars map[string]string) dispatchFunc {
 		return func(ctx *Context, r *http.Request) http.Handler {
 			// Always checks the same name context
-			if ctx.Repository.Name() != ctx.vars["name"] {
+			if ctx.Repository.Name() != getName(ctx) {
 				t.Fatalf("unexpected name: %q != %q", ctx.Repository.Name(), "foo/bar")
 			}
 
 			// Check that we have all that is expected
 			for expectedK, expectedV := range expectedVars {
-				if ctx.vars[expectedK] != expectedV {
+				if ctx.Value(expectedK) != expectedV {
-					t.Fatalf("unexpected %s in context vars: %q != %q", expectedK, ctx.vars[expectedK], expectedV)
+					t.Fatalf("unexpected %s in context vars: %q != %q", expectedK, ctx.Value(expectedK), expectedV)
 				}
 			}
 
 			// Check that we only have variables that are expected
-			for k, v := range ctx.vars {
+			for k, v := range ctx.Value("vars").(map[string]string) {
 				_, ok := expectedVars[k]
 
 				if !ok { // name is checked on context
@@ -135,6 +137,7 @@ func TestAppDispatcher(t *testing.T) {
 // TestNewApp covers the creation of an application via NewApp with a
 // configuration.
 func TestNewApp(t *testing.T) {
+	ctx := context.Background()
 	config := configuration.Configuration{
 		Storage: configuration.Storage{
 			"inmemory": nil,
@@ -152,7 +155,7 @@ func TestNewApp(t *testing.T) {
 	// Mostly, with this test, given a sane configuration, we are simply
 	// ensuring that NewApp doesn't panic. We might want to tweak this
 	// behavior.
-	app := NewApp(config)
+	app := NewApp(ctx, config)
 
 	server := httptest.NewServer(app)
 	builder, err := v2.NewURLBuilderFromString(server.URL)

registry/basicauth.go

@@ -0,0 +1,11 @@
+// +build go1.4
+
+package registry
+
+import (
+	"net/http"
+)
+
+func basicAuth(r *http.Request) (username, password string, ok bool) {
+	return r.BasicAuth()
+}

registry/basicauth_prego14.go

@@ -0,0 +1,41 @@
+// +build !go1.4
+
+package registry
+
+import (
+	"encoding/base64"
+	"net/http"
+	"strings"
+)
+
+// NOTE(stevvooe): This is basic auth support from go1.4 present to ensure we
+// can compile on go1.3 and earlier.
+
+// BasicAuth returns the username and password provided in the request's
+// Authorization header, if the request uses HTTP Basic Authentication.
+// See RFC 2617, Section 2.
+func basicAuth(r *http.Request) (username, password string, ok bool) {
+	auth := r.Header.Get("Authorization")
+	if auth == "" {
+		return
+	}
+	return parseBasicAuth(auth)
+}
+
+// parseBasicAuth parses an HTTP Basic Authentication string.
+// "Basic QWxhZGRpbjpvcGVuIHNlc2FtZQ==" returns ("Aladdin", "open sesame", true).
+func parseBasicAuth(auth string) (username, password string, ok bool) {
+	if !strings.HasPrefix(auth, "Basic ") {
+		return
+	}
+	c, err := base64.StdEncoding.DecodeString(strings.TrimPrefix(auth, "Basic "))
+	if err != nil {
+		return
+	}
+	cs := string(c)
+	s := strings.IndexByte(cs, ':')
+	if s < 0 {
+		return
+	}
+	return cs[:s], cs[s+1:], true
+}

registry/context.go

@@ -1,10 +1,14 @@
 package registry
 
 import (
-	"github.com/Sirupsen/logrus"
+	"fmt"
+	"net/http"
+
 	"github.com/docker/distribution/api/v2"
-	"github.com/docker/distribution/auth"
+	ctxu "github.com/docker/distribution/context"
+	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/storage"
+	"golang.org/x/net/context"
 )
 
 // Context should contain the request specific context for use in across
@@ -13,9 +17,7 @@ import (
 type Context struct {
 	// App points to the application structure that created this context.
 	*App
-
+	context.Context
-	// RequestID is the unique id of the request.
-	RequestID string
 
 	// Repository is the repository for the current request. All requests
 	// should be scoped to a single repository. This field may be nil.
@@ -26,15 +28,63 @@ type Context struct {
 	// handler *must not* start the response via http.ResponseWriter.
 	Errors v2.Errors
 
-	// AuthUserInfo contains information about an authorized client.
-	AuthUserInfo auth.UserInfo
-
-	// vars contains the extracted gorilla/mux variables that can be used for
-	// assignment.
-	vars map[string]string
-
-	// log provides a context specific logger.
-	log *logrus.Entry
-
 	urlBuilder *v2.URLBuilder
+
+	// TODO(stevvooe): The goal is too completely factor this context and
+	// dispatching out of the web application. Ideally, we should lean on
+	// context.Context for injection of these resources.
+}
+
+// Value overrides context.Context.Value to ensure that calls are routed to
+// correct context.
+func (ctx *Context) Value(key interface{}) interface{} {
+	return ctx.Context.Value(key)
+}
+
+func getName(ctx context.Context) (name string) {
+	return ctxu.GetStringValue(ctx, "vars.name")
+}
+
+func getTag(ctx context.Context) (tag string) {
+	return ctxu.GetStringValue(ctx, "vars.tag")
+}
+
+var errDigestNotAvailable = fmt.Errorf("digest not available in context")
+
+func getDigest(ctx context.Context) (dgst digest.Digest, err error) {
+	dgstStr := ctxu.GetStringValue(ctx, "vars.digest")
+
+	if dgstStr == "" {
+		ctxu.GetLogger(ctx).Errorf("digest not available")
+		return "", errDigestNotAvailable
+	}
+
+	d, err := digest.ParseDigest(dgstStr)
+	if err != nil {
+		ctxu.GetLogger(ctx).Errorf("error parsing digest=%q: %v", dgstStr, err)
+		return "", err
+	}
+
+	return d, nil
+}
+
+func getUploadUUID(ctx context.Context) (uuid string) {
+	return ctxu.GetStringValue(ctx, "vars.uuid")
+}
+
+// getUserName attempts to resolve a username from the context and request. If
+// a username cannot be resolved, the empty string is returned.
+func getUserName(ctx context.Context, r *http.Request) string {
+	username := ctxu.GetStringValue(ctx, "auth.user.name")
+
+	// Fallback to request user with basic auth
+	if username == "" {
+		var ok bool
+		uname, _, ok := basicAuth(r)
+		if ok {
+			username = uname
+		}
+	}
+
+	return username
 }

registry/images.go

@@ -6,6 +6,7 @@ import (
 	"net/http"
 
 	"github.com/docker/distribution/api/v2"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/manifest"
 	"github.com/docker/distribution/storage"
@@ -17,11 +18,9 @@ import (
 func imageManifestDispatcher(ctx *Context, r *http.Request) http.Handler {
 	imageManifestHandler := &imageManifestHandler{
 		Context: ctx,
-		Tag:     ctx.vars["tag"],
+		Tag:     getTag(ctx),
 	}
 
-	imageManifestHandler.log = imageManifestHandler.log.WithField("tag", imageManifestHandler.Tag)
-
 	return handlers.MethodHandler{
 		"GET":    http.HandlerFunc(imageManifestHandler.GetImageManifest),
 		"PUT":    http.HandlerFunc(imageManifestHandler.PutImageManifest),
@@ -38,6 +37,7 @@ type imageManifestHandler struct {
 
 // GetImageManifest fetches the image manifest from the storage backend, if it exists.
 func (imh *imageManifestHandler) GetImageManifest(w http.ResponseWriter, r *http.Request) {
+	ctxu.GetLogger(imh).Debug("GetImageManifest")
 	manifests := imh.Repository.Manifests()
 	manifest, err := manifests.Get(imh.Tag)
 
@@ -54,6 +54,7 @@ func (imh *imageManifestHandler) GetImageManifest(w http.ResponseWriter, r *http
 
 // PutImageManifest validates and stores and image in the registry.
 func (imh *imageManifestHandler) PutImageManifest(w http.ResponseWriter, r *http.Request) {
+	ctxu.GetLogger(imh).Debug("PutImageManifest")
 	manifests := imh.Repository.Manifests()
 	dec := json.NewDecoder(r.Body)
 
@@ -98,6 +99,7 @@ func (imh *imageManifestHandler) PutImageManifest(w http.ResponseWriter, r *http
 
 // DeleteImageManifest removes the image with the given tag from the registry.
 func (imh *imageManifestHandler) DeleteImageManifest(w http.ResponseWriter, r *http.Request) {
+	ctxu.GetLogger(imh).Debug("DeleteImageManifest")
 	manifests := imh.Repository.Manifests()
 	if err := manifests.Delete(imh.Tag); err != nil {
 		switch err := err.(type) {

registry/layer.go

@@ -4,6 +4,7 @@ import (
 	"net/http"
 
 	"github.com/docker/distribution/api/v2"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/storage"
 	"github.com/gorilla/handlers"
@@ -11,9 +12,16 @@ import (
 
 // layerDispatcher uses the request context to build a layerHandler.
 func layerDispatcher(ctx *Context, r *http.Request) http.Handler {
-	dgst, err := digest.ParseDigest(ctx.vars["digest"])
+	dgst, err := getDigest(ctx)
-
 	if err != nil {
+
+		if err == errDigestNotAvailable {
+			return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+				w.WriteHeader(http.StatusNotFound)
+				ctx.Errors.Push(v2.ErrorCodeDigestInvalid, err)
+			})
+		}
+
 		return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 			ctx.Errors.Push(v2.ErrorCodeDigestInvalid, err)
 		})
@@ -24,8 +32,6 @@ func layerDispatcher(ctx *Context, r *http.Request) http.Handler {
 		Digest:  dgst,
 	}
 
-	layerHandler.log = layerHandler.log.WithField("digest", dgst)
-
 	return handlers.MethodHandler{
 		"GET":  http.HandlerFunc(layerHandler.GetLayer),
 		"HEAD": http.HandlerFunc(layerHandler.GetLayer),
@@ -42,6 +48,7 @@ type layerHandler struct {
 // GetLayer fetches the binary data from backend storage returns it in the
 // response.
 func (lh *layerHandler) GetLayer(w http.ResponseWriter, r *http.Request) {
+	ctxu.GetLogger(lh).Debug("GetImageLayer")
 	layers := lh.Repository.Layers()
 	layer, err := layers.Fetch(lh.Digest)
 

registry/layerupload.go

@@ -7,8 +7,8 @@ import (
 	"net/url"
 	"os"
 
-	"github.com/Sirupsen/logrus"
 	"github.com/docker/distribution/api/v2"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/storage"
 	"github.com/gorilla/handlers"
@@ -19,7 +19,7 @@ import (
 func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 	luh := &layerUploadHandler{
 		Context: ctx,
-		UUID:    ctx.vars["uuid"],
+		UUID:    getUploadUUID(ctx),
 	}
 
 	handler := http.Handler(handlers.MethodHandler{
@@ -33,12 +33,10 @@ func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 	})
 
 	if luh.UUID != "" {
-		luh.log = luh.log.WithField("uuid", luh.UUID)
-
 		state, err := hmacKey(ctx.Config.HTTP.Secret).unpackUploadState(r.FormValue("_state"))
 		if err != nil {
 			return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-				ctx.log.Infof("error resolving upload: %v", err)
+				ctxu.GetLogger(ctx).Infof("error resolving upload: %v", err)
 				w.WriteHeader(http.StatusBadRequest)
 				luh.Errors.Push(v2.ErrorCodeBlobUploadInvalid, err)
 			})
@@ -47,7 +45,7 @@ func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 
 		if state.Name != ctx.Repository.Name() {
 			return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-				ctx.log.Infof("mismatched repository name in upload state: %q != %q", state.Name, luh.Repository.Name())
+				ctxu.GetLogger(ctx).Infof("mismatched repository name in upload state: %q != %q", state.Name, luh.Repository.Name())
 				w.WriteHeader(http.StatusBadRequest)
 				luh.Errors.Push(v2.ErrorCodeBlobUploadInvalid, err)
 			})
@@ -55,7 +53,7 @@ func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 
 		if state.UUID != luh.UUID {
 			return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-				ctx.log.Infof("mismatched uuid in upload state: %q != %q", state.UUID, luh.UUID)
+				ctxu.GetLogger(ctx).Infof("mismatched uuid in upload state: %q != %q", state.UUID, luh.UUID)
 				w.WriteHeader(http.StatusBadRequest)
 				luh.Errors.Push(v2.ErrorCodeBlobUploadInvalid, err)
 			})
@@ -64,7 +62,7 @@ func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 		layers := ctx.Repository.Layers()
 		upload, err := layers.Resume(luh.UUID)
 		if err != nil {
-			ctx.log.Errorf("error resolving upload: %v", err)
+			ctxu.GetLogger(ctx).Errorf("error resolving upload: %v", err)
 			if err == storage.ErrLayerUploadUnknown {
 				return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 					w.WriteHeader(http.StatusNotFound)
@@ -86,7 +84,7 @@ func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 			// start over.
 			if nn, err := upload.Seek(luh.State.Offset, os.SEEK_SET); err != nil {
 				defer upload.Close()
-				ctx.log.Infof("error seeking layer upload: %v", err)
+				ctxu.GetLogger(ctx).Infof("error seeking layer upload: %v", err)
 				return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 					w.WriteHeader(http.StatusBadRequest)
 					luh.Errors.Push(v2.ErrorCodeBlobUploadInvalid, err)
@@ -94,7 +92,7 @@ func layerUploadDispatcher(ctx *Context, r *http.Request) http.Handler {
 				})
 			} else if nn != luh.State.Offset {
 				defer upload.Close()
-				ctx.log.Infof("seek to wrong offest: %d != %d", nn, luh.State.Offset)
+				ctxu.GetLogger(ctx).Infof("seek to wrong offest: %d != %d", nn, luh.State.Offset)
 				return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 					w.WriteHeader(http.StatusBadRequest)
 					luh.Errors.Push(v2.ErrorCodeBlobUploadInvalid, err)
@@ -202,7 +200,7 @@ func (luh *layerUploadHandler) PutLayerUploadComplete(w http.ResponseWriter, r *
 			w.WriteHeader(http.StatusBadRequest)
 			luh.Errors.Push(v2.ErrorCodeDigestInvalid, err)
 		default:
-			luh.log.Errorf("unknown error completing upload: %#v", err)
+			ctxu.GetLogger(luh).Errorf("unknown error completing upload: %#v", err)
 			w.WriteHeader(http.StatusInternalServerError)
 			luh.Errors.Push(v2.ErrorCodeUnknown, err)
 		}
@@ -210,7 +208,7 @@ func (luh *layerUploadHandler) PutLayerUploadComplete(w http.ResponseWriter, r *
 		// Clean up the backend layer data if there was an error.
 		if err := luh.Upload.Cancel(); err != nil {
 			// If the cleanup fails, all we can do is observe and report.
-			luh.log.Errorf("error canceling upload after error: %v", err)
+			ctxu.GetLogger(luh).Errorf("error canceling upload after error: %v", err)
 		}
 
 		return
@@ -238,7 +236,7 @@ func (luh *layerUploadHandler) CancelLayerUpload(w http.ResponseWriter, r *http.
 	}
 
 	if err := luh.Upload.Cancel(); err != nil {
-		luh.log.Errorf("error encountered canceling upload: %v", err)
+		ctxu.GetLogger(luh).Errorf("error encountered canceling upload: %v", err)
 		w.WriteHeader(http.StatusInternalServerError)
 		luh.Errors.PushErr(err)
 	}
@@ -253,7 +251,7 @@ func (luh *layerUploadHandler) layerUploadResponse(w http.ResponseWriter, r *htt
 
 	offset, err := luh.Upload.Seek(0, os.SEEK_CUR)
 	if err != nil {
-		luh.log.Errorf("unable get current offset of layer upload: %v", err)
+		ctxu.GetLogger(luh).Errorf("unable get current offset of layer upload: %v", err)
 		return err
 	}
 
@@ -265,7 +263,7 @@ func (luh *layerUploadHandler) layerUploadResponse(w http.ResponseWriter, r *htt
 
 	token, err := hmacKey(luh.Config.HTTP.Secret).packUploadState(luh.State)
 	if err != nil {
-		logrus.Infof("error building upload state token: %s", err)
+		ctxu.GetLogger(luh).Infof("error building upload state token: %s", err)
 		return err
 	}
 
@@ -275,7 +273,7 @@ func (luh *layerUploadHandler) layerUploadResponse(w http.ResponseWriter, r *htt
 			"_state": []string{token},
 		})
 	if err != nil {
-		logrus.Infof("error building upload url: %s", err)
+		ctxu.GetLogger(luh).Infof("error building upload url: %s", err)
 		return err
 	}