Added logging to constructor and enforcer (#10)

* Added logging to constructor and enforcer

* Changes from code review

* Added log level

* Added nil logger check

bascule/basculehttp/constructor.go

@@ -1,11 +1,13 @@
 package basculehttp
 
 import (
+	"context"
 	"net/http"
 	"net/textproto"
 	"strings"
 
 	"github.com/Comcast/comcast-bascule/bascule"
+	"github.com/go-kit/kit/log/level"
 )
 
 const (
@@ -15,18 +17,26 @@ const (
 type constructor struct {
 	headerName     string
 	authorizations map[bascule.Authorization]TokenFactory
+	getLogger      func(context.Context) bascule.Logger
 }
 
 func (c *constructor) decorate(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(response http.ResponseWriter, request *http.Request) {
+		logger := c.getLogger(request.Context())
+		if logger == nil {
+			logger = bascule.GetDefaultLoggerFunc(request.Context())
+		}
 		authorization := request.Header.Get(c.headerName)
 		if len(authorization) == 0 {
+			logger.Log(level.Key(), level.ErrorValue(), bascule.ErrorKey, "no authorization header", "request", request)
 			response.WriteHeader(http.StatusForbidden)
 			return
 		}
 
 		i := strings.IndexByte(authorization, ' ')
 		if i < 1 {
+			logger.Log(level.Key(), level.ErrorValue(), bascule.ErrorKey, "unexpected authorization header value",
+				"request", request, "auth", authorization)
 			response.WriteHeader(http.StatusBadRequest)
 			return
 		}
@@ -37,13 +47,17 @@ func (c *constructor) decorate(next http.Handler) http.Handler {
 
 		tf, supported := c.authorizations[key]
 		if !supported {
+			logger.Log(level.Key(), level.ErrorValue(), bascule.ErrorKey, "key not supported", "request", request,
+				"key", key, "auth", authorization[i+1:])
 			response.WriteHeader(http.StatusForbidden)
 			return
 		}
 
 		ctx := request.Context()
 		token, err := tf.ParseAndValidate(ctx, request, key, authorization[i+1:])
 		if err != nil {
+			logger.Log(level.Key(), level.ErrorValue(), bascule.ErrorKey, err.Error(), "request", request,
+				"key", key, "auth", authorization[i+1:])
 			WriteResponse(response, http.StatusUnauthorized, err)
 			return
 		}
@@ -55,6 +69,8 @@ func (c *constructor) decorate(next http.Handler) http.Handler {
 				Token:         token,
 			},
 		)
+		logger.Log(level.Key(), level.DebugValue(), "msg", "authentication added to context", "request", request,
+			"token", token, "key", key)
 
 		next.ServeHTTP(response, request.WithContext(ctx))
 	})
@@ -78,11 +94,18 @@ func WithTokenFactory(key bascule.Authorization, tf TokenFactory) COption {
 	}
 }
 
+func WithCLogger(getLogger func(context.Context) bascule.Logger) COption {
+	return func(c *constructor) {
+		c.getLogger = getLogger
+	}
+}
+
 // New returns an Alice-style constructor which decorates HTTP handlers with security code
 func NewConstructor(options ...COption) func(http.Handler) http.Handler {
 	c := &constructor{
 		headerName:     DefaultHeaderName,
 		authorizations: make(map[bascule.Authorization]TokenFactory),
+		getLogger:      bascule.GetDefaultLoggerFunc,
 	}
 
 	for _, o := range options {

bascule/basculehttp/enforcer.go

@@ -1,9 +1,11 @@
 package basculehttp
 
 import (
+	"context"
 	"net/http"
 
 	"github.com/Comcast/comcast-bascule/bascule"
+	"github.com/go-kit/kit/log/level"
 )
 
 //go:generate stringer -type=NotFoundBehavior
@@ -19,18 +21,27 @@ const (
 type enforcer struct {
 	notFoundBehavior NotFoundBehavior
 	rules            map[bascule.Authorization]bascule.Validators
+	getLogger        func(context.Context) bascule.Logger
 }
 
 func (e *enforcer) decorate(next http.Handler) http.Handler {
 	return http.HandlerFunc(func(response http.ResponseWriter, request *http.Request) {
 		ctx := request.Context()
+		logger := e.getLogger(ctx)
+		if logger == nil {
+			logger = bascule.GetDefaultLoggerFunc(ctx)
+		}
 		auth, ok := bascule.FromContext(ctx)
 		if !ok {
+			logger.Log(level.Key(), level.ErrorValue(), bascule.ErrorKey, "no authentication found",
+				"request", request)
 			response.WriteHeader(http.StatusForbidden)
 			return
 		}
 		rules, ok := e.rules[auth.Authorization]
 		if !ok {
+			logger.Log(level.Key(), level.ErrorValue(),
+				bascule.ErrorKey, "no rules found for authorization", "request", request)
 			switch e.notFoundBehavior {
 			case Forbid:
 				response.WriteHeader(http.StatusForbidden)
@@ -44,10 +55,20 @@ func (e *enforcer) decorate(next http.Handler) http.Handler {
 		} else {
 			err := rules.Check(ctx, auth.Token)
 			if err != nil {
+				errs := []string{err.Error()}
+				if es, ok := err.(bascule.Errors); ok {
+					for _, e := range es {
+						errs = append(errs, e.Error())
+					}
+				}
+				logger.Log(level.Key(), level.ErrorValue(), bascule.ErrorKey, errs,
+					"request", request)
 				WriteResponse(response, http.StatusUnauthorized, err)
 				return
 			}
 		}
+		logger.Log(level.Key(), level.DebugValue(), "msg", "authentication accepted by enforcer",
+			"request", request)
 		next.ServeHTTP(response, request)
 	})
 }
@@ -66,9 +87,16 @@ func WithRules(key bascule.Authorization, v bascule.Validators) EOption {
 	}
 }
 
+func WithELogger(getLogger func(context.Context) bascule.Logger) EOption {
+	return func(e *enforcer) {
+		e.getLogger = getLogger
+	}
+}
+
 func NewEnforcer(options ...EOption) func(http.Handler) http.Handler {
 	e := &enforcer{
-		rules: make(map[bascule.Authorization]bascule.Validators),
+		rules:     make(map[bascule.Authorization]bascule.Validators),
+		getLogger: bascule.GetDefaultLoggerFunc,
 	}
 
 	for _, o := range options {

bascule/log.go

@@ -0,0 +1,26 @@
+package bascule
+
+import (
+	"context"
+
+	"github.com/go-kit/kit/log"
+)
+
+var (
+	defaultLogger = log.NewNopLogger()
+
+	ErrorKey interface{} = "error"
+)
+
+// logger we expect for the decorators
+type Logger interface {
+	Log(keyvals ...interface{}) error
+}
+
+func NewDefaultLogger() Logger {
+	return defaultLogger
+}
+
+func GetDefaultLoggerFunc(ctx context.Context) Logger {
+	return NewDefaultLogger()
+}

go.mod

@@ -3,18 +3,13 @@ module github.com/Comcast/comcast-bascule
 go 1.12
 
 require (
-	github.com/Comcast/codex v0.2.7 // indirect
 	github.com/Comcast/webpa-common v0.0.0-20190312224005-400bb4f8fc50
 	github.com/SermoDigital/jose v0.9.2-0.20161205224733-f6df55f235c2
-	github.com/c9s/goprocinfo v0.0.0-20190309065803-0b2ad9ac246b // indirect
-	github.com/erikstmartin/go-testdb v0.0.0-20160219214506-8d10e4a1bae5 // indirect
+	github.com/davecgh/go-spew v1.1.1 // indirect
+	github.com/go-kit/kit v0.8.0
+	github.com/go-logfmt/logfmt v0.4.0 // indirect
 	github.com/go-stack/stack v1.8.0 // indirect
-	github.com/gofrs/uuid v3.2.0+incompatible // indirect
-	github.com/jinzhu/now v1.0.0 // indirect
 	github.com/jtacoma/uritemplates v1.0.0 // indirect
-	github.com/justinas/alice v0.0.0-20171023064455-03f45bd4b7da // indirect
-	github.com/mattn/go-sqlite3 v1.10.0 // indirect
+	github.com/stretchr/objx v0.1.1 // indirect
 	github.com/stretchr/testify v1.3.0
-	github.com/ugorji/go v1.1.2-0.20181022190402-e5e69e061d4f // indirect
-	github.com/ugorji/go/codec v1.1.2-0.20181022190402-e5e69e061d4f // indirect
 )