Merge pull request #151 from stevvooe/context-aware-logging

context, registry, auth, auth/token, cmd/registry: context aware logging

Godeps/Godeps.json

@@ -1,14 +1,14 @@
 {
 	"ImportPath": "github.com/docker/distribution",
-	"GoVersion": "go1.4",
+	"GoVersion": "go1.4.1",
 	"Packages": [
 		"./..."
 	],
 	"Deps": [
 		{
 			"ImportPath": "code.google.com/p/go-uuid/uuid",
-			"Comment": "null-12",
+			"Comment": "null-15",
-			"Rev": "7dda39b2e7d5e265014674c5af696ba4186679e9"
+			"Rev": "35bc42037350f0078e3c974c6ea690f1926603ab"
 		},
 		{
 			"ImportPath": "github.com/AdRoll/goamz/aws",
@@ -24,8 +24,8 @@
 		},
 		{
 			"ImportPath": "github.com/Sirupsen/logrus",
-			"Comment": "v0.6.1-8-gcc09837",
+			"Comment": "v0.6.4-12-g467d9d5",
-			"Rev": "cc09837bcd512ffe6bb2e3f635bed138c4cd6bc8"
+			"Rev": "467d9d55c2d2c17248441a8fc661561161f40d5e"
 		},
 		{
 			"ImportPath": "github.com/bugsnag/bugsnag-go",

Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/LICENSE

@@ -1,4 +1,4 @@
-Copyright (c) 2009 Google Inc. All rights reserved.
+Copyright (c) 2009,2014 Google Inc. All rights reserved.
 
 Redistribution and use in source and binary forms, with or without
 modification, are permitted provided that the following conditions are

Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/time.go

@@ -40,15 +40,15 @@ func (t Time) UnixTime() (sec, nsec int64) {
 }
 
 // GetTime returns the current Time (100s of nanoseconds since 15 Oct 1582) and
-// adjusts the clock sequence as needed.  An error is returned if the current
+// clock sequence as well as adjusting the clock sequence as needed.  An error
-// time cannot be determined.
+// is returned if the current time cannot be determined.
-func GetTime() (Time, error) {
+func GetTime() (Time, uint16, error) {
 	defer mu.Unlock()
 	mu.Lock()
 	return getTime()
 }
 
-func getTime() (Time, error) {
+func getTime() (Time, uint16, error) {
 	t := timeNow()
 
 	// If we don't have a clock sequence already, set one.
@@ -63,7 +63,7 @@ func getTime() (Time, error) {
 		clock_seq = ((clock_seq + 1) & 0x3fff) | 0x8000
 	}
 	lasttime = now
-	return Time(now), nil
+	return Time(now), clock_seq, nil
 }
 
 // ClockSequence returns the current clock sequence, generating one if not

Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/version1.go

@@ -19,7 +19,7 @@ func NewUUID() UUID {
 		SetNodeInterface("")
 	}
 
-	now, err := GetTime()
+	now, seq, err := GetTime()
 	if err != nil {
 		return nil
 	}
@@ -34,7 +34,7 @@ func NewUUID() UUID {
 	binary.BigEndian.PutUint32(uuid[0:], time_low)
 	binary.BigEndian.PutUint16(uuid[4:], time_mid)
 	binary.BigEndian.PutUint16(uuid[6:], time_hi)
-	binary.BigEndian.PutUint16(uuid[8:], clock_seq)
+	binary.BigEndian.PutUint16(uuid[8:], seq)
 	copy(uuid[10:], nodeID)
 
 	return uuid

Godeps/_workspace/src/github.com/Sirupsen/logrus/.travis.yml

@@ -2,9 +2,7 @@ language: go
 go:
   - 1.2
   - 1.3
+  - 1.4
   - tip
 install:
-  - go get github.com/stretchr/testify
+  - go get -t ./...
-  - go get github.com/stvp/go-udp-testing
-  - go get github.com/tobi/airbrake-go
-  - go get github.com/getsentry/raven-go

Godeps/_workspace/src/github.com/Sirupsen/logrus/README.md

@@ -1,8 +1,8 @@
-# Logrus <img src="http://i.imgur.com/hTeVwmJ.png" width="40" height="40" alt=":walrus:" class="emoji" title=":walrus:"/>&nbsp;[![Build Status](https://travis-ci.org/Sirupsen/logrus.svg?branch=master)](https://travis-ci.org/Sirupsen/logrus)
+# Logrus <img src="http://i.imgur.com/hTeVwmJ.png" width="40" height="40" alt=":walrus:" class="emoji" title=":walrus:"/>&nbsp;[![Build Status](https://travis-ci.org/Sirupsen/logrus.svg?branch=master)](https://travis-ci.org/Sirupsen/logrus)&nbsp;[![godoc reference](https://godoc.org/github.com/Sirupsen/logrus?status.png)][godoc]
 
 Logrus is a structured logger for Go (golang), completely API compatible with
 the standard library logger. [Godoc][godoc]. **Please note the Logrus API is not
-yet stable (pre 1.0), the core API is unlikely change much but please version
+yet stable (pre 1.0), the core API is unlikely to change much but please version
 control your Logrus to make sure you aren't fetching latest `master` on every
 build.**
 
@@ -33,7 +33,7 @@ ocean","size":10,"time":"2014-03-10 19:57:38.562264131 -0400 EDT"}
 
 With the default `log.Formatter = new(logrus.TextFormatter)` when a TTY is not
 attached, the output is compatible with the
-[l2met](http://r.32k.io/l2met-introduction) format:
+[logfmt](http://godoc.org/github.com/kr/logfmt) format:
 
 ```text
 time="2014-04-20 15:36:23.830442383 -0400 EDT" level="info" msg="A group of walrus emerges from the ocean" animal="walrus" size=10
@@ -235,6 +235,12 @@ func init() {
 * [`github.com/nubo/hiprus`](https://github.com/nubo/hiprus)
   Send errors to a channel in hipchat.
 
+* [`github.com/sebest/logrusly`](https://github.com/sebest/logrusly)
+  Send logs to Loggly (https://www.loggly.com/)
+
+* [`github.com/johntdyer/slackrus`](https://github.com/johntdyer/slackrus)
+  Hook for Slack chat.
+
 #### Level logging
 
 Logrus has six logging levels: Debug, Info, Warning, Error, Fatal and Panic.
@@ -314,7 +320,7 @@ The built-in logging formatters are:
 
 Third party logging formatters:
 
-* [`zalgo`](https://github.com/aybabtme/logzalgo): invoking the P͉̫o̳̼̊w̖͈̰͎e̬͔̭͂r͚̼̹̲ ̫͓͉̳͈ō̠͕͖̚f̝͍̠ ͕̲̞͖͑Z̖̫̤̫ͪa͉̬͈̗l͖͎g̳̥o̰̥̅!̣͔̲̻͊̄ ̙̘̦̹̦.
+* [`zalgo`](https://github.com/aybabtme/logzalgo): invoking the P͉̫o̳̼̊w̖͈̰͎e̬͔̭͂r͚̼̹̲ ̫͓͉̳͈ō̠͕͖̚f̝͍̠ ͕̲̞͖͑Z̖̫̤̫ͪa͉̬͈̗l͖͎g̳̥o̰̥̅!̣͔̲̻͊̄ ̙̘̦̹̦.
 
 You can define your formatter by implementing the `Formatter` interface,
 requiring a `Format` method. `Format` takes an `*Entry`. `entry.Data` is a
@@ -339,6 +345,24 @@ func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
 }
 ```
 
+#### Logger as an `io.Writer`
+
+Logrus can be transormed into an `io.Writer`. That writer is the end of an `io.Pipe` and it is your responsability to close it.
+
+```go
+w := logger.Writer()
+defer w.Close()
+
+srv := http.Server{
+    // create a stdlib log.Logger that writes to
+    // logrus.Logger.
+    ErrorLog: log.New(w, "", 0),
+}
+```
+
+Each line written to that writer will be printed the usual way, using formatters
+and hooks. The level for those entries is `info`.
+
 #### Rotation
 
 Log rotation is not provided with Logrus. Log rotation should be done by an

Godeps/_workspace/src/github.com/Sirupsen/logrus/entry.go

@@ -126,6 +126,10 @@ func (entry *Entry) Warn(args ...interface{}) {
 	}
 }
 
+func (entry *Entry) Warning(args ...interface{}) {
+	entry.Warn(args...)
+}
+
 func (entry *Entry) Error(args ...interface{}) {
 	if entry.Logger.Level >= ErrorLevel {
 		entry.log(ErrorLevel, fmt.Sprint(args...))

Godeps/_workspace/src/github.com/Sirupsen/logrus/exported.go

@@ -9,6 +9,10 @@ var (
 	std = New()
 )
 
+func StandardLogger() *Logger {
+	return std
+}
+
 // SetOutput sets the standard logger output.
 func SetOutput(out io.Writer) {
 	std.mu.Lock()

Godeps/_workspace/src/github.com/Sirupsen/logrus/formatter.go

@@ -26,19 +26,19 @@ type Formatter interface {
 //
 // It's not exported because it's still using Data in an opinionated way. It's to
 // avoid code duplication between the two default formatters.
-func prefixFieldClashes(entry *Entry) {
+func prefixFieldClashes(data Fields) {
-	_, ok := entry.Data["time"]
+	_, ok := data["time"]
 	if ok {
-		entry.Data["fields.time"] = entry.Data["time"]
+		data["fields.time"] = data["time"]
 	}
 
-	_, ok = entry.Data["msg"]
+	_, ok = data["msg"]
 	if ok {
-		entry.Data["fields.msg"] = entry.Data["msg"]
+		data["fields.msg"] = data["msg"]
 	}
 
-	_, ok = entry.Data["level"]
+	_, ok = data["level"]
 	if ok {
-		entry.Data["fields.level"] = entry.Data["level"]
+		data["fields.level"] = data["level"]
 	}
 }

Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/papertrail/papertrail.go

@@ -30,7 +30,8 @@ func NewPapertrailHook(host string, port int, appName string) (*PapertrailHook,
 // Fire is called when a log event is fired.
 func (hook *PapertrailHook) Fire(entry *logrus.Entry) error {
 	date := time.Now().Format(format)
-	payload := fmt.Sprintf("<22> %s %s: [%s] %s", date, hook.AppName, entry.Level, entry.Message)
+	msg, _ := entry.String()
+	payload := fmt.Sprintf("<22> %s %s: %s", date, hook.AppName, msg)
 
 	bytesWritten, err := hook.UDPConn.Write([]byte(payload))
 	if err != nil {

Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/syslog/README.md

@@ -6,7 +6,7 @@
 import (
   "log/syslog"
   "github.com/Sirupsen/logrus"
-  "github.com/Sirupsen/logrus/hooks/syslog"
+  logrus_syslog "github.com/Sirupsen/logrus/hooks/syslog"
 )
 
 func main() {

Godeps/_workspace/src/github.com/Sirupsen/logrus/json_formatter.go

@@ -9,12 +9,16 @@ import (
 type JSONFormatter struct{}
 
 func (f *JSONFormatter) Format(entry *Entry) ([]byte, error) {
-	prefixFieldClashes(entry)
+	data := make(Fields, len(entry.Data)+3)
-	entry.Data["time"] = entry.Time.Format(time.RFC3339)
+	for k, v := range entry.Data {
-	entry.Data["msg"] = entry.Message
+		data[k] = v
-	entry.Data["level"] = entry.Level.String()
+	}
+	prefixFieldClashes(data)
+	data["time"] = entry.Time.Format(time.RFC3339)
+	data["msg"] = entry.Message
+	data["level"] = entry.Level.String()
 
-	serialized, err := json.Marshal(entry.Data)
+	serialized, err := json.Marshal(data)
 	if err != nil {
 		return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err)
 	}

Godeps/_workspace/src/github.com/Sirupsen/logrus/logger.go

@@ -38,7 +38,7 @@ type Logger struct {
 //      Out: os.Stderr,
 //      Formatter: new(JSONFormatter),
 //      Hooks: make(levelHooks),
-//      Level: logrus.Debug,
+//      Level: logrus.DebugLevel,
 //    }
 //
 // It's recommended to make this a global instance called `log`.

Godeps/_workspace/src/github.com/Sirupsen/logrus/logrus_test.go

@@ -44,8 +44,12 @@ func LogAndAssertText(t *testing.T, log func(*Logger), assertions func(fields ma
 		}
 		kvArr := strings.Split(kv, "=")
 		key := strings.TrimSpace(kvArr[0])
-		val, err := strconv.Unquote(kvArr[1])
+		val := kvArr[1]
-		assert.NoError(t, err)
+		if kvArr[1][0] == '"' {
+			var err error
+			val, err = strconv.Unquote(val)
+			assert.NoError(t, err)
+		}
 		fields[key] = val
 	}
 	assertions(fields)
@@ -204,6 +208,38 @@ func TestDefaultFieldsAreNotPrefixed(t *testing.T) {
 	})
 }
 
+func TestDoubleLoggingDoesntPrefixPreviousFields(t *testing.T) {
+
+	var buffer bytes.Buffer
+	var fields Fields
+
+	logger := New()
+	logger.Out = &buffer
+	logger.Formatter = new(JSONFormatter)
+
+	llog := logger.WithField("context", "eating raw fish")
+
+	llog.Info("looks delicious")
+
+	err := json.Unmarshal(buffer.Bytes(), &fields)
+	assert.NoError(t, err, "should have decoded first message")
+	assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields")
+	assert.Equal(t, fields["msg"], "looks delicious")
+	assert.Equal(t, fields["context"], "eating raw fish")
+
+	buffer.Reset()
+
+	llog.Warn("omg it is!")
+
+	err = json.Unmarshal(buffer.Bytes(), &fields)
+	assert.NoError(t, err, "should have decoded second message")
+	assert.Equal(t, len(fields), 4, "should only have msg/time/level/context fields")
+	assert.Equal(t, fields["msg"], "omg it is!")
+	assert.Equal(t, fields["context"], "eating raw fish")
+	assert.Nil(t, fields["fields.msg"], "should not have prefixed previous `msg` entry")
+
+}
+
 func TestConvertLevelToString(t *testing.T) {
 	assert.Equal(t, "debug", DebugLevel.String())
 	assert.Equal(t, "info", InfoLevel.String())

Godeps/_workspace/src/github.com/Sirupsen/logrus/terminal_notwindows.go

@@ -3,7 +3,7 @@
 // Use of this source code is governed by a BSD-style
 // license that can be found in the LICENSE file.
 
-// +build linux,!appengine darwin freebsd
+// +build linux,!appengine darwin freebsd openbsd
 
 package logrus
 

Godeps/_workspace/src/github.com/Sirupsen/logrus/text_formatter.go

@@ -3,6 +3,7 @@ package logrus
 import (
 	"bytes"
 	"fmt"
+	"regexp"
 	"sort"
 	"strings"
 	"time"
@@ -19,6 +20,7 @@ const (
 var (
 	baseTimestamp time.Time
 	isTerminal    bool
+	noQuoteNeeded *regexp.Regexp
 )
 
 func init() {
@@ -34,6 +36,9 @@ type TextFormatter struct {
 	// Set to true to bypass checking for a TTY before outputting colors.
 	ForceColors   bool
 	DisableColors bool
+	// Set to true to disable timestamp logging (useful when the output
+	// is redirected to a logging system already adding a timestamp)
+	DisableTimestamp bool
 }
 
 func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
@@ -46,14 +51,16 @@ func (f *TextFormatter) Format(entry *Entry) ([]byte, error) {
 
 	b := &bytes.Buffer{}
 
-	prefixFieldClashes(entry)
+	prefixFieldClashes(entry.Data)
 
 	isColored := (f.ForceColors || isTerminal) && !f.DisableColors
 
 	if isColored {
 		printColored(b, entry, keys)
 	} else {
-		f.appendKeyValue(b, "time", entry.Time.Format(time.RFC3339))
+		if !f.DisableTimestamp {
+			f.appendKeyValue(b, "time", entry.Time.Format(time.RFC3339))
+		}
 		f.appendKeyValue(b, "level", entry.Level.String())
 		f.appendKeyValue(b, "msg", entry.Message)
 		for _, key := range keys {
@@ -85,10 +92,32 @@ func printColored(b *bytes.Buffer, entry *Entry, keys []string) {
 	}
 }
 
+func needsQuoting(text string) bool {
+	for _, ch := range text {
+		if !((ch >= 'a' && ch <= 'z') ||
+			(ch >= 'A' && ch <= 'Z') ||
+			(ch >= '0' && ch < '9') ||
+			ch == '-' || ch == '.') {
+			return false
+		}
+	}
+	return true
+}
+
 func (f *TextFormatter) appendKeyValue(b *bytes.Buffer, key, value interface{}) {
 	switch value.(type) {
-	case string, error:
+	case string:
-		fmt.Fprintf(b, "%v=%q ", key, value)
+		if needsQuoting(value.(string)) {
+			fmt.Fprintf(b, "%v=%s ", key, value)
+		} else {
+			fmt.Fprintf(b, "%v=%q ", key, value)
+		}
+	case error:
+		if needsQuoting(value.(error).Error()) {
+			fmt.Fprintf(b, "%v=%s ", key, value)
+		} else {
+			fmt.Fprintf(b, "%v=%q ", key, value)
+		}
 	default:
 		fmt.Fprintf(b, "%v=%v ", key, value)
 	}

auth/auth.go

@@ -31,29 +31,12 @@
 package auth
 
 import (
-	"errors"
 	"fmt"
 	"net/http"
 
 	"golang.org/x/net/context"
 )
 
-// Common errors used with this package.
-var (
-	ErrNoRequestContext = errors.New("no http request in context")
-	ErrNoAuthUserInfo   = errors.New("no auth user info in context")
-)
-
-// RequestFromContext returns the http request in the given context.
-// Returns ErrNoRequestContext if the context does not have an http
-// request associated with it.
-func RequestFromContext(ctx context.Context) (*http.Request, error) {
-	if r, ok := ctx.Value("http.request").(*http.Request); r != nil && ok {
-		return r, nil
-	}
-	return nil, ErrNoRequestContext
-}
-
 // UserInfo carries information about
 // an autenticated/authorized client.
 type UserInfo struct {
@@ -102,6 +85,30 @@ type AccessController interface {
 	Authorized(ctx context.Context, access ...Access) (context.Context, error)
 }
 
+// WithUser returns a context with the authorized user info.
+func WithUser(ctx context.Context, user UserInfo) context.Context {
+	return userInfoContext{
+		Context: ctx,
+		user:    user,
+	}
+}
+
+type userInfoContext struct {
+	context.Context
+	user UserInfo
+}
+
+func (uic userInfoContext) Value(key interface{}) interface{} {
+	switch key {
+	case "auth.user":
+		return uic.user
+	case "auth.user.name":
+		return uic.user.Name
+	}
+
+	return uic.Context.Value(key)
+}
+
 // InitFunc is the type of an AccessController factory function and is used
 // to register the contsructor for different AccesController backends.
 type InitFunc func(options map[string]interface{}) (AccessController, error)

auth/silly/access.go

@@ -13,6 +13,7 @@ import (
 	"strings"
 
 	"github.com/docker/distribution/auth"
+	ctxu "github.com/docker/distribution/context"
 	"golang.org/x/net/context"
 )
 
@@ -43,7 +44,7 @@ func newAccessController(options map[string]interface{}) (auth.AccessController,
 // Authorized simply checks for the existence of the authorization header,
 // responding with a bearer challenge if it doesn't exist.
 func (ac *accessController) Authorized(ctx context.Context, accessRecords ...auth.Access) (context.Context, error) {
-	req, err := auth.RequestFromContext(ctx)
+	req, err := ctxu.GetRequest(ctx)
 	if err != nil {
 		return nil, err
 	}

auth/token/accesscontroller.go

@@ -12,6 +12,7 @@ import (
 	"strings"
 
 	"github.com/docker/distribution/auth"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/libtrust"
 	"golang.org/x/net/context"
 )
@@ -224,7 +225,7 @@ func (ac *accessController) Authorized(ctx context.Context, accessItems ...auth.
 		accessSet: newAccessSet(accessItems...),
 	}
 
-	req, err := auth.RequestFromContext(ctx)
+	req, err := ctxu.GetRequest(ctx)
 	if err != nil {
 		return nil, err
 	}
@@ -264,7 +265,7 @@ func (ac *accessController) Authorized(ctx context.Context, accessItems ...auth.
 		}
 	}
 
-	return context.WithValue(ctx, "auth.user", auth.UserInfo{Name: token.Claims.Subject}), nil
+	return auth.WithUser(ctx, auth.UserInfo{Name: token.Claims.Subject}), nil
 }
 
 // init handles registering the token auth backend.

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)
 		}
 	}
 }

context/doc.go

@@ -0,0 +1,76 @@
+// Package context provides several utilities for working with
+// golang.org/x/net/context in http requests. Primarily, the focus is on
+// logging relevent request information but this package is not limited to
+// that purpose.
+//
+// Logging
+//
+// The most useful aspect of this package is GetLogger. This function takes
+// any context.Context interface and returns the current logger from the
+// context. Canonical usage looks like this:
+//
+// 	GetLogger(ctx).Infof("something interesting happened")
+//
+// GetLogger also takes optional key arguments. The keys will be looked up in
+// the context and reported with the logger. The following example would
+// return a logger that prints the version with each log message:
+//
+// 	ctx := context.Context(context.Background(), "version", version)
+// 	GetLogger(ctx, "version").Infof("this log message has a version field")
+//
+// The above would print out a log message like this:
+//
+// 	INFO[0000] this log message has a version field        version=v2.0.0-alpha.2.m
+//
+// When used with WithLogger, we gain the ability to decorate the context with
+// loggers that have information from disparate parts of the call stack.
+// Following from the version example, we can build a new context with the
+// configured logger such that we always print the version field:
+//
+// 	ctx = WithLogger(ctx, GetLogger(ctx, "version"))
+//
+// Since the logger has been pushed to the context, we can now get the version
+// field for free with our log messages. Future calls to GetLogger on the new
+// context will have the version field:
+//
+// 	GetLogger(ctx).Infof("this log message has a version field")
+//
+// This becomes more powerful when we start stacking loggers. Let's say we
+// have the version logger from above but also want a request id. Using the
+// context above, in our request scoped function, we place another logger in
+// the context:
+//
+// 	ctx = context.WithValue(ctx, "http.request.id", "unique id") // called when building request context
+// 	ctx = WithLogger(ctx, GetLogger(ctx, "http.request.id"))
+//
+// When GetLogger is called on the new context, "http.request.id" will be
+// included as a logger field, along with the original "version" field:
+//
+// 	INFO[0000] this log message has a version field        http.request.id=unique id version=v2.0.0-alpha.2.m
+//
+// Note that this only affects the new context, the previous context, with the
+// version field, can be used independently. Put another way, the new logger,
+// added to the request context, is unique to that context and can have
+// request scoped varaibles.
+//
+// HTTP Requests
+//
+// This package also contains several methods for working with http requests.
+// The concepts are very similar to those described above. We simply place the
+// request in the context using WithRequest. This makes the request variables
+// available. GetRequestLogger can then be called to get request specific
+// variables in a log line:
+//
+// 	ctx = WithRequest(ctx, req)
+// 	GetRequestLogger(ctx).Infof("request variables")
+//
+// Like above, if we want to include the request data in all log messages in
+// the context, we push the logger to a new context and use that one:
+//
+// 	ctx = WithLogger(ctx, GetRequestLogger(ctx))
+//
+// The concept is fairly powerful and ensures that calls throughout the stack
+// can be traced in log messages. Using the fields like "http.request.id", one
+// can analyze call flow for a particular request with a simple grep of the
+// logs.
+package context

context/http.go

@@ -0,0 +1,270 @@
+package context
+
+import (
+	"errors"
+	"net/http"
+	"strings"
+	"sync"
+	"time"
+
+	"code.google.com/p/go-uuid/uuid"
+	"github.com/gorilla/mux"
+	"golang.org/x/net/context"
+)
+
+// Common errors used with this package.
+var (
+	ErrNoRequestContext = errors.New("no http request in context")
+)
+
+// WithRequest places the request on the context. The context of the request
+// is assigned a unique id, available at "http.request.id". The request itself
+// is available at "http.request". Other common attributes are available under
+// the prefix "http.request.". If a request is already present on the context,
+// this method will panic.
+func WithRequest(ctx context.Context, r *http.Request) context.Context {
+	if ctx.Value("http.request") != nil {
+		// NOTE(stevvooe): This needs to be considered a programming error. It
+		// is unlikely that we'd want to have more than one request in
+		// context.
+		panic("only one request per context")
+	}
+
+	return &httpRequestContext{
+		Context:   ctx,
+		startedAt: time.Now(),
+		id:        uuid.New(), // assign the request a unique.
+		r:         r,
+	}
+}
+
+// GetRequest returns the http request in the given context. Returns
+// ErrNoRequestContext if the context does not have an http request associated
+// with it.
+func GetRequest(ctx context.Context) (*http.Request, error) {
+	if r, ok := ctx.Value("http.request").(*http.Request); r != nil && ok {
+		return r, nil
+	}
+	return nil, ErrNoRequestContext
+}
+
+// GetRequestID attempts to resolve the current request id, if possible. An
+// error is return if it is not available on the context.
+func GetRequestID(ctx context.Context) string {
+	return GetStringValue(ctx, "http.request.id")
+}
+
+// WithResponseWriter returns a new context and response writer that makes
+// interesting response statistics available within the context.
+func WithResponseWriter(ctx context.Context, w http.ResponseWriter) (context.Context, http.ResponseWriter) {
+	irw := &instrumentedResponseWriter{
+		ResponseWriter: w,
+		Context:        ctx,
+	}
+
+	return irw, irw
+}
+
+// getVarsFromRequest let's us change request vars implementation for testing
+// and maybe future changes.
+var getVarsFromRequest = mux.Vars
+
+// WithVars extracts gorilla/mux vars and makes them available on the returned
+// context. Variables are available at keys with the prefix "vars.". For
+// example, if looking for the variable "name", it can be accessed as
+// "vars.name". Implementations that are accessing values need not know that
+// the underlying context is implemented with gorilla/mux vars.
+func WithVars(ctx context.Context, r *http.Request) context.Context {
+	return &muxVarsContext{
+		Context: ctx,
+		vars:    getVarsFromRequest(r),
+	}
+}
+
+// GetRequestLogger returns a logger that contains fields from the request in
+// the current context. If the request is not available in the context, no
+// fields will display. Request loggers can safely be pushed onto the context.
+func GetRequestLogger(ctx context.Context) Logger {
+	return GetLogger(ctx,
+		"http.request.id",
+		"http.request.method",
+		"http.request.host",
+		"http.request.uri",
+		"http.request.referer",
+		"http.request.useragent",
+		"http.request.remoteaddr",
+		"http.request.contenttype")
+}
+
+// GetResponseLogger reads the current response stats and builds a logger.
+// Because the values are read at call time, pushing a logger returned from
+// this function on the context will lead to missing or invalid data. Only
+// call this at the end of a request, after the response has been written.
+func GetResponseLogger(ctx context.Context) Logger {
+	l := getLogrusLogger(ctx,
+		"http.response.written",
+		"http.response.status",
+		"http.response.contenttype")
+
+	duration := Since(ctx, "http.request.startedat")
+
+	if duration > 0 {
+		l = l.WithField("http.response.duration", duration)
+	}
+
+	return l
+}
+
+// httpRequestContext makes information about a request available to context.
+type httpRequestContext struct {
+	context.Context
+
+	startedAt time.Time
+	id        string
+	r         *http.Request
+}
+
+// Value returns a keyed element of the request for use in the context. To get
+// the request itself, query "request". For other components, access them as
+// "request.<component>". For example, r.RequestURI
+func (ctx *httpRequestContext) Value(key interface{}) interface{} {
+	if keyStr, ok := key.(string); ok {
+		if keyStr == "http.request" {
+			return ctx.r
+		}
+
+		parts := strings.Split(keyStr, ".")
+
+		if len(parts) != 3 {
+			goto fallback
+		}
+
+		switch parts[2] {
+		case "uri":
+			return ctx.r.RequestURI
+		case "remoteaddr":
+			return ctx.r.RemoteAddr
+		case "method":
+			return ctx.r.Method
+		case "host":
+			return ctx.r.Host
+		case "referer":
+			referer := ctx.r.Referer()
+			if referer != "" {
+				return referer
+			}
+		case "useragent":
+			return ctx.r.UserAgent()
+		case "id":
+			return ctx.id
+		case "startedat":
+			return ctx.startedAt
+		case "contenttype":
+			ct := ctx.r.Header.Get("Content-Type")
+			if ct != "" {
+				return ct
+			}
+		}
+	}
+
+fallback:
+	return ctx.Context.Value(key)
+}
+
+type muxVarsContext struct {
+	context.Context
+	vars map[string]string
+}
+
+func (ctx *muxVarsContext) Value(key interface{}) interface{} {
+	if keyStr, ok := key.(string); ok {
+		if keyStr == "vars" {
+			return ctx.vars
+		}
+
+		if strings.HasPrefix(keyStr, "vars.") {
+			keyStr = strings.TrimPrefix(keyStr, "vars.")
+		}
+
+		if v, ok := ctx.vars[keyStr]; ok {
+			return v
+		}
+	}
+
+	return ctx.Context.Value(key)
+}
+
+// instrumentedResponseWriter provides response writer information in a
+// context.
+type instrumentedResponseWriter struct {
+	http.ResponseWriter
+	context.Context
+
+	mu      sync.Mutex
+	status  int
+	written int64
+}
+
+func (irw *instrumentedResponseWriter) Write(p []byte) (n int, err error) {
+	n, err = irw.ResponseWriter.Write(p)
+
+	irw.mu.Lock()
+	irw.written += int64(n)
+
+	// Guess the likely status if not set.
+	if irw.status == 0 {
+		irw.status = http.StatusOK
+	}
+
+	irw.mu.Unlock()
+
+	return
+}
+
+func (irw *instrumentedResponseWriter) WriteHeader(status int) {
+	irw.ResponseWriter.WriteHeader(status)
+
+	irw.mu.Lock()
+	irw.status = status
+	irw.mu.Unlock()
+}
+
+func (irw *instrumentedResponseWriter) Flush() {
+	if flusher, ok := irw.ResponseWriter.(http.Flusher); ok {
+		flusher.Flush()
+	}
+}
+
+func (irw *instrumentedResponseWriter) Value(key interface{}) interface{} {
+	if keyStr, ok := key.(string); ok {
+		if keyStr == "http.response" {
+			return irw.ResponseWriter
+		}
+
+		parts := strings.Split(keyStr, ".")
+
+		if len(parts) != 3 {
+			goto fallback
+		}
+
+		irw.mu.Lock()
+		defer irw.mu.Unlock()
+
+		switch parts[2] {
+		case "written":
+			return irw.written
+		case "status":
+			if irw.status != 0 {
+				return irw.status
+			}
+		case "contenttype":
+			contentType := irw.Header().Get("Content-Type")
+			if contentType != "" {
+				return contentType
+			}
+		}
+	}
+
+fallback:
+	return irw.Context.Value(key)
+}

context/http_test.go

@@ -0,0 +1,207 @@
+package context
+
+import (
+	"net/http"
+	"reflect"
+	"testing"
+	"time"
+
+	"golang.org/x/net/context"
+)
+
+func TestWithRequest(t *testing.T) {
+	var req http.Request
+
+	start := time.Now()
+	req.Method = "GET"
+	req.Host = "example.com"
+	req.RequestURI = "/test-test"
+	req.Header = make(http.Header)
+	req.Header.Set("Referer", "foo.com/referer")
+	req.Header.Set("User-Agent", "test/0.1")
+
+	ctx := WithRequest(context.Background(), &req)
+	for _, testcase := range []struct {
+		key      string
+		expected interface{}
+	}{
+		{
+			key:      "http.request",
+			expected: &req,
+		},
+		{
+			key: "http.request.id",
+		},
+		{
+			key:      "http.request.method",
+			expected: req.Method,
+		},
+		{
+			key:      "http.request.host",
+			expected: req.Host,
+		},
+		{
+			key:      "http.request.uri",
+			expected: req.RequestURI,
+		},
+		{
+			key:      "http.request.referer",
+			expected: req.Referer(),
+		},
+		{
+			key:      "http.request.useragent",
+			expected: req.UserAgent(),
+		},
+		{
+			key:      "http.request.remoteaddr",
+			expected: req.RemoteAddr,
+		},
+		{
+			key: "http.request.startedat",
+		},
+	} {
+		v := ctx.Value(testcase.key)
+
+		if v == nil {
+			t.Fatalf("value not found for %q", testcase.key)
+		}
+
+		if testcase.expected != nil && v != testcase.expected {
+			t.Fatalf("%s: %v != %v", testcase.key, v, testcase.expected)
+		}
+
+		// Key specific checks!
+		switch testcase.key {
+		case "http.request.id":
+			if _, ok := v.(string); !ok {
+				t.Fatalf("request id not a string: %v", v)
+			}
+		case "http.request.startedat":
+			vt, ok := v.(time.Time)
+			if !ok {
+				t.Fatalf("value not a time: %v", v)
+			}
+
+			now := time.Now()
+			if vt.After(now) {
+				t.Fatalf("time generated too late: %v > %v", vt, now)
+			}
+
+			if vt.Before(start) {
+				t.Fatalf("time generated too early: %v < %v", vt, start)
+			}
+		}
+	}
+}
+
+type testResponseWriter struct {
+	flushed bool
+	status  int
+	written int64
+	header  http.Header
+}
+
+func (trw *testResponseWriter) Header() http.Header {
+	if trw.header == nil {
+		trw.header = make(http.Header)
+	}
+
+	return trw.header
+}
+
+func (trw *testResponseWriter) Write(p []byte) (n int, err error) {
+	if trw.status == 0 {
+		trw.status = http.StatusOK
+	}
+
+	n = len(p)
+	trw.written += int64(n)
+	return
+}
+
+func (trw *testResponseWriter) WriteHeader(status int) {
+	trw.status = status
+}
+
+func (trw *testResponseWriter) Flush() {
+	trw.flushed = true
+}
+
+func TestWithResponseWriter(t *testing.T) {
+	trw := testResponseWriter{}
+	ctx, rw := WithResponseWriter(context.Background(), &trw)
+
+	if ctx.Value("http.response") != &trw {
+		t.Fatalf("response not available in context: %v != %v", ctx.Value("http.response"), &trw)
+	}
+
+	if n, err := rw.Write(make([]byte, 1024)); err != nil {
+		t.Fatalf("unexpected error writing: %v", err)
+	} else if n != 1024 {
+		t.Fatalf("unexpected number of bytes written: %v != %v", n, 1024)
+	}
+
+	if ctx.Value("http.response.status") != http.StatusOK {
+		t.Fatalf("unexpected response status in context: %v != %v", ctx.Value("http.response.status"), http.StatusOK)
+	}
+
+	if ctx.Value("http.response.written") != int64(1024) {
+		t.Fatalf("unexpected number reported bytes written: %v != %v", ctx.Value("http.response.written"), 1024)
+	}
+
+	// Make sure flush propagates
+	rw.(http.Flusher).Flush()
+
+	if !trw.flushed {
+		t.Fatalf("response writer not flushed")
+	}
+
+	// Write another status and make sure context is correct. This normally
+	// wouldn't work except for in this contrived testcase.
+	rw.WriteHeader(http.StatusBadRequest)
+
+	if ctx.Value("http.response.status") != http.StatusBadRequest {
+		t.Fatalf("unexpected response status in context: %v != %v", ctx.Value("http.response.status"), http.StatusBadRequest)
+	}
+}
+
+func TestWithVars(t *testing.T) {
+	var req http.Request
+	vars := map[string]string{
+		"foo": "asdf",
+		"bar": "qwer",
+	}
+
+	getVarsFromRequest = func(r *http.Request) map[string]string {
+		if r != &req {
+			t.Fatalf("unexpected request: %v != %v", r, req)
+		}
+
+		return vars
+	}
+
+	ctx := WithVars(context.Background(), &req)
+	for _, testcase := range []struct {
+		key      string
+		expected interface{}
+	}{
+		{
+			key:      "vars",
+			expected: vars,
+		},
+		{
+			key:      "vars.foo",
+			expected: "asdf",
+		},
+		{
+			key:      "vars.bar",
+			expected: "qwer",
+		},
+	} {
+		v := ctx.Value(testcase.key)
+
+		if !reflect.DeepEqual(v, testcase.expected) {
+			t.Fatalf("%q: %v != %v", testcase.key, v, testcase.expected)
+		}
+	}
+}

context/logger.go

@@ -0,0 +1,88 @@
+package context
+
+import (
+	"fmt"
+
+	"github.com/Sirupsen/logrus"
+	"golang.org/x/net/context"
+)
+
+// Logger provides a leveled-logging interface.
+type Logger interface {
+	// standard logger methods
+	Print(args ...interface{})
+	Printf(format string, args ...interface{})
+	Println(args ...interface{})
+
+	Fatal(args ...interface{})
+	Fatalf(format string, args ...interface{})
+	Fatalln(args ...interface{})
+
+	Panic(args ...interface{})
+	Panicf(format string, args ...interface{})
+	Panicln(args ...interface{})
+
+	// Leveled methods, from logrus
+	Debug(args ...interface{})
+	Debugf(format string, args ...interface{})
+	Debugln(args ...interface{})
+
+	Error(args ...interface{})
+	Errorf(format string, args ...interface{})
+	Errorln(args ...interface{})
+
+	Info(args ...interface{})
+	Infof(format string, args ...interface{})
+	Infoln(args ...interface{})
+
+	Warn(args ...interface{})
+	Warnf(format string, args ...interface{})
+	Warnln(args ...interface{})
+}
+
+// WithLogger creates a new context with provided logger.
+func WithLogger(ctx context.Context, logger Logger) context.Context {
+	return context.WithValue(ctx, "logger", logger)
+}
+
+// GetLogger returns the logger from the current context, if present. If one
+// or more keys are provided, they will be resolved on the context and
+// included in the logger. While context.Value takes an interface, any key
+// argument passed to GetLogger will be passed to fmt.Sprint when expanded as
+// a logging key field. If context keys are integer constants, for example,
+// its recommended that a String method is implemented.
+func GetLogger(ctx context.Context, keys ...interface{}) Logger {
+	return getLogrusLogger(ctx, keys...)
+}
+
+// GetLogrusLogger returns the logrus logger for the context. If one more keys
+// are provided, they will be resolved on the context and included in the
+// logger. Only use this function if specific logrus functionality is
+// required.
+func getLogrusLogger(ctx context.Context, keys ...interface{}) *logrus.Entry {
+	var logger *logrus.Entry
+
+	// Get a logger, if it is present.
+	loggerInterface := ctx.Value("logger")
+	if loggerInterface != nil {
+		if lgr, ok := loggerInterface.(*logrus.Entry); ok {
+			logger = lgr
+		}
+	}
+
+	if logger == nil {
+		// If no logger is found, just return the standard logger.
+		logger = logrus.NewEntry(logrus.StandardLogger())
+	}
+
+	fields := logrus.Fields{}
+
+	for _, key := range keys {
+		v := ctx.Value(key)
+		if v != nil {
+			fields[fmt.Sprint(key)] = v
+		}
+	}
+
+	return logger.WithFields(fields)
+}

context/util.go

@@ -0,0 +1,34 @@
+package context
+
+import (
+	"time"
+
+	"golang.org/x/net/context"
+)
+
+// Since looks up key, which should be a time.Time, and returns the duration
+// since that time. If the key is not found, the value returned will be zero.
+// This is helpful when inferring metrics related to context execution times.
+func Since(ctx context.Context, key interface{}) time.Duration {
+	startedAtI := ctx.Value(key)
+	if startedAtI != nil {
+		if startedAt, ok := startedAtI.(time.Time); ok {
+			return time.Since(startedAt)
+		}
+	}
+
+	return 0
+}
+
+// GetStringValue returns a string value from the context. The empty string
+// will be returned if not found.
+func GetStringValue(ctx context.Context, key string) (value string) {
+	stringi := ctx.Value(key)
+	if stringi != nil {
+		if valuev, ok := stringi.(string); ok {
+			value = valuev
+		}
+	}
+
+	return value
+}

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,30 @@ 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))
+			app.registry.Repository(context, getName(context)),
-
+			app.eventBridge(context, r))
-		context.log = log.WithField("name", context.Repository.Name())
 		handler := dispatch(context, r)
 
 		ssrw := &singleStatusResponseWriter{ResponseWriter: w}
@@ -230,28 +248,35 @@ 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 {
-	if app.accessController == nil {
+	ctxu.GetLogger(context).Debug("authorizing request")
-		// No access controller, so we simply provide access.
+	repo := getName(context)
-		context.Repository = app.registry.Repository(repo)
 
+	if app.accessController == nil {
 		return nil // access controller is not enabled.
 	}
 
@@ -308,7 +333,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,20 +348,17 @@ 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
+	// TODO(stevvooe): This pattern needs to be cleaned up a bit. One context
-	// object. If it doesn't, just use the zero value for now.
+	// should be replaced by another, rather than replacing the context on a
-	context.AuthUserInfo, _ = authCtx.Value("auth.user").(auth.UserInfo)
+	// mutable object.
-
+	context.Context = ctx
-	// At this point, the request should have access to the repository under
-	// the requested operation. Make is available on the context.
-	context.Repository = app.registry.Repository(repo)
 
 	return nil
 }
@@ -345,9 +367,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
 	}
 

storage/blobstore.go

@@ -3,10 +3,10 @@ package storage
 import (
 	"fmt"
 
-	"github.com/Sirupsen/logrus"
+	ctxu "github.com/docker/distribution/context"
-
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/storagedriver"
+	"golang.org/x/net/context"
 )
 
 // TODO(stevvooe): Currently, the blobStore implementation used by the
@@ -19,6 +19,7 @@ import (
 // backend links.
 type blobStore struct {
 	*registry
+	ctx context.Context
 }
 
 // exists reports whether or not the path exists. If the driver returns error
@@ -110,7 +111,7 @@ func (bs *blobStore) resolve(path string) (string, error) {
 func (bs *blobStore) put(p []byte) (digest.Digest, error) {
 	dgst, err := digest.FromBytes(p)
 	if err != nil {
-		logrus.Errorf("error digesting content: %v, %s", err, string(p))
+		ctxu.GetLogger(bs.ctx).Errorf("error digesting content: %v, %s", err, string(p))
 		return "", err
 	}
 

storage/layer_test.go

@@ -13,6 +13,7 @@ import (
 	"github.com/docker/distribution/storagedriver"
 	"github.com/docker/distribution/storagedriver/inmemory"
 	"github.com/docker/distribution/testutil"
+	"golang.org/x/net/context"
 )
 
 // TestSimpleLayerUpload covers the layer upload process, exercising common
@@ -30,10 +31,11 @@ func TestSimpleLayerUpload(t *testing.T) {
 		t.Fatalf("error allocating upload store: %v", err)
 	}
 
+	ctx := context.Background()
 	imageName := "foo/bar"
 	driver := inmemory.New()
 	registry := NewRegistryWithDriver(driver)
-	ls := registry.Repository(imageName).Layers()
+	ls := registry.Repository(ctx, imageName).Layers()
 
 	h := sha256.New()
 	rd := io.TeeReader(randomDataReader, h)
@@ -133,10 +135,11 @@ func TestSimpleLayerUpload(t *testing.T) {
 // open, read, seek, read works. More specific edge cases should be covered in
 // other tests.
 func TestSimpleLayerRead(t *testing.T) {
+	ctx := context.Background()
 	imageName := "foo/bar"
 	driver := inmemory.New()
 	registry := NewRegistryWithDriver(driver)
-	ls := registry.Repository(imageName).Layers()
+	ls := registry.Repository(ctx, imageName).Layers()
 
 	randomLayerReader, tarSumStr, err := testutil.CreateRandomTarFile()
 	if err != nil {
@@ -237,10 +240,11 @@ func TestSimpleLayerRead(t *testing.T) {
 
 // TestLayerUploadZeroLength uploads zero-length
 func TestLayerUploadZeroLength(t *testing.T) {
+	ctx := context.Background()
 	imageName := "foo/bar"
 	driver := inmemory.New()
 	registry := NewRegistryWithDriver(driver)
-	ls := registry.Repository(imageName).Layers()
+	ls := registry.Repository(ctx, imageName).Layers()
 
 	upload, err := ls.Upload()
 	if err != nil {

storage/layerstore.go

@@ -4,6 +4,7 @@ import (
 	"time"
 
 	"code.google.com/p/go-uuid/uuid"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/manifest"
 	"github.com/docker/distribution/storagedriver"
@@ -14,6 +15,8 @@ type layerStore struct {
 }
 
 func (ls *layerStore) Exists(digest digest.Digest) (bool, error) {
+	ctxu.GetLogger(ls.repository.ctx).Debug("(*layerStore).Exists")
+
 	// Because this implementation just follows blob links, an existence check
 	// is pretty cheap by starting and closing a fetch.
 	_, err := ls.Fetch(digest)
@@ -31,6 +34,7 @@ func (ls *layerStore) Exists(digest digest.Digest) (bool, error) {
 }
 
 func (ls *layerStore) Fetch(dgst digest.Digest) (Layer, error) {
+	ctxu.GetLogger(ls.repository.ctx).Debug("(*layerStore).Fetch")
 	bp, err := ls.path(dgst)
 	if err != nil {
 		return nil, err
@@ -52,6 +56,7 @@ func (ls *layerStore) Fetch(dgst digest.Digest) (Layer, error) {
 // is already in progress or the layer has already been uploaded, this
 // will return an error.
 func (ls *layerStore) Upload() (LayerUpload, error) {
+	ctxu.GetLogger(ls.repository.ctx).Debug("(*layerStore).Upload")
 
 	// NOTE(stevvooe): Consider the issues with allowing concurrent upload of
 	// the same two layers. Should it be disallowed? For now, we allow both
@@ -89,6 +94,7 @@ func (ls *layerStore) Upload() (LayerUpload, error) {
 // Resume continues an in progress layer upload, returning the current
 // state of the upload.
 func (ls *layerStore) Resume(uuid string) (LayerUpload, error) {
+	ctxu.GetLogger(ls.repository.ctx).Debug("(*layerStore).Resume")
 	startedAtPath, err := ls.repository.registry.pm.path(uploadStartedAtPathSpec{
 		name: ls.repository.Name(),
 		uuid: uuid,

storage/layerupload.go

@@ -7,6 +7,7 @@ import (
 	"time"
 
 	"github.com/Sirupsen/logrus"
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/storagedriver"
 	"github.com/docker/docker/pkg/tarsum"
@@ -44,6 +45,7 @@ func (luc *layerUploadController) StartedAt() time.Time {
 // contents of the uploaded layer. The checksum should be provided in the
 // format <algorithm>:<hex digest>.
 func (luc *layerUploadController) Finish(digest digest.Digest) (Layer, error) {
+	ctxu.GetLogger(luc.layerStore.repository.ctx).Debug("(*layerUploadController).Finish")
 	canonical, err := luc.validateLayer(digest)
 	if err != nil {
 		return nil, err
@@ -68,6 +70,7 @@ func (luc *layerUploadController) Finish(digest digest.Digest) (Layer, error) {
 
 // Cancel the layer upload process.
 func (luc *layerUploadController) Cancel() error {
+	ctxu.GetLogger(luc.layerStore.repository.ctx).Debug("(*layerUploadController).Cancel")
 	if err := luc.removeResources(); err != nil {
 		return err
 	}

storage/manifeststore.go

@@ -4,6 +4,7 @@ import (
 	"fmt"
 	"strings"
 
+	ctxu "github.com/docker/distribution/context"
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/manifest"
 	"github.com/docker/libtrust"
@@ -77,14 +78,17 @@ var _ ManifestService = &manifestStore{}
 // }
 
 func (ms *manifestStore) Tags() ([]string, error) {
+	ctxu.GetLogger(ms.repository.ctx).Debug("(*manifestStore).Tags")
 	return ms.tagStore.tags()
 }
 
 func (ms *manifestStore) Exists(tag string) (bool, error) {
+	ctxu.GetLogger(ms.repository.ctx).Debug("(*manifestStore).Exists")
 	return ms.tagStore.exists(tag)
 }
 
 func (ms *manifestStore) Get(tag string) (*manifest.SignedManifest, error) {
+	ctxu.GetLogger(ms.repository.ctx).Debug("(*manifestStore).Get")
 	dgst, err := ms.tagStore.resolve(tag)
 	if err != nil {
 		return nil, err
@@ -94,6 +98,8 @@ func (ms *manifestStore) Get(tag string) (*manifest.SignedManifest, error) {
 }
 
 func (ms *manifestStore) Put(tag string, manifest *manifest.SignedManifest) error {
+	ctxu.GetLogger(ms.repository.ctx).Debug("(*manifestStore).Put")
+
 	// TODO(stevvooe): Add check here to see if the revision is already
 	// present in the repository. If it is, we should merge the signatures, do
 	// a shallow verify (or a full one, doesn't matter) and return an error
@@ -118,6 +124,8 @@ func (ms *manifestStore) Put(tag string, manifest *manifest.SignedManifest) erro
 // semantics in the future, but this will maintain consistency. The underlying
 // blobs are left alone.
 func (ms *manifestStore) Delete(tag string) error {
+	ctxu.GetLogger(ms.repository.ctx).Debug("(*manifestStore).Delete")
+
 	revisions, err := ms.tagStore.revisions(tag)
 	if err != nil {
 		return err

storage/manifeststore_test.go

@@ -6,20 +6,21 @@ import (
 	"reflect"
 	"testing"
 
-	"github.com/docker/distribution/testutil"
-
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/manifest"
 	"github.com/docker/distribution/storagedriver/inmemory"
+	"github.com/docker/distribution/testutil"
 	"github.com/docker/libtrust"
+	"golang.org/x/net/context"
 )
 
 func TestManifestStorage(t *testing.T) {
+	ctx := context.Background()
 	name := "foo/bar"
 	tag := "thetag"
 	driver := inmemory.New()
 	registry := NewRegistryWithDriver(driver)
-	repo := registry.Repository(name)
+	repo := registry.Repository(ctx, name)
 	ms := repo.Manifests()
 
 	exists, err := ms.Exists(tag)

storage/notifications/listener_test.go

@@ -11,6 +11,7 @@ import (
 	"github.com/docker/distribution/storagedriver/inmemory"
 	"github.com/docker/distribution/testutil"
 	"github.com/docker/libtrust"
+	"golang.org/x/net/context"
 )
 
 func TestListener(t *testing.T) {
@@ -18,7 +19,8 @@ func TestListener(t *testing.T) {
 	tl := &testListener{
 		ops: make(map[string]int),
 	}
-	repository := Listen(registry.Repository("foo/bar"), tl)
+	ctx := context.Background()
+	repository := Listen(registry.Repository(ctx, "foo/bar"), tl)
 
 	// Now take the registry through a number of operations
 	checkExerciseRepository(t, repository)

storage/registry.go

@@ -1,6 +1,9 @@
 package storage
 
-import "github.com/docker/distribution/storagedriver"
+import (
+	"github.com/docker/distribution/storagedriver"
+	"golang.org/x/net/context"
+)
 
 // registry is the top-level implementation of Registry for use in the storage
 // package. All instances should descend from this object.
@@ -32,8 +35,9 @@ func NewRegistryWithDriver(driver storagedriver.StorageDriver) Registry {
 // Repository returns an instance of the repository tied to the registry.
 // Instances should not be shared between goroutines but are cheap to
 // allocate. In general, they should be request scoped.
-func (reg *registry) Repository(name string) Repository {
+func (reg *registry) Repository(ctx context.Context, name string) Repository {
 	return &repository{
+		ctx:      ctx,
 		registry: reg,
 		name:     name,
 	}
@@ -42,6 +46,7 @@ func (reg *registry) Repository(name string) Repository {
 // repository provides name-scoped access to various services.
 type repository struct {
 	*registry
+	ctx  context.Context
 	name string
 }
 

storage/services.go

@@ -3,6 +3,7 @@ package storage
 import (
 	"github.com/docker/distribution/digest"
 	"github.com/docker/distribution/manifest"
+	"golang.org/x/net/context"
 )
 
 // TODO(stevvooe): These types need to be moved out of the storage package.
@@ -12,7 +13,7 @@ type Registry interface {
 	// Repository should return a reference to the named repository. The
 	// registry may or may not have the repository but should always return a
 	// reference.
-	Repository(name string) Repository
+	Repository(ctx context.Context, name string) Repository
 }
 
 // Repository is a named collection of manifests and layers.