MM-14574 Intercept log messages from local image proxy (#10668)

* MM-14574 Switch willnorris/imageproxy to fork

* MM-14574 Intercept log messages from local image proxy

* Revert "MM-14574 Switch willnorris/imageproxy to fork"

This reverts commit 046ab5c4216a5c6fee5bf8e2e0cceb1afffa6747.

* Update willnorris/imageproxy

app/server.go

@@ -167,7 +167,7 @@ func NewServer(options ...Option) (*Server, error) {
 
 	s.HTTPService = httpservice.MakeHTTPService(s.FakeApp())
 
-	s.ImageProxy = imageproxy.MakeImageProxy(s, s.HTTPService)
+	s.ImageProxy = imageproxy.MakeImageProxy(s, s.HTTPService, s.Log)
 
 	if err := utils.TranslationsPreInit(); err != nil {
 		return nil, errors.Wrapf(err, "unable to load Mattermost translation files")

go.mod

@@ -91,7 +91,7 @@ require (
 	gopkg.in/natefinch/lumberjack.v2 v2.0.0
 	gopkg.in/olivere/elastic.v5 v5.0.79
 	gopkg.in/yaml.v2 v2.2.2
-	willnorris.com/go/imageproxy v0.8.1-0.20190326225038-cf54b2cf2c9e
+	willnorris.com/go/imageproxy v0.8.1-0.20190326225038-d4246a08fdec
 )
 
 // Workaround for https://github.com/golang/go/issues/30831 and fallout.

go.sum

@@ -486,5 +486,5 @@ honnef.co/go/tools v0.0.0-20190102054323-c2f93a96b099/go.mod h1:rf3lG4BRIbNafJWh
 honnef.co/go/tools v0.0.0-20190106161140-3f1c8253044a/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 willnorris.com/go/gifresize v1.0.0 h1:GKS68zjNhHMqkgNTv4iFAO/j/sNcVSOHQ7SqmDAIAmM=
 willnorris.com/go/gifresize v1.0.0/go.mod h1:eBM8gogBGCcaH603vxSpnfjwXIpq6nmnj/jauBDKtAk=
-willnorris.com/go/imageproxy v0.8.1-0.20190326225038-cf54b2cf2c9e h1:YPJb3vEWw4G0MHzd0k+CoO6p+2AS08dzXGLg40KB0P4=
+willnorris.com/go/imageproxy v0.8.1-0.20190326225038-d4246a08fdec h1:fc1f9n+GkWqcDYXvirpYG+v4ymo+e02QXyBgKmxI7VQ=
-willnorris.com/go/imageproxy v0.8.1-0.20190326225038-cf54b2cf2c9e/go.mod h1:CKIesng3W4D4npJaypowqkxF33s3AH7EuohbR1miBGw=
+willnorris.com/go/imageproxy v0.8.1-0.20190326225038-d4246a08fdec/go.mod h1:CKIesng3W4D4npJaypowqkxF33s3AH7EuohbR1miBGw=

services/imageproxy/atmos_camo_test.go

@@ -32,7 +32,7 @@ func makeTestAtmosCamoProxy() *ImageProxy {
 		},
 	}
 
-	return MakeImageProxy(configService, httpservice.MakeHTTPService(configService))
+	return MakeImageProxy(configService, httpservice.MakeHTTPService(configService), nil)
 }
 
 func TestAtmosCamoBackend_GetImage(t *testing.T) {

services/imageproxy/imageproxy.go

@@ -9,6 +9,7 @@ import (
 	"net/http"
 	"sync"
 
+	"github.com/mattermost/mattermost-server/mlog"
 	"github.com/mattermost/mattermost-server/model"
 	"github.com/mattermost/mattermost-server/services/configservice"
 	"github.com/mattermost/mattermost-server/services/httpservice"
@@ -24,6 +25,8 @@ type ImageProxy struct {
 
 	HTTPService httpservice.HTTPService
 
+	Logger *mlog.Logger
+
 	lock    sync.RWMutex
 	backend ImageProxyBackend
 }
@@ -45,10 +48,11 @@ type ImageProxyBackend interface {
 	GetUnproxiedImageURL(proxiedURL string) string
 }
 
-func MakeImageProxy(configService configservice.ConfigService, httpService httpservice.HTTPService) *ImageProxy {
+func MakeImageProxy(configService configservice.ConfigService, httpService httpservice.HTTPService, logger *mlog.Logger) *ImageProxy {
 	proxy := &ImageProxy{
 		ConfigService: configService,
 		HTTPService:   httpService,
+		Logger:        logger,
 	}
 
 	proxy.configListenerId = proxy.ConfigService.AddConfigListener(proxy.OnConfigChange)

services/imageproxy/local.go

@@ -43,6 +43,15 @@ type LocalBackend struct {
 func makeLocalBackend(proxy *ImageProxy) *LocalBackend {
 	impl := imageproxy.NewProxy(proxy.HTTPService.MakeTransport(false), nil)
 
+	if proxy.Logger != nil {
+		logger, err := proxy.Logger.StdLogAt(mlog.LevelDebug, mlog.String("image_proxy", "local"))
+		if err != nil {
+			mlog.Error("Failed to initialize logger for image proxy", mlog.Err(err))
+		}
+
+		impl.Logger = logger
+	}
+
 	baseURL, err := url.Parse(*proxy.ConfigService.Config().ServiceSettings.SiteURL)
 	if err != nil {
 		mlog.Error("Failed to set base URL for image proxy. Relative image links may not work.", mlog.Err(err))

services/imageproxy/local_test.go

@@ -31,7 +31,7 @@ func makeTestLocalProxy() *ImageProxy {
 		},
 	}
 
-	return MakeImageProxy(configService, httpservice.MakeHTTPService(configService))
+	return MakeImageProxy(configService, httpservice.MakeHTTPService(configService), nil)
 }
 
 func TestLocalBackend_GetImage(t *testing.T) {

vendor/modules.txt

@@ -359,6 +359,6 @@ gopkg.in/olivere/elastic.v5/uritemplates
 gopkg.in/yaml.v2
 # willnorris.com/go/gifresize v1.0.0
 willnorris.com/go/gifresize
-# willnorris.com/go/imageproxy v0.8.1-0.20190326225038-cf54b2cf2c9e
+# willnorris.com/go/imageproxy v0.8.1-0.20190326225038-d4246a08fdec
 willnorris.com/go/imageproxy
 willnorris.com/go/imageproxy/third_party/http

vendor/willnorris.com/go/imageproxy/CHANGELOG.md

@@ -10,6 +10,16 @@ adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
 ### Changed
  - updated docker image to use go1.12 compiler and build imageproxy as a go module.
 
+ - options are now sorted when converting to string.  This is a breaking change
+   for anyone relying on the option order, and will additionally invalidate
+   most cached values, since the option string is part of the cache key.
+
+   Both the original remote image, as well as any transformations on that image
+   are cached, but only the transformed images will be impacted by this change.
+   This will result in imageproxy having to re-perform the transformations, but
+   should not result in re-fetching the remote image, unless it has already
+   otherwise expired.
+
 ### Removed
  - removed deprecated `whitelist` flag and `Proxy.Whitelist` struct field. Use
    `allowHosts` and `Proxy.AllowHosts` instead.

vendor/willnorris.com/go/imageproxy/data.go

@@ -19,6 +19,7 @@ import (
 	"net/http"
 	"net/url"
 	"regexp"
+	"sort"
 	"strconv"
 	"strings"
 )
@@ -133,6 +134,7 @@ func (o Options) String() string {
 	if o.SmartCrop {
 		opts = append(opts, optSmartCrop)
 	}
+	sort.Strings(opts)
 	return strings.Join(opts, ",")
 }
 

vendor/willnorris.com/go/imageproxy/imageproxy.go

@@ -61,6 +61,9 @@ type Proxy struct {
 	// absolute.
 	DefaultBaseURL *url.URL
 
+	// The Logger used by the image proxy
+	Logger *log.Logger
+
 	// SignatureKey is the HMAC key used to verify signed requests.
 	SignatureKey []byte
 
@@ -105,7 +108,7 @@ func NewProxy(transport http.RoundTripper, cache Cache) *Proxy {
 			CachingClient: client,
 			log: func(format string, v ...interface{}) {
 				if proxy.Verbose {
-					log.Printf(format, v...)
+					proxy.logf(format, v...)
 				}
 			},
 		},
@@ -141,20 +144,20 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) {
 	req, err := NewRequest(r, p.DefaultBaseURL)
 	if err != nil {
 		msg := fmt.Sprintf("invalid request URL: %v", err)
-		log.Print(msg)
+		p.log(msg)
 		http.Error(w, msg, http.StatusBadRequest)
 		return
 	}
 
+	if err := p.allowed(req); err != nil {
+		p.logf("%s: %v", err, req)
+		http.Error(w, msgNotAllowed, http.StatusForbidden)
+		return
+	}
+
 	// assign static settings from proxy to req.Options
 	req.Options.ScaleUp = p.ScaleUp
 
-	if err := p.allowed(req); err != nil {
-		log.Printf("%s: %v", err, req)
-		http.Error(w, msgNotAllowed, http.StatusForbidden)
-		return
-	}
-
 	actualReq, _ := http.NewRequest("GET", req.String(), nil)
 	if p.UserAgent != "" {
 		actualReq.Header.Set("User-Agent", p.UserAgent)
@@ -166,7 +169,7 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) {
 
 	if err != nil {
 		msg := fmt.Sprintf("error fetching remote image: %v", err)
-		log.Print(msg)
+		p.log(msg)
 		http.Error(w, msg, http.StatusInternalServerError)
 		return
 	}
@@ -175,7 +178,7 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) {
 
 	cached := resp.Header.Get(httpcache.XFromCache)
 	if p.Verbose {
-		log.Printf("request: %+v (served from cache: %t)", *actualReq, cached == "1")
+		p.logf("request: %+v (served from cache: %t)", *actualReq, cached == "1")
 	}
 
 	copyHeader(w.Header(), resp.Header, "Cache-Control", "Last-Modified", "Expires", "Etag", "Link")
@@ -193,7 +196,7 @@ func (p *Proxy) serveImage(w http.ResponseWriter, r *http.Request) {
 		contentType = peekContentType(b)
 	}
 	if resp.ContentLength != 0 && !contentTypeMatches(p.ContentTypes, contentType) {
-		log.Printf("content-type not allowed: %q", contentType)
+		p.logf("content-type not allowed: %q", contentType)
 		http.Error(w, msgNotAllowed, http.StatusForbidden)
 		return
 	}
@@ -322,10 +325,22 @@ func validSignature(key []byte, r *Request) bool {
 		return false
 	}
 
+	// check signature with URL only
 	mac := hmac.New(sha256.New, key)
 	mac.Write([]byte(r.URL.String()))
 	want := mac.Sum(nil)
+	if hmac.Equal(got, want) {
+		return true
+	}
 
+	// check signature with URL and options
+	u, opt := *r.URL, r.Options // make copies
+	opt.Signature = ""
+	u.Fragment = opt.String()
+
+	mac = hmac.New(sha256.New, key)
+	mac.Write([]byte(u.String()))
+	want = mac.Sum(nil)
 	return hmac.Equal(got, want)
 }
 
@@ -356,6 +371,22 @@ func should304(req *http.Request, resp *http.Response) bool {
 	return false
 }
 
+func (p *Proxy) log(v ...interface{}) {
+	if p.Logger != nil {
+		p.Logger.Print(v...)
+	} else {
+		log.Print(v...)
+	}
+}
+
+func (p *Proxy) logf(format string, v ...interface{}) {
+	if p.Logger != nil {
+		p.Logger.Printf(format, v...)
+	} else {
+		log.Printf(format, v...)
+	}
+}
+
 // TransformingTransport is an implementation of http.RoundTripper that
 // optionally transforms images using the options specified in the request URL
 // fragment.