From 29135602ecbf95f39ae92962048a12615834d656 Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Thu, 5 Feb 2015 11:58:43 -0800 Subject: [PATCH 1/6] Update go-uuid dependency There don't seem to be any major changes but we'll update this while we're at it. This dependency is pretty important for coming changes. Signed-off-by: Stephen J Day --- Godeps/Godeps.json | 6 +++--- .../src/code.google.com/p/go-uuid/uuid/LICENSE | 2 +- .../src/code.google.com/p/go-uuid/uuid/time.go | 10 +++++----- .../src/code.google.com/p/go-uuid/uuid/version1.go | 4 ++-- 4 files changed, 11 insertions(+), 11 deletions(-) diff --git a/Godeps/Godeps.json b/Godeps/Godeps.json index 41b729ea..a64ab359 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", 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 ab6b011a..5dc68268 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 b9369c20..7ebc9bef 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 63580044..0127eacf 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 From 13382e45baa7707bf125a63de3fcb738f1850412 Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Thu, 5 Feb 2015 12:00:07 -0800 Subject: [PATCH 2/6] Update logrus dependency This dependency added a method to access the current standard logger. This is required to properly configure the logger for context awareness. The plan is to have all loggers descend from the standard logger. Signed-off-by: Stephen J Day --- Godeps/Godeps.json | 4 +- .../github.com/Sirupsen/logrus/.travis.yml | 6 +-- .../src/github.com/Sirupsen/logrus/README.md | 32 +++++++++++++-- .../src/github.com/Sirupsen/logrus/entry.go | 4 ++ .../github.com/Sirupsen/logrus/exported.go | 4 ++ .../github.com/Sirupsen/logrus/formatter.go | 14 +++---- .../logrus/hooks/papertrail/papertrail.go | 3 +- .../Sirupsen/logrus/hooks/syslog/README.md | 4 +- .../Sirupsen/logrus/json_formatter.go | 14 ++++--- .../src/github.com/Sirupsen/logrus/logger.go | 2 +- .../github.com/Sirupsen/logrus/logrus_test.go | 40 ++++++++++++++++++- .../Sirupsen/logrus/terminal_notwindows.go | 2 +- .../Sirupsen/logrus/text_formatter.go | 37 +++++++++++++++-- 13 files changed, 133 insertions(+), 33 deletions(-) diff --git a/Godeps/Godeps.json b/Godeps/Godeps.json index a64ab359..45c1c5ac 100644 --- a/Godeps/Godeps.json +++ b/Godeps/Godeps.json @@ -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/github.com/Sirupsen/logrus/.travis.yml b/Godeps/_workspace/src/github.com/Sirupsen/logrus/.travis.yml index c3af3ce2..2d8c0866 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 cabd027a..6227b3f3 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 e164eecb..17fe6f70 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 d0871244..fd092fc7 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 74c49a0e..038ce9fd 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 12c56f29..c0f10c1b 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 cd706bc1..4dbb8e72 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 9d11b642..b09227c2 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 7374fe36..b392e547 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 15157d17..7f52c6fb 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 276447bd..80edd323 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 fc0a4082..78e78893 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) } From 4b14eef595a22f14ffa3d1329a3943f70deb84d7 Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Thu, 5 Feb 2015 13:56:50 -0800 Subject: [PATCH 3/6] Context package to support context-aware logging The new context package supports context-aware logging, integrating with logrus. Several utilities are provided to associate http requests with a context, ensuring that one can trace log messages all the way through a context-aware call stack. A full description of this functionality is available in doc.go. Signed-off-by: Stephen J Day --- context/doc.go | 76 ++++++++++++ context/http.go | 270 +++++++++++++++++++++++++++++++++++++++++++ context/http_test.go | 207 +++++++++++++++++++++++++++++++++ context/logger.go | 88 ++++++++++++++ context/util.go | 34 ++++++ 5 files changed, 675 insertions(+) create mode 100644 context/doc.go create mode 100644 context/http.go create mode 100644 context/http_test.go create mode 100644 context/logger.go create mode 100644 context/util.go diff --git a/context/doc.go b/context/doc.go new file mode 100644 index 00000000..a63989e5 --- /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 00000000..ab3a3744 --- /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 00000000..df3734e8 --- /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 00000000..bec8fade --- /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 00000000..7202c160 --- /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 +} From 9e33fb0f956a7693b565848848226d6706b1f5b9 Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Thu, 5 Feb 2015 19:12:32 -0800 Subject: [PATCH 4/6] Update auth/token to use context package utils Signed-off-by: Stephen J Day --- auth/auth.go | 41 ++++++++++++++++++++-------------- auth/silly/access.go | 3 ++- auth/token/accesscontroller.go | 5 +++-- 3 files changed, 29 insertions(+), 20 deletions(-) diff --git a/auth/auth.go b/auth/auth.go index e5bd6535..cd6ee096 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 2f0831e7..c3adba80 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 77232109..2f1e3d6d 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. From d2bfb5825caee862f0d7e7deb1b8cfbcf9cee047 Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Fri, 6 Feb 2015 16:19:19 -0800 Subject: [PATCH 5/6] Integrate contextual logging with regsitry app This changeset integrates contextual logging into the registry web application. Idiomatic context use is attempted within the current webapp layout. The functionality is centered around making lifecycle objects (application and request context) into contexts themselves. Relevant data has been moved into the context where appropriate. We still have some work to do to factor out the registry.Context object and the dispatching functionality to remove some awkward portions. The api tests were slightly refactored to use a test environment to eliminate common code. Signed-off-by: Stephen J Day --- cmd/registry/main.go | 24 ++++--- registry/api_test.go | 120 +++++++++++++++++----------------- registry/app.go | 77 ++++++++++++++-------- registry/app_test.go | 13 ++-- registry/basicauth.go | 11 ++++ registry/basicauth_prego14.go | 41 ++++++++++++ registry/context.go | 80 ++++++++++++++++++----- registry/images.go | 8 ++- registry/layer.go | 15 +++-- registry/layerupload.go | 30 ++++----- 10 files changed, 281 insertions(+), 138 deletions(-) create mode 100644 registry/basicauth.go create mode 100644 registry/basicauth_prego14.go diff --git a/cmd/registry/main.go b/cmd/registry/main.go index 98f3d5bd..0ed8fcd2 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/registry/api_test.go b/registry/api_test.go index aa70e504..5e3bd72c 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 6e5480c3..f40d35ef 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,29 @@ 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()) handler := dispatch(context, r) ssrw := &singleStatusResponseWriter{ResponseWriter: w} @@ -230,24 +247,34 @@ func (app *App) dispatcher(dispatch dispatchFunc) http.Handler { // context constructs the context object for the application. This only be // called once per request. -func (app *App) context(r *http.Request) *Context { - 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 { +func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Context) error { + ctxu.GetLogger(context).Debug("authorizing request") + repo := getName(context) + if app.accessController == nil { // No access controller, so we simply provide access. context.Repository = app.registry.Repository(repo) @@ -308,7 +335,7 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont } } - authCtx, err := app.accessController.Authorized(WithRequest(nil, r), accessRecords...) + ctx, err := app.accessController.Authorized(context.Context, accessRecords...) if err != nil { switch err := err.(type) { case auth.Challenge: @@ -323,16 +350,14 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont // the configuration or whatever is backing the access // controller. Just return a bad request with no information // to avoid exposure. The request should not proceed. - context.log.Errorf("error checking authorization: %v", err) + ctxu.GetLogger(context).Errorf("error checking authorization: %v", err) w.WriteHeader(http.StatusBadRequest) } return err } - // The authorized context should contain an auth.UserInfo - // object. If it doesn't, just use the zero value for now. - context.AuthUserInfo, _ = authCtx.Value("auth.user").(auth.UserInfo) + context.Context = ctx // At this point, the request should have access to the repository under // the requested operation. Make is available on the context. @@ -345,9 +370,9 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont // correct actor and source. func (app *App) eventBridge(ctx *Context, r *http.Request) notifications.Listener { actor := notifications.ActorRecord{ - Name: ctx.AuthUserInfo.Name, + Name: getUserName(ctx, r), } - request := notifications.NewRequestRecord(ctx.RequestID, r) + request := notifications.NewRequestRecord(ctxu.GetRequestID(ctx), r) return notifications.NewBridge(ctx.urlBuilder, app.events.source, actor, request, app.events.sink) } diff --git a/registry/app_test.go b/registry/app_test.go index d49c7bbd..9b106575 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 00000000..55794ee3 --- /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 00000000..dc563135 --- /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 150e5de6..7c4dbb02 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 db6bd705..c44b0b21 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 bea1cc8b..10569465 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 cfce98f3..f30bb3aa 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 } From d9d84ae2693004b51cf5e7ca9e1f47731bb373cf Mon Sep 17 00:00:00 2001 From: Stephen J Day Date: Mon, 9 Feb 2015 14:44:58 -0800 Subject: [PATCH 6/6] Integrate context with storage package This changeset integrates context with the storage package. Debug messages have been added to exported methods. Existing log messages will now include contextual details through logger fields to aid in debugging. This integration focuses on logging and may be followed up with a metric-oriented change in the future. Signed-off-by: Stephen J Day --- registry/app.go | 13 +++++-------- storage/blobstore.go | 7 ++++--- storage/layer_test.go | 10 +++++++--- storage/layerstore.go | 6 ++++++ storage/layerupload.go | 3 +++ storage/manifeststore.go | 8 ++++++++ storage/manifeststore_test.go | 7 ++++--- storage/notifications/listener_test.go | 4 +++- storage/registry.go | 9 +++++++-- storage/services.go | 3 ++- 10 files changed, 49 insertions(+), 21 deletions(-) diff --git a/registry/app.go b/registry/app.go index f40d35ef..d2f9e2d9 100644 --- a/registry/app.go +++ b/registry/app.go @@ -227,7 +227,8 @@ func (app *App) dispatcher(dispatch dispatchFunc) http.Handler { // 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)) handler := dispatch(context, r) ssrw := &singleStatusResponseWriter{ResponseWriter: w} @@ -276,9 +277,6 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont repo := getName(context) if app.accessController == nil { - // No access controller, so we simply provide access. - context.Repository = app.registry.Repository(repo) - return nil // access controller is not enabled. } @@ -357,12 +355,11 @@ func (app *App) authorized(w http.ResponseWriter, r *http.Request, context *Cont return err } + // 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 - // 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 } diff --git a/storage/blobstore.go b/storage/blobstore.go index 04d247ff..ac123f44 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 2a551694..c7d64b79 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 7dd7e2ac..b6578792 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 0c69e30d..54860913 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 f84a0208..1f798dde 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 15bf27be..8284ce94 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 17af8b15..30d3f43f 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 b1e20eec..ed865007 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 cfb8c787..7e6ac476 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.