Skip to content

Commit

Permalink
internal/middleware,etc.: store requests
Browse files Browse the repository at this point in the history
This CL provides several improvements to the worker home page:

- Display all requests, not just fetches.

- Link to the logs for each request.

- Link that will cancel a request.

At the heart of these changes is a new piece of middleware that tracks
all active requests, along with their trace ID and a function that
can be used to cancel them.

This change also affects logging, because the logger doesn't need to
maintain its own trace ID.

Change-Id: Id022170073d2d7ca4e45aaa1d78b216d8a512f35
Reviewed-on: https://go-review.googlesource.com/c/pkgsite/+/568236
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Michael Matloob <matloob@golang.org>
kokoro-CI: kokoro <noreply+kokoro@google.com>
  • Loading branch information
jba committed Mar 1, 2024
1 parent d223bbd commit df601fe
Show file tree
Hide file tree
Showing 14 changed files with 244 additions and 52 deletions.
1 change: 1 addition & 0 deletions cmd/frontend/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -218,6 +218,7 @@ func main() {
ermw = middleware.ErrorReporting(reporter)
}
mw := middleware.Chain(
middleware.RequestInfo(),
middleware.RequestLog(cmdconfig.Logger(ctx, cfg, "frontend-log")),
middleware.AcceptRequests(http.MethodGet, http.MethodPost, http.MethodHead), // accept only GETs, POSTs and HEADs
middleware.BetaPkgGoDevRedirect(),
Expand Down
1 change: 1 addition & 0 deletions cmd/worker/main.go
Original file line number Diff line number Diff line change
Expand Up @@ -143,6 +143,7 @@ func main() {
}

mw := middleware.Chain(
middleware.RequestInfo(), // must be first
middleware.RequestLog(cmdconfig.Logger(ctx, cfg, "worker-log")),
mtimeout.Timeout(time.Duration(timeout)*time.Minute),
iap,
Expand Down
1 change: 1 addition & 0 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -28,6 +28,7 @@ require (
github.com/lib/pq v1.10.9
github.com/russross/blackfriday/v2 v2.1.0
go.opencensus.io v0.24.0
golang.org/x/exp v0.0.0-20240222234643-814bf88cf225
golang.org/x/mod v0.15.0
golang.org/x/net v0.21.0
golang.org/x/sync v0.6.0
Expand Down
2 changes: 2 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -1116,6 +1116,8 @@ golang.org/x/exp v0.0.0-20191227195350-da58074b4299/go.mod h1:2RIsYlXP63K8oxa1u0
golang.org/x/exp v0.0.0-20200119233911-0405dc783f0a/go.mod h1:2RIsYlXP63K8oxa1u096TMicItID8zy7Y6sNkU49FU4=
golang.org/x/exp v0.0.0-20200207192155-f17229e696bd/go.mod h1:J/WKrq2StrnmMY6+EHIKF9dgMWnmCNThgcyBT1FY9mM=
golang.org/x/exp v0.0.0-20200224162631-6cc2880d07d6/go.mod h1:3jZMyOhIsHpP37uCMkUooju7aAi5cS1Q23tOzKc+0MU=
golang.org/x/exp v0.0.0-20240222234643-814bf88cf225 h1:LfspQV/FYTatPTr/3HzIcmiUFH7PGP+OQ6mgDYo3yuQ=
golang.org/x/exp v0.0.0-20240222234643-814bf88cf225/go.mod h1:CxmFvTBINI24O/j8iY7H1xHzx2i4OsyguNBmN/uPtqc=
golang.org/x/image v0.0.0-20180708004352-c73c2afc3b81/go.mod h1:ux5Hcp/YLpHSI86hEcLt0YII63i6oz57MZXIpbrjZUs=
golang.org/x/image v0.0.0-20190227222117-0694c2d4d067/go.mod h1:kZ7UVZpmo3dzQBMxlp+ypCbDeSB+sBbTgSJuh5dn5js=
golang.org/x/image v0.0.0-20190802002840-cff245a6509b/go.mod h1:FeLwcggjj3mMvU+oOTbSwawSJRM1uh48EjtB4UJZlP0=
Expand Down
19 changes: 5 additions & 14 deletions internal/log/stackdriverlogger/log.go
Original file line number Diff line number Diff line change
Expand Up @@ -16,6 +16,7 @@ import (
"sync"

"cloud.google.com/go/logging"
"golang.org/x/pkgsite/internal"
"golang.org/x/pkgsite/internal/derrors"
"golang.org/x/pkgsite/internal/experiment"
"golang.org/x/pkgsite/internal/log"
Expand All @@ -31,18 +32,8 @@ func init() {
}
}

type (
// traceIDKey is the type of the context key for trace IDs.
traceIDKey struct{}

// labelsKey is the type of the context key for labels.
labelsKey struct{}
)

// NewContextWithTraceID creates a new context from ctx that adds the trace ID.
func NewContextWithTraceID(ctx context.Context, traceID string) context.Context {
return context.WithValue(ctx, traceIDKey{}, traceID)
}
// labelsKey is the type of the context key for labels.
type labelsKey struct{}

// NewContextWithLabel creates a new context from ctx that adds a label that will
// appear in the log entry.
Expand Down Expand Up @@ -90,7 +81,7 @@ func (l *logger) Log(ctx context.Context, s log.Severity, payload any) {
if err, ok := payload.(error); ok {
payload = err.Error()
}
traceID, _ := ctx.Value(traceIDKey{}).(string) // if not present, traceID is "", which is fine

labels, _ := ctx.Value(labelsKey{}).(map[string]string)
es := experimentString(ctx)
if len(es) > 0 {
Expand All @@ -105,7 +96,7 @@ func (l *logger) Log(ctx context.Context, s log.Severity, payload any) {
Severity: stackdriverSeverity(s),
Labels: labels,
Payload: payload,
Trace: traceID,
Trace: internal.RequestInfoFromContext(ctx).TraceID,
})
}

Expand Down
18 changes: 9 additions & 9 deletions internal/middleware/requestlog.go
Original file line number Diff line number Diff line change
Expand Up @@ -13,8 +13,8 @@ import (
"time"

"cloud.google.com/go/logging"
"golang.org/x/pkgsite/internal"
"golang.org/x/pkgsite/internal/log"
"golang.org/x/pkgsite/internal/log/stackdriverlogger"
)

// Logger is the interface used to write request logs to GCP.
Expand All @@ -40,12 +40,12 @@ func (l LocalLogger) Log(entry logging.Entry) {
}

// RequestLog returns a middleware that logs each incoming requests using the
// given logger. This logger replaces the built-in appengine request logger,
// which logged PII when behind IAP, in such a way that was impossible to turn
// off.
// given logger.
//
// Logs may be viewed in Pantheon by selecting the log source corresponding to
// the AppEngine service name (e.g. 'dev-worker').
// the service name (e.g. 'dev-worker').
//
// Install this middleware after RequestInfo to ensure that trace IDs appear in the log.
func RequestLog(lg Logger) Middleware {
return func(h http.Handler) http.Handler {
return &handler{delegate: h, logger: lg}
Expand All @@ -59,21 +59,21 @@ type handler struct {

func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
start := time.Now()
traceID := r.Header.Get("X-Cloud-Trace-Context")
severity := logging.Info
if r.Method == http.MethodGet && r.URL.Path == "/healthz" {
severity = logging.Debug
}
requestInfo := internal.RequestInfoFromContext(r.Context())
h.logger.Log(logging.Entry{
HTTPRequest: &logging.HTTPRequest{Request: r},
Payload: map[string]string{
"requestType": "request start",
},
Severity: severity,
Trace: traceID,
Trace: requestInfo.TraceID,
})
w2 := &responseWriter{ResponseWriter: w}
h.delegate.ServeHTTP(w2, r.WithContext(stackdriverlogger.NewContextWithTraceID(r.Context(), traceID)))
h.delegate.ServeHTTP(w2, r)
s := severity
if w2.status == http.StatusServiceUnavailable {
// load shedding is a warning, not an error
Expand All @@ -92,7 +92,7 @@ func (h *handler) ServeHTTP(w http.ResponseWriter, r *http.Request) {
"isRobot": isRobot(r.Header.Get("User-Agent")),
},
Severity: s,
Trace: traceID,
Trace: requestInfo.TraceID,
})
}

Expand Down
68 changes: 68 additions & 0 deletions internal/middleware/requests.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,68 @@
// Copyright 2024 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package middleware

import (
"context"
"net/http"
"sync"

"golang.org/x/pkgsite/internal"
)

var (
requestMapMu sync.Mutex
requestMap = map[string]*internal.RequestInfo{}
)

// RequestInfo adds information about the request to a context.
// It also stores it while the request is active.
// [ActiveRequests] retrieves all stored requests.
func RequestInfo() Middleware {
return func(h http.Handler) http.Handler {
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
ri := internal.NewRequestInfo(r)
ctx, cancel := context.WithCancelCause(r.Context())
ri.Cancel = cancel

// If the request has a trace ID, store it in the requestMap while
// it is active.
if ri.TraceID != "" {
requestMapMu.Lock()
requestMap[ri.TraceID] = ri
requestMapMu.Unlock()

defer func() {
requestMapMu.Lock()
delete(requestMap, ri.TraceID)
requestMapMu.Unlock()
}()
}

ctx = internal.NewContextWithRequestInfo(ctx, ri)
h.ServeHTTP(w, r.WithContext(ctx))
})
}
}

// ActiveRequests returns all requests that are currently being handled by the server,
// in no particular order.
func ActiveRequests() []*internal.RequestInfo {
requestMapMu.Lock()
defer requestMapMu.Unlock()
var ris []*internal.RequestInfo
for _, ri := range requestMap {
ris = append(ris, ri)
}
return ris
}

// RequestForTraceID returns the active request with the given trace ID,
// or nil if there is no such request.
func RequestForTraceID(id string) *internal.RequestInfo {
requestMapMu.Lock()
defer requestMapMu.Unlock()
return requestMap[id]
}
51 changes: 51 additions & 0 deletions internal/request_info.go
Original file line number Diff line number Diff line change
@@ -0,0 +1,51 @@
// Copyright 2024 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

package internal

import (
"context"
"net/http"
"time"
)

// RequestInfo is information about an HTTP request.
type RequestInfo struct {
Request *http.Request
TrimmedURL string // URL with the scheme and host removed
TraceID string // extracted from request header
Start time.Time // when the request began
Cancel func(error) // function that cancels the request's context
}

func NewRequestInfo(r *http.Request) *RequestInfo {
turl := *r.URL
turl.Scheme = ""
turl.Host = ""
turl.User = nil
return &RequestInfo{
Request: r,
TrimmedURL: turl.String(),
TraceID: r.Header.Get("X-Cloud-Trace-Context"),
Start: time.Now(),
}
}

// requestInfoKey is the type of the context key for RequestInfos.
type requestInfoKey struct{}

// NewContextWithRequestInfo creates a new context from ctx that adds the trace ID.
func NewContextWithRequestInfo(ctx context.Context, ri *RequestInfo) context.Context {
return context.WithValue(ctx, requestInfoKey{}, ri)
}

// RequestInfoFromContext retrieves the trace ID from the context, or a zero one
// if it isn't there.
func RequestInfoFromContext(ctx context.Context) *RequestInfo {
ri, _ := ctx.Value(requestInfoKey{}).(*RequestInfo)
if ri == nil {
return &RequestInfo{}
}
return ri
}
2 changes: 1 addition & 1 deletion internal/trace/trace.go
Original file line number Diff line number Diff line change
Expand Up @@ -3,7 +3,7 @@
// license that can be found in the LICENSE file.

// package trace provides a wrapper around third party tracing
// libraries
// libraries.
package trace

import "context"
Expand Down
9 changes: 5 additions & 4 deletions internal/worker/fetch.go
Original file line number Diff line number Diff line change
Expand Up @@ -157,10 +157,11 @@ func (f *Fetcher) FetchAndUpdateState(ctx context.Context, modulePath, requested
}

fi := &FetchInfo{
ModulePath: modulePath,
Version: requestedVersion,
ZipSize: uint64(zipSize),
Start: time.Now(),
RequestInfo: internal.RequestInfoFromContext(ctx),
ModulePath: modulePath,
Version: requestedVersion,
ZipSize: uint64(zipSize),
Start: time.Now(),
}
startFetchInfo(fi)
defer func() { finishFetchInfo(fi, status, err) }()
Expand Down
17 changes: 10 additions & 7 deletions internal/worker/fetchinfo.go
Original file line number Diff line number Diff line change
Expand Up @@ -8,18 +8,21 @@ import (
"sort"
"sync"
"time"

"golang.org/x/pkgsite/internal"
)

// FetchInfo describes a fetch in progress, or completed.
// It is used to display information on the worker home page.
type FetchInfo struct {
ModulePath string
Version string
ZipSize uint64
Start time.Time
Finish time.Time
Status int
Error error
RequestInfo *internal.RequestInfo
ModulePath string
Version string
ZipSize uint64
Start time.Time
Finish time.Time
Status int
Error error
}

var (
Expand Down
25 changes: 11 additions & 14 deletions internal/worker/pages.go
Original file line number Diff line number Diff line change
Expand Up @@ -19,10 +19,10 @@ import (
"github.com/google/safehtml/template"
"golang.org/x/pkgsite/internal"
"golang.org/x/pkgsite/internal/config"
"golang.org/x/pkgsite/internal/config/serverconfig"
"golang.org/x/pkgsite/internal/derrors"
"golang.org/x/pkgsite/internal/log"
"golang.org/x/pkgsite/internal/memory"
"golang.org/x/pkgsite/internal/middleware"
"golang.org/x/pkgsite/internal/postgres"
"golang.org/x/sync/errgroup"
)
Expand Down Expand Up @@ -60,17 +60,14 @@ func (s *Server) doIndexPage(w http.ResponseWriter, r *http.Request) (err error)
if err != nil {
log.Warningf(ctx, "could not get cgroup stats: %v", err)
}
var logsURL string
if serverconfig.OnGKE() {
env := s.cfg.DeploymentEnvironment()
cluster := env + "-" + "pkgsite"
logsURL = `https://pantheon.corp.google.com/logs/query;query=resource.type%3D%22k8s_container%22%20resource.labels.cluster_name%3D%22` +
cluster +
`%22%20resource.labels.container_name%3D%22worker%22?project=` +
s.cfg.ProjectID
} else {
logsURL = `https://cloud.google.com/console/logs/viewer?resource=gae_app%2Fmodule_id%2F` + s.cfg.ServiceID + `&project=` +
s.cfg.ProjectID

// Display requests that aren't fetches separately.
// Don't include the request for this page itself.
var nonFetchRequests []*internal.RequestInfo
for _, ri := range middleware.ActiveRequests() {
if ri.TrimmedURL != "/" && !strings.HasPrefix(ri.TrimmedURL, "/fetch/") {
nonFetchRequests = append(nonFetchRequests, ri)
}
}

page := struct {
Expand All @@ -88,7 +85,7 @@ func (s *Server) doIndexPage(w http.ResponseWriter, r *http.Request) (err error)
SystemStats memory.SystemStats
CgroupStats map[string]uint64
Fetches []*FetchInfo
LogsURL string
OtherRequests []*internal.RequestInfo
DBInfo *postgres.UserInfo
}{
Config: s.cfg,
Expand All @@ -104,7 +101,7 @@ func (s *Server) doIndexPage(w http.ResponseWriter, r *http.Request) (err error)
SystemStats: sms,
CgroupStats: cms,
Fetches: FetchInfos(),
LogsURL: logsURL,
OtherRequests: nonFetchRequests,
DBInfo: s.workerDBInfo(),
}
return renderPage(ctx, w, page, s.templates[indexTemplate])
Expand Down
Loading

0 comments on commit df601fe

Please sign in to comment.