// Copyright (c) 2021 Gitpod GmbH. All rights reserved. // Licensed under the GNU Affero General Public License (AGPL). // See License.AGPL.txt in the project root for license information. package pkg import ( "context" "fmt" "math/rand" "net/http" "net/http/httputil" "strconv" "time" "github.com/gitpod-io/gitpod/common-go/log" "github.com/google/uuid" "github.com/sirupsen/logrus" ) func (o *OpenVSXProxy) Handler(p *httputil.ReverseProxy) func(http.ResponseWriter, *http.Request) { return func(rw http.ResponseWriter, r *http.Request) { start := time.Now() var ( hitCacheRegular = false hitCacheBackup = false ) reqid := "" uuid, err := uuid.NewRandom() if err != nil { log.WithError(err).Warn("cannot generate a UUID") reqid = fmt.Sprintf("req%d", rand.Intn(999999)) } else { reqid = uuid.String() } logFields := logrus.Fields{ LOG_FIELD_FUNC: "request_handler", LOG_FIELD_REQUEST_ID: reqid, LOG_FIELD_REQUEST: fmt.Sprintf("%s %s", r.Method, r.URL), "request_content_length": strconv.FormatInt(r.ContentLength, 10), } log.WithFields(logFields).Debug("handling request") r = r.WithContext(context.WithValue(r.Context(), REQUEST_ID_CTX, reqid)) upstream := o.GetUpstreamUrl(r) r = r.WithContext(context.WithValue(r.Context(), UPSTREAM_CTX, upstream)) if o.IsDisabledCache(upstream) { log.WithFields(logFields).WithField("upstream", upstream.String()).Debug("go without cache") p.ServeHTTP(rw, r) o.finishLog(logFields, start, false, false) o.metrics.DurationRequestProcessingHistogram.Observe(time.Since(start).Seconds()) return } key, err := o.key(r) if err != nil { log.WithFields(logFields).WithError(err).Error("cannot create cache key") p.ServeHTTP(rw, r) o.finishLog(logFields, start, hitCacheRegular, hitCacheBackup) o.metrics.DurationRequestProcessingHistogram.Observe(time.Since(start).Seconds()) return } r = r.WithContext(context.WithValue(r.Context(), REQUEST_CACHE_KEY_CTX, key)) logFields[LOG_FIELD_REQUEST] = key if o.Config.CacheDurationRegular > 0 { cached, ok, err := o.ReadCache(key) if err != nil { log.WithFields(logFields).WithError(err).Error("cannot read from cache") } else if !ok { log.WithFields(logFields).Debug("cache has no entry for key") } else { hitCacheBackup = true dateHeader := cached.Header.Get("Date") log.WithFields(logFields).Debugf("there is a cached value with date: %s", dateHeader) t, err := time.Parse("Mon, _2 Jan 2006 15:04:05 MST", dateHeader) if err != nil { log.WithFields(logFields).WithError(err).Warn("cannot parse date header of cached value") } else { minDate := time.Now().Add(-time.Duration(o.Config.CacheDurationRegular)) if t.After(minDate) { hitCacheRegular = true log.WithFields(logFields).Debugf("cached value is younger than %s - using cached value", o.Config.CacheDurationRegular) for k, v := range cached.Header { for i, val := range v { if i == 0 { rw.Header().Set(k, val) } else { rw.Header().Add(k, val) } } } if v := rw.Header().Get("Access-Control-Allow-Origin"); v != "" && v != "*" { rw.Header().Set("Access-Control-Allow-Origin", r.Header.Get("Origin")) } rw.Header().Set("X-Cache", "HIT") rw.WriteHeader(cached.StatusCode) rw.Write(cached.Body) o.finishLog(logFields, start, hitCacheRegular, hitCacheBackup) o.metrics.DurationRequestProcessingHistogram.Observe(time.Since(start).Seconds()) return } else { log.WithFields(logFields).Debugf("cached value is older than %s - ignoring cached value", o.Config.CacheDurationRegular) } } } } duration := time.Since(start) log.WithFields(logFields).WithFields(o.DurationLogFields(duration)).Debug("processing request finished") o.metrics.DurationRequestProcessingHistogram.Observe(duration.Seconds()) p.ServeHTTP(rw, r) o.finishLog(logFields, start, hitCacheRegular, hitCacheBackup) } } func (o *OpenVSXProxy) finishLog(logFields logrus.Fields, start time.Time, hitCacheRegular, hitCacheBackup bool) { duration := time.Since(start) o.metrics.DurationOverallHistogram.Observe(duration.Seconds()) if hitCacheBackup { o.metrics.BackupCacheHitCounter.Inc() } else { o.metrics.BackupCacheMissCounter.Inc() } if hitCacheRegular { o.metrics.RegularCacheHitServeCounter.Inc() } else { o.metrics.RegularCacheMissCounter.Inc() } log. WithFields(logFields). WithFields(o.DurationLogFields(duration)). WithField("hit_cache_regular", hitCacheRegular). WithField("hit_cache_backup", hitCacheBackup). Info("request finished") }