diff --git a/changelog/unreleased/proxy-access-log.md b/changelog/unreleased/proxy-access-log.md new file mode 100644 index 0000000000..967082c820 --- /dev/null +++ b/changelog/unreleased/proxy-access-log.md @@ -0,0 +1,5 @@ +Bugfix: log all requests in the proxy access log + +We now use a dedicated middleware to log all requests, regardless of routing selector outcome. The log now includes the remote address and the selected routing policy. + +https://github.com/owncloud/ocis/pull/2301 diff --git a/ocis-pkg/middleware/logger.go b/ocis-pkg/middleware/logger.go index 66a71a5ad4..dad3836f75 100644 --- a/ocis-pkg/middleware/logger.go +++ b/ocis-pkg/middleware/logger.go @@ -8,7 +8,7 @@ import ( "github.com/owncloud/ocis/ocis-pkg/log" ) -// Logger is a middleware to log http requests. +// Logger is a middleware to log http requests. It uses debug level logging and should be used by all services save the proxy (which uses info level logging). func Logger(logger log.Logger) func(http.Handler) http.Handler { return func(next http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { diff --git a/proxy/go.mod b/proxy/go.mod index d12624cf6a..7b0d54d6b2 100644 --- a/proxy/go.mod +++ b/proxy/go.mod @@ -12,6 +12,7 @@ require ( github.com/cs3org/go-cs3apis v0.0.0-20210702091910-85a56bfd027f github.com/cs3org/reva v1.10.0 github.com/dgrijalva/jwt-go v3.2.0+incompatible + github.com/go-chi/chi v4.1.2+incompatible github.com/justinas/alice v1.2.0 github.com/micro/cli/v2 v2.1.2 github.com/oklog/run v1.1.0 @@ -30,6 +31,7 @@ require ( golang.org/x/crypto v0.0.0-20201221181555-eec23a3978ad golang.org/x/oauth2 v0.0.0-20210402161424-2e8d93401602 google.golang.org/grpc v1.39.0 + google.golang.org/grpc/examples v0.0.0-20210712234202-ebfe3be62a82 // indirect ) replace ( diff --git a/proxy/go.sum b/proxy/go.sum index f827db55e3..d4dceeafd4 100644 --- a/proxy/go.sum +++ b/proxy/go.sum @@ -299,12 +299,9 @@ github.com/cs3org/go-cs3apis v0.0.0-20210325133324-32b03d75a535/go.mod h1:UXha4T github.com/cs3org/go-cs3apis v0.0.0-20210702091910-85a56bfd027f h1:l09QSEPO8DI3V2hBnc6KhTsrNg/DTyBYjCTwSb/HR6Q= github.com/cs3org/go-cs3apis v0.0.0-20210702091910-85a56bfd027f/go.mod h1:UXha4TguuB52H14EMoSsCqDj7k8a/t7g4gVP+bgY5LY= github.com/cs3org/reva v1.6.1-0.20210329145723-ed244aac4ddc/go.mod h1:exwJqEJ8lVVnmdY0GrGwuPRQ018xUU9mKVXQBiO0ZlQ= -github.com/cs3org/reva v1.9.1 h1:M1LrYRo0mRk/wAxapqzd7jieGarIA7p6R+rxRbqJrGs= -github.com/cs3org/reva v1.9.1/go.mod h1:4bpcovnx3EAetafPIp4Fia1GkFvjFDkztacmCWI7cN0= github.com/cs3org/reva v1.10.0 h1:8sne7z4pe+9rkGP3ZX2i3Sx1FMQ8hhBs5QCb4VVvZJI= github.com/cs3org/reva v1.10.0/go.mod h1:4bpcovnx3EAetafPIp4Fia1GkFvjFDkztacmCWI7cN0= github.com/cucumber/godog v0.8.1/go.mod h1:vSh3r/lM+psC1BPXvdkSEuNjmXfpVqrMGYAElF6hxnA= -github.com/cznic/b v0.0.0-20181122101859-a26611c4d92d/go.mod h1:URriBxXwVq5ijiJ12C7iIZqlA69nTlI+LgI6/pwftG8= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= @@ -912,7 +909,6 @@ github.com/jinzhu/copier v0.0.0-20190924061706-b57f9002281a/go.mod h1:yL958EeXv8 github.com/jmespath/go-jmespath v0.0.0-20180206201540-c2b33e8439af/go.mod h1:Nht3zPeWKUH0NzdCt2Blrr5ys8VGpn0CEB0cQHVjt7k= github.com/jmespath/go-jmespath v0.4.0/go.mod h1:T8mJZnbsbmF+m6zOOFylbeCJqk5+pHWvzYPziyZiYoo= github.com/jmespath/go-jmespath/internal/testify v1.5.1/go.mod h1:L3OGu8Wl2/fWfCI6z80xFu9LTZmf1ZRjMHUOPmWr69U= -github.com/jmhodges/levigo v1.0.0/go.mod h1:Q6Qx+uH3RAqyK4rFQroq9RL7mdkABMcfhEI+nNuzMJQ= github.com/jmoiron/sqlx v0.0.0-20180614180643-0dae4fefe7c0/go.mod h1:IiEW3SEiiErVyFdH8NTuWjSifiEQKUoyK3LNqr2kCHU= github.com/jmoiron/sqlx v1.2.0/go.mod h1:1FEQNm3xlJgrMD+FBdI9+xvCksHtbpVBBw5dYhBSsks= github.com/joeshaw/multierror v0.0.0-20140124173710-69b34d4ec901/go.mod h1:Z86h9688Y0wesXCyonoVr47MasHilkuLMqGhRZ4Hpak= @@ -1510,7 +1506,6 @@ github.com/subosito/gotenv v1.2.0/go.mod h1:N0PQaV/YGNqwC0u51sEeR/aUtSLEXKX9iv69 github.com/syndtr/gocapability v0.0.0-20170704070218-db04d3cc01c8/go.mod h1:hkRG7XYTFWNJGYcbNJQlaLq0fg1yr4J4t/NcTQtrfww= github.com/syndtr/goleveldb v1.0.0/go.mod h1:ZVVdQEZoIme9iO1Ch2Jdy24qqXrMMOU6lpPAyBWyWuQ= github.com/tarm/serial v0.0.0-20180830185346-98f6abe2eb07/go.mod h1:kDXzergiv9cbyO7IOYJZWg1U88JhDg3PB6klq9Hg2pA= -github.com/tecbot/gorocksdb v0.0.0-20191217155057-f0fad39f321c/go.mod h1:ahpPrc7HpcfEWDQRZEmnXMzHY03mLDYMCxeDzy46i+8= github.com/technoweenie/multipartstreamer v1.0.1/go.mod h1:jNVxdtShOxzAsukZwTSw6MDx5eUJoiEBsSvzDU9uzog= github.com/thejerf/suture/v4 v4.0.0 h1:GX3X+1Qaewtj9flL2wgoTBfLA5NcmrCY39TJRpPbUrI= github.com/thejerf/suture/v4 v4.0.0/go.mod h1:g0e8vwskm9tI0jRjxrnA6lSr0q6OfPdWJVX7G5bVWRs= @@ -2157,8 +2152,8 @@ google.golang.org/grpc v1.36.1/go.mod h1:qjiiYl8FncCW8feJPdyg3v6XW24KsRHe+dy9BAG google.golang.org/grpc v1.39.0 h1:Klz8I9kdtkIN6EpHHUOMLCYhTn/2WAe5a0s1hcBkdTI= google.golang.org/grpc v1.39.0/go.mod h1:PImNr+rS9TWYb2O4/emRugxiyHZ5JyHW5F+RPnDzfrE= google.golang.org/grpc/cmd/protoc-gen-go-grpc v1.0.0/go.mod h1:6Kw0yEErY5E/yWrBtf03jp27GLLJujG4z/JK95pnjjw= -google.golang.org/grpc/examples v0.0.0-20210708170655-30dfb4b933a5 h1:/nNpSw+ljz9YA+pnTWpmAkpasLbp9ei8kc94UVon31c= -google.golang.org/grpc/examples v0.0.0-20210708170655-30dfb4b933a5/go.mod h1:bF8wuZSAZTcbF7ZPKrDI/qY52toTP/yxLpRRY4Eu9Js= +google.golang.org/grpc/examples v0.0.0-20210712234202-ebfe3be62a82 h1:9iXqYJAPd7mfU5KwIFmRQQGLDBr+NxzBfHzUabiKLNA= +google.golang.org/grpc/examples v0.0.0-20210712234202-ebfe3be62a82/go.mod h1:bF8wuZSAZTcbF7ZPKrDI/qY52toTP/yxLpRRY4Eu9Js= google.golang.org/protobuf v0.0.0-20200109180630-ec00e32a8dfd/go.mod h1:DFci5gLYBciE7Vtevhsrf46CRTquxDuWsQurQQe4oz8= google.golang.org/protobuf v0.0.0-20200221191635-4d8936d0db64/go.mod h1:kwYJMbMJ01Woi6D6+Kah6886xMZcty6N08ah7+eCXa0= google.golang.org/protobuf v0.0.0-20200228230310-ab0ca4ff8a60/go.mod h1:cfTl7dwQJ+fmap5saPgwCLgHXTUD7jkjRqWcaiX5VyM= diff --git a/proxy/pkg/command/server.go b/proxy/pkg/command/server.go index 1b9b231957..797c36d74b 100644 --- a/proxy/pkg/command/server.go +++ b/proxy/pkg/command/server.go @@ -15,6 +15,7 @@ import ( acc "github.com/owncloud/ocis/accounts/pkg/proto/v0" "github.com/owncloud/ocis/ocis-pkg/conversions" "github.com/owncloud/ocis/ocis-pkg/log" + pkgmiddleware "github.com/owncloud/ocis/ocis-pkg/middleware" "github.com/owncloud/ocis/ocis-pkg/service/grpc" "github.com/owncloud/ocis/ocis-pkg/sync" "github.com/owncloud/ocis/proxy/pkg/config" @@ -176,7 +177,13 @@ func loadMiddlewares(ctx context.Context, l log.Logger, cfg *config.Config) alic } return alice.New( + // first make sure we log all requests and redirect to https if necessary + pkgmiddleware.RealIP, + pkgmiddleware.RequestID, + middleware.AccessLog(l), middleware.HTTPSRedirect, + + // now that we established the basics, on with authentication middleware middleware.Authentication( // OIDC Options middleware.OIDCProviderFunc(func() (middleware.OIDCProvider, error) { @@ -211,6 +218,8 @@ func loadMiddlewares(ctx context.Context, l log.Logger, cfg *config.Config) alic middleware.TokenManagerConfig(cfg.TokenManager), middleware.AutoprovisionAccounts(cfg.AutoprovisionAccounts), ), + + // finally, trigger home creation when a user logs in middleware.CreateHome( middleware.Logger(l), middleware.TokenManagerConfig(cfg.TokenManager), diff --git a/proxy/pkg/middleware/accesslog.go b/proxy/pkg/middleware/accesslog.go new file mode 100644 index 0000000000..63e27e0bc9 --- /dev/null +++ b/proxy/pkg/middleware/accesslog.go @@ -0,0 +1,33 @@ +package middleware + +import ( + "net/http" + "time" + + "github.com/go-chi/chi/middleware" + "github.com/owncloud/ocis/ocis-pkg/log" + "github.com/owncloud/ocis/proxy/pkg/proxy/policy" +) + +// AccessLog is a middleware to log http requests at info level logging. +func AccessLog(logger log.Logger) func(http.Handler) http.Handler { + return func(next http.Handler) http.Handler { + return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + start := time.Now() + wrap := middleware.NewWrapResponseWriter(w, r.ProtoMajor) + next.ServeHTTP(wrap, r) + + logger.Info(). + Str("proto", r.Proto). + Str("request", r.Header.Get("X-Request-ID")). + Str("remote-addr", r.RemoteAddr). + Str("method", r.Method). + Str("routing-policy", policy.ContextGetPolicy(r.Context())). + Int("status", wrap.Status()). + Str("path", r.URL.Path). + Dur("duration", time.Since(start)). + Int("bytes", wrap.BytesWritten()). + Msg("access-log") + }) + } +} diff --git a/proxy/pkg/proxy/policy/selector.go b/proxy/pkg/proxy/policy/selector.go index aa33b6410b..083637963e 100644 --- a/proxy/pkg/proxy/policy/selector.go +++ b/proxy/pkg/proxy/policy/selector.go @@ -20,6 +20,20 @@ var ( ErrUnexpectedConfigError = fmt.Errorf("could not initialize policy-selector for given config") ) +// policyKey serves as key for the routing policy in the context +var policyKey struct{} + +// ContextGetPolicy returns the policy if set in the given context. +func ContextGetPolicy(ctx context.Context) string { + u, _ := ctx.Value(policyKey).(string) + return u +} + +// ContextSetPolicy stores the selected policy in the context. +func ContextSetPolicy(ctx context.Context, p string) context.Context { + return context.WithValue(ctx, policyKey, p) +} + // Selector is a function which selects a proxy-policy based on the request. // // A policy is a random name which identifies a set of proxy-routes: diff --git a/proxy/pkg/proxy/proxy.go b/proxy/pkg/proxy/proxy.go index fa5fe5ea24..d2eb4cd8a2 100644 --- a/proxy/pkg/proxy/proxy.go +++ b/proxy/pkg/proxy/proxy.go @@ -146,12 +146,7 @@ func (p *MultiHostReverseProxy) directorSelectionDirector(r *http.Request) { Str("routeType", string(rt)). Msg("director found") - p.logger.Info(). - Str("method", r.Method). - Str("path", r.Method). - Str("from", r.RemoteAddr). - Msg("access-log") - + r = r.WithContext(policy.ContextSetPolicy(r.Context(), pol)) p.Directors[pol][rt][endpoint](r) return }