diff --git a/Godeps/Godeps.json b/Godeps/Godeps.json index 41b729ea0..45c1c5ac2 100644 --- a/Godeps/Godeps.json +++ b/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", - "Rev": "7dda39b2e7d5e265014674c5af696ba4186679e9" + "Comment": "null-15", + "Rev": "35bc42037350f0078e3c974c6ea690f1926603ab" }, { "ImportPath": "github.com/AdRoll/goamz/aws", @@ -24,8 +24,8 @@ }, { "ImportPath": "github.com/Sirupsen/logrus", - "Comment": "v0.6.1-8-gcc09837", - "Rev": "cc09837bcd512ffe6bb2e3f635bed138c4cd6bc8" + "Comment": "v0.6.4-12-g467d9d5", + "Rev": "467d9d55c2d2c17248441a8fc661561161f40d5e" }, { "ImportPath": "github.com/bugsnag/bugsnag-go", diff --git a/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/LICENSE b/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/LICENSE index ab6b011a1..5dc68268d 100644 --- a/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/LICENSE +++ b/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 diff --git a/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/time.go b/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/time.go index b9369c200..7ebc9bef1 100644 --- a/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/time.go +++ b/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 -// time cannot be determined. -func GetTime() (Time, error) { +// clock sequence as well as adjusting the clock sequence as needed. An error +// is returned if the current time cannot be determined. +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 diff --git a/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/version1.go b/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/version1.go index 63580044b..0127eacfa 100644 --- a/Godeps/_workspace/src/code.google.com/p/go-uuid/uuid/version1.go +++ b/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 diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/.travis.yml b/Godeps/_workspace/src/github.com/Sirupsen/logrus/.travis.yml index c3af3ce27..2d8c08661 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/.travis.yml +++ b/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 github.com/stvp/go-udp-testing - - go get github.com/tobi/airbrake-go - - go get github.com/getsentry/raven-go + - go get -t ./... diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/README.md b/Godeps/_workspace/src/github.com/Sirupsen/logrus/README.md index cabd027ae..6227b3f32 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/README.md +++ b/Godeps/_workspace/src/github.com/Sirupsen/logrus/README.md @@ -1,8 +1,8 @@ -# Logrus :walrus: [![Build Status](https://travis-ci.org/Sirupsen/logrus.svg?branch=master)](https://travis-ci.org/Sirupsen/logrus) +# Logrus :walrus: [![Build Status](https://travis-ci.org/Sirupsen/logrus.svg?branch=master)](https://travis-ci.org/Sirupsen/logrus) [![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 diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/entry.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/entry.go index e164eecb5..17fe6f707 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/entry.go +++ b/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...)) diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/exported.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/exported.go index d08712448..fd092fc7e 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/exported.go +++ b/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() diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/formatter.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/formatter.go index 74c49a0e0..038ce9fd2 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/formatter.go +++ b/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) { - _, ok := entry.Data["time"] +func prefixFieldClashes(data Fields) { + _, 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"] } } diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/papertrail/papertrail.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/papertrail/papertrail.go index 12c56f293..c0f10c1bd 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/papertrail/papertrail.go +++ b/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 { diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/syslog/README.md b/Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/syslog/README.md index cd706bc1b..4dbb8e729 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/hooks/syslog/README.md +++ b/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() { @@ -17,4 +17,4 @@ func main() { log.Hooks.Add(hook) } } -``` \ No newline at end of file +``` diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/json_formatter.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/json_formatter.go index 9d11b642d..b09227c2b 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/json_formatter.go +++ b/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) - entry.Data["time"] = entry.Time.Format(time.RFC3339) - entry.Data["msg"] = entry.Message - entry.Data["level"] = entry.Level.String() + data := make(Fields, len(entry.Data)+3) + for k, v := range entry.Data { + data[k] = v + } + 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) } diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/logger.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/logger.go index 7374fe365..b392e547a 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/logger.go +++ b/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`. diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/logrus_test.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/logrus_test.go index 15157d172..7f52c6fbc 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/logrus_test.go +++ b/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]) - assert.NoError(t, err) + val := kvArr[1] + 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()) diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/terminal_notwindows.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/terminal_notwindows.go index 276447bd5..80edd3237 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/terminal_notwindows.go +++ b/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 diff --git a/Godeps/_workspace/src/github.com/Sirupsen/logrus/text_formatter.go b/Godeps/_workspace/src/github.com/Sirupsen/logrus/text_formatter.go index fc0a4082a..78e788935 100644 --- a/Godeps/_workspace/src/github.com/Sirupsen/logrus/text_formatter.go +++ b/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: - fmt.Fprintf(b, "%v=%q ", key, value) + case string: + 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) } diff --git a/auth/auth.go b/auth/auth.go index e5bd65358..cd6ee0961 100644 --- a/auth/auth.go +++ b/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) diff --git a/auth/silly/access.go b/auth/silly/access.go index 2f0831e7d..c3adba804 100644 --- a/auth/silly/access.go +++ b/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 } diff --git a/auth/token/accesscontroller.go b/auth/token/accesscontroller.go index 77232109c..2f1e3d6d7 100644 --- a/auth/token/accesscontroller.go +++ b/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. diff --git a/cmd/registry/main.go b/cmd/registry/main.go index 98f3d5bda..0ed8fcd28 100644 --- a/cmd/registry/main.go +++ b/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) } } } diff --git a/context/doc.go b/context/doc.go new file mode 100644 index 000000000..a63989e54 --- /dev/null +++ b/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 diff --git a/context/http.go b/context/http.go new file mode 100644 index 000000000..ab3a3744d --- /dev/null +++ b/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.". 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) +} diff --git a/context/http_test.go b/context/http_test.go new file mode 100644 index 000000000..df3734e86 --- /dev/null +++ b/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) + } + } +} diff --git a/context/logger.go b/context/logger.go new file mode 100644 index 000000000..bec8fade4 --- /dev/null +++ b/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) +} diff --git a/context/util.go b/context/util.go new file mode 100644 index 000000000..7202c160d --- /dev/null +++ b/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 +} diff --git a/registry/api_test.go b/registry/api_test.go index aa70e504c..5e3bd72c6 100644 --- a/registry/api_test.go +++ b/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{ - Storage: configuration.Storage{ - "inmemory": configuration.Parameters{}, - }, - } + env := newTestEnv(t) - 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) - } - - baseURL, err := builder.BuildBaseURL() + baseURL, err := env.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. - - 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) - } + env := newTestEnv(t) 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) - resp, err = doPushLayer(t, builder, imageName, layerDigest, uploadURLBase, bytes.NewReader([]byte{})) + uploadURLBase = startPushLayer(t, env.builder, imageName) + 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) - pushLayer(t, builder, imageName, zeroDigest, uploadURLBase, bytes.NewReader([]byte{})) + uploadURLBase = startPushLayer(t, env.builder, imageName) + 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) - pushLayer(t, builder, imageName, emptyDigest, uploadURLBase, bytes.NewReader(emptyTar)) + uploadURLBase = startPushLayer(t, env.builder, imageName) + 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) - pushLayer(t, builder, imageName, layerDigest, uploadURLBase, layerFile) + uploadURLBase = startPushLayer(t, env.builder, imageName) + 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() - 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) - } + env := newTestEnv(t) 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) - pushLayer(t, builder, imageName, dgst, uploadURLBase, rs) + uploadURLBase := startPushLayer(t, env.builder, imageName) + 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 { diff --git a/registry/app.go b/registry/app.go index 6e5480c38..d2f9e2d94 100644 --- a/registry/app.go +++ b/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 -// a new context with an "http.request" value. -func WithRequest(ctx context.Context, r *http.Request) context.Context { - return context.WithValue(ctx, "http.request", r) +func (ssrw *singleStatusResponseWriter) Flush() { + if flusher, ok := ssrw.ResponseWriter.(http.Flusher); ok { + flusher.Flush() + } } // 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()) + app.registry.Repository(context, getName(context)), + app.eventBridge(context, r)) 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 { - vars := mux.Vars(r) +func (app *App) context(w http.ResponseWriter, r *http.Request) *Context { + 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 { - if app.accessController == nil { - // No access controller, so we simply provide access. - context.Repository = app.registry.Repository(repo) +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 { 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 - // 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. - context.Repository = app.registry.Repository(repo) + // TODO(stevvooe): This pattern needs to be cleaned up a bit. One context + // should be replaced by another, rather than replacing the context on a + // mutable object. + context.Context = ctx 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) } diff --git a/registry/app_test.go b/registry/app_test.go index d49c7bbd4..9b106575d 100644 --- a/registry/app_test.go +++ b/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 { - t.Fatalf("unexpected %s in context vars: %q != %q", expectedK, ctx.vars[expectedK], expectedV) + if ctx.Value(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) diff --git a/registry/basicauth.go b/registry/basicauth.go new file mode 100644 index 000000000..55794ee32 --- /dev/null +++ b/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() +} diff --git a/registry/basicauth_prego14.go b/registry/basicauth_prego14.go new file mode 100644 index 000000000..dc563135b --- /dev/null +++ b/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 +} diff --git a/registry/context.go b/registry/context.go index 150e5de63..7c4dbb023 100644 --- a/registry/context.go +++ b/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 - - // RequestID is the unique id of the request. - RequestID string + context.Context // 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 } diff --git a/registry/images.go b/registry/images.go index db6bd7058..c44b0b210 100644 --- a/registry/images.go +++ b/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) { diff --git a/registry/layer.go b/registry/layer.go index bea1cc8b9..10569465c 100644 --- a/registry/layer.go +++ b/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) diff --git a/registry/layerupload.go b/registry/layerupload.go index cfce98f3a..f30bb3aa6 100644 --- a/registry/layerupload.go +++ b/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 } diff --git a/storage/blobstore.go b/storage/blobstore.go index 04d247ffc..ac123f44a 100644 --- a/storage/blobstore.go +++ b/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 } diff --git a/storage/layer_test.go b/storage/layer_test.go index 2a551694e..c7d64b794 100644 --- a/storage/layer_test.go +++ b/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 { diff --git a/storage/layerstore.go b/storage/layerstore.go index 7dd7e2ac6..b6578792d 100644 --- a/storage/layerstore.go +++ b/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, diff --git a/storage/layerupload.go b/storage/layerupload.go index 0c69e30da..54860913a 100644 --- a/storage/layerupload.go +++ b/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 :. 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 } diff --git a/storage/manifeststore.go b/storage/manifeststore.go index f84a0208f..1f798dde8 100644 --- a/storage/manifeststore.go +++ b/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 diff --git a/storage/manifeststore_test.go b/storage/manifeststore_test.go index 15bf27beb..8284ce948 100644 --- a/storage/manifeststore_test.go +++ b/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) diff --git a/storage/notifications/listener_test.go b/storage/notifications/listener_test.go index 17af8b158..30d3f43f3 100644 --- a/storage/notifications/listener_test.go +++ b/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) diff --git a/storage/registry.go b/storage/registry.go index b1e20eecb..ed8650076 100644 --- a/storage/registry.go +++ b/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 } diff --git a/storage/services.go b/storage/services.go index cfb8c7876..7e6ac4766 100644 --- a/storage/services.go +++ b/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.