Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

logging tweaks to improve usability #1235

Merged
merged 3 commits into from
Dec 13, 2022
Merged

logging tweaks to improve usability #1235

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
eab65e6
logging tweaks to improve usability
bobcallaway Dec 10, 2022
fde7dd1
variable name for linter
bobcallaway Dec 10, 2022
d1306a3
update types to put string formatting at lower level
bobcallaway Dec 12, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
8 changes: 4 additions & 4 deletions pkg/api/entries.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -133,14 +133,14 @@ func logEntryFromLeaf(ctx context.Context, signer signature.Signer, tc TrillianC
if attKey != "" {
att, fetchErr = storageClient.FetchAttestation(ctx, attKey)
if fetchErr != nil {
log.ContextLogger(ctx).Errorf("error fetching attestation by key, trying by UUID: %s %w", attKey, fetchErr)
log.ContextLogger(ctx).Debugf("error fetching attestation by key, trying by UUID: %s %v", attKey, fetchErr)
}
}
// if looking up by key failed or we weren't able to generate a key, try looking up by uuid
if attKey == "" || fetchErr != nil {
att, fetchErr = storageClient.FetchAttestation(ctx, entryIDstruct.UUID)
if fetchErr != nil {
log.ContextLogger(ctx).Errorf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr)
log.ContextLogger(ctx).Debugf("error fetching attestation by uuid: %s %v", entryIDstruct.UUID, fetchErr)
}
}
if fetchErr == nil {
Expand Down Expand Up @@ -237,12 +237,12 @@ func createLogEntry(params entries.CreateLogEntryParams) (models.LogEntry, middl
go func() {
keys, err := entry.IndexKeys()
if err != nil {
log.ContextLogger(ctx).Error(err)
log.ContextLogger(ctx).Errorf("getting entry index keys: %v", err)
return
}
for _, key := range keys {
if err := addToIndex(context.Background(), key, entryID); err != nil {
log.ContextLogger(ctx).Error(err)
log.ContextLogger(ctx).Errorf("adding keys to index: %v", err)
}
}
}()
Expand Down
7 changes: 6 additions & 1 deletion pkg/api/error.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -69,7 +69,12 @@ func handleRekorAPIError(params interface{}, code int, err error, message string

logMsg := func(r *http.Request) {
ctx := r.Context()
log.ContextLogger(ctx).Errorw("error processing request", append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message, "error", err}, fields...)...)
fields := append([]interface{}{"handler", handler, "statusCode", code, "clientMessage", message}, fields...)
if code >= 500 {
log.ContextLogger(ctx).Errorw(err.Error(), fields)
} else {
log.ContextLogger(ctx).Warnw(err.Error(), fields)
}
paramsFields := map[string]interface{}{}
if err := mapstructure.Decode(params, &paramsFields); err == nil {
log.ContextLogger(ctx).Debug(paramsFields)
Expand Down
2 changes: 0 additions & 2 deletions pkg/api/public_key.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -23,7 +23,6 @@ import (
"github.com/go-openapi/swag"
"github.com/sigstore/rekor/pkg/generated/models"
"github.com/sigstore/rekor/pkg/generated/restapi/operations/pubkey"
"github.com/sigstore/rekor/pkg/log"
)

func GetPublicKeyHandler(params pubkey.GetPublicKeyParams) middleware.Responder {
Expand All @@ -34,7 +33,6 @@ func GetPublicKeyHandler(params pubkey.GetPublicKeyParams) middleware.Responder
if err != nil {
return handleRekorAPIError(params, http.StatusBadRequest, err, "")
}
log.ContextLogger(ctx).Info("returning public key")
return pubkey.NewGetPublicKeyOK().WithPayload(pk)
}

Expand Down
104 changes: 97 additions & 7 deletions pkg/generated/restapi/configure_rekor_server.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,7 +20,9 @@ package restapi
import (
"context"
"crypto/tls"
"fmt"
"net/http"
"net/http/httputil"
"strconv"
"time"

Expand All @@ -33,6 +35,8 @@ import (
"github.com/mitchellh/mapstructure"
"github.com/rs/cors"
"github.com/spf13/viper"
"go.uber.org/zap"
"go.uber.org/zap/zapcore"

pkgapi "github.com/sigstore/rekor/pkg/api"
"github.com/sigstore/rekor/pkg/generated/restapi/operations"
Expand Down Expand Up @@ -174,21 +178,81 @@ func setupMiddlewares(handler http.Handler) http.Handler {
return handler
}

type httpRequestFields struct {
requestMethod string
requestURL string
requestSize int64
status int
responseSize int
userAgent string
remoteIP string
latency time.Duration
protocol string
}

func (h *httpRequestFields) MarshalLogObject(enc zapcore.ObjectEncoder) error {
enc.AddString("requestMethod", h.requestMethod)
enc.AddString("requestUrl", h.requestURL)
enc.AddString("requestSize", fmt.Sprintf("%d", h.requestSize))
enc.AddInt("status", h.status)
enc.AddString("responseSize", fmt.Sprintf("%d", h.responseSize))
enc.AddString("userAgent", h.userAgent)
enc.AddString("remoteIP", h.remoteIP)
enc.AddString("latency", fmt.Sprintf("%.9fs", h.latency.Seconds())) // formatted per GCP expectations
enc.AddString("protocol", h.protocol)
bobcallaway marked this conversation as resolved.
Show resolved Hide resolved
return nil
}

// We need this type to act as an adapter between zap and the middleware request logger.
type logAdapter struct {
type zapLogEntry struct {
r *http.Request
}

func (l *logAdapter) Print(v ...interface{}) {
log.Logger.Info(v...)
func (z *zapLogEntry) Write(status, bytes int, header http.Header, elapsed time.Duration, extra interface{}) {
var fields []interface{}
bobcallaway marked this conversation as resolved.
Show resolved Hide resolved

// follows https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry as a convention
// append HTTP Request / Response Information
scheme := "http"
if z.r.TLS != nil {
scheme = "https"
}
httpRequestObj := &httpRequestFields{
requestMethod: z.r.Method,
requestURL: fmt.Sprintf("%s://%s%s", scheme, z.r.Host, z.r.RequestURI),
requestSize: z.r.ContentLength,
status: status,
responseSize: bytes,
userAgent: z.r.Header.Get("User-Agent"),
remoteIP: z.r.RemoteAddr,
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Any reason to log IP? Some PII risk of being able to correlate requests across artifacts, gather usage data, etc

latency: elapsed,
protocol: z.r.Proto,
}
fields = append(fields, zap.Object("httpRequest", httpRequestObj))
if extra != nil {
fields = append(fields, zap.Any("extra", extra))
}

log.ContextLogger(z.r.Context()).With(fields...).Info("completed request")
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If the fields were declared as []zapcore.Field then this can be
log.ContextLogger(z.r.Context()).With(fields).Info("completed request")

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

With([]interface{}) is how this is defined, and the logger doesn't work if you more strongly type this.

}

func (z *zapLogEntry) Panic(v interface{}, stack []byte) {
fields := []interface{}{zap.String("message", fmt.Sprintf("%v\n%v", v, string(stack)))}
log.ContextLogger(z.r.Context()).With(fields...).Errorf("panic detected: %v", v)
}

type logFormatter struct{}

func (l *logFormatter) NewLogEntry(r *http.Request) middleware.LogEntry {
return &zapLogEntry{r}
}

// The middleware configuration happens before anything, this middleware also applies to serving the swagger.json document.
// So this is a good place to plug in a panic handling middleware, logging and metrics
func setupGlobalMiddleware(handler http.Handler) http.Handler {
middleware.DefaultLogger = middleware.RequestLogger(
&middleware.DefaultLogFormatter{Logger: &logAdapter{}})
returnHandler := middleware.Logger(handler)
returnHandler = middleware.Recoverer(returnHandler)
returnHandler := recoverer(handler)
middleware.DefaultLogger = middleware.RequestLogger(&logFormatter{})
returnHandler = middleware.Logger(returnHandler)
returnHandler = middleware.Heartbeat("/ping")(returnHandler)
returnHandler = serveStaticContent(returnHandler)

Expand Down Expand Up @@ -296,3 +360,29 @@ func serveStaticContent(handler http.Handler) http.Handler {
handler.ServeHTTP(w, r)
})
}

// recoverer
func recoverer(next http.Handler) http.Handler {
fn := func(w http.ResponseWriter, r *http.Request) {
defer func() {
if rvr := recover(); rvr != nil && rvr != http.ErrAbortHandler {
var fields []interface{}

// get context before dump request in case there is an error
ctx := r.Context()
request, err := httputil.DumpRequest(r, false)
if err == nil {
fields = append(fields, zap.ByteString("request_headers", request))
}

log.ContextLogger(ctx).With(fields...).Errorf("panic detected: %v", rvr)

errors.ServeError(w, r, nil)
}
}()

next.ServeHTTP(w, r)
}

return http.HandlerFunc(fn)
}
38 changes: 37 additions & 1 deletion pkg/log/log.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -37,6 +37,11 @@ func ConfigureLogger(logType string) {
cfg = zap.NewProductionConfig()
cfg.EncoderConfig.LevelKey = "severity"
cfg.EncoderConfig.MessageKey = "message"
cfg.EncoderConfig.TimeKey = "time"
cfg.EncoderConfig.EncodeLevel = encodeLevel()
cfg.EncoderConfig.EncodeTime = zapcore.RFC3339TimeEncoder
cfg.EncoderConfig.EncodeDuration = zapcore.SecondsDurationEncoder
cfg.EncoderConfig.EncodeCaller = zapcore.FullCallerEncoder
} else {
cfg = zap.NewDevelopmentConfig()
cfg.EncoderConfig.EncodeLevel = zapcore.CapitalColorLevelEncoder
Expand All @@ -48,6 +53,27 @@ func ConfigureLogger(logType string) {
Logger = logger.Sugar()
}

func encodeLevel() zapcore.LevelEncoder {
return func(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) {
switch l {
case zapcore.DebugLevel:
enc.AppendString("DEBUG")
case zapcore.InfoLevel:
enc.AppendString("INFO")
case zapcore.WarnLevel:
enc.AppendString("WARNING")
case zapcore.ErrorLevel:
enc.AppendString("ERROR")
case zapcore.DPanicLevel:
enc.AppendString("CRITICAL")
case zapcore.PanicLevel:
enc.AppendString("ALERT")
case zapcore.FatalLevel:
enc.AppendString("EMERGENCY")
}
}
}

var CliLogger = createCliLogger()

func createCliLogger() *zap.SugaredLogger {
Expand All @@ -68,11 +94,21 @@ func WithRequestID(ctx context.Context, id string) context.Context {
return context.WithValue(ctx, middleware.RequestIDKey, id)
}

type operation struct {
id string
}

func (o operation) MarshalLogObject(enc zapcore.ObjectEncoder) error {
enc.AddString("id", o.id)
return nil
}

func ContextLogger(ctx context.Context) *zap.SugaredLogger {
proposedLogger := Logger
if ctx != nil {
if ctxRequestID, ok := ctx.Value(middleware.RequestIDKey).(string); ok {
proposedLogger = proposedLogger.With(zap.String("requestID", ctxRequestID))
requestID := operation{ctxRequestID}
proposedLogger = proposedLogger.With(zap.Object("operation", requestID))
}
}
return proposedLogger
Expand Down