Skip to content

Commit

Permalink
Merge branch 'master' into ws-error-status
Browse files Browse the repository at this point in the history
  • Loading branch information
@alfrunes
alfrunes committed Dec 12, 2023
2 parents 0b62e2d + dbd92a2 commit 1cac297
Show file tree
Hide file tree
Showing 7 changed files with 307 additions and 180 deletions.
124 changes: 96 additions & 28 deletions accesslog/middleware.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,7 +17,10 @@ import (
"bytes"
"fmt"
"net"
"net/http"
"os"
"path"
"runtime"
"strings"
"text/template"
"time"
Expand All @@ -42,6 +45,92 @@ const (
type AccessLogMiddleware struct {
Format AccessLogFormat
textTemplate *template.Template

DisableLog func(statusCode int, r *rest.Request) bool

recorder *rest.RecorderMiddleware
}

const MaxTraceback = 32

func collectTrace() string {
var (
trace [MaxTraceback]uintptr
traceback strings.Builder
)
// Skip 4
// = accesslog.LogFunc
// + accesslog.collectTrace
// + runtime.Callers
// + runtime.gopanic
n := runtime.Callers(4, trace[:])
frames := runtime.CallersFrames(trace[:n])
for frame, more := frames.Next(); frame.PC != 0 &&
n >= 0; frame, more = frames.Next() {
funcName := frame.Function
if funcName == "" {
fmt.Fprint(&traceback, "???\n")
} else {
fmt.Fprintf(&traceback, "%s@%s:%d",
frame.Function,
path.Base(frame.File),
frame.Line,
)
}
if more {
fmt.Fprintln(&traceback)
}
n--
}
return traceback.String()
}

func (mw *AccessLogMiddleware) LogFunc(startTime time.Time, w rest.ResponseWriter, r *rest.Request) {
util := &accessLogUtil{w, r}
fields := logrus.Fields{
"type": r.Proto,
"ts": startTime.
Truncate(time.Millisecond).
Format(time.RFC3339Nano),
"method": r.Method,
"path": r.URL.Path,
"qs": r.URL.RawQuery,
}
statusCode := util.StatusCode()

if panic := recover(); panic != nil {
trace := collectTrace()
fields["panic"] = panic
fields["trace"] = trace
// Wrap in recorder middleware to make sure the response is recorded
mw.recorder.MiddlewareFunc(func(w rest.ResponseWriter, r *rest.Request) {
rest.Error(w, "Internal Server Error", http.StatusInternalServerError)
})(w, r)
statusCode = http.StatusInternalServerError
} else if mw.DisableLog != nil && mw.DisableLog(statusCode, r) {
return
}
rspTime := time.Since(startTime)
r.Env["ELAPSED_TIME"] = &rspTime
// We do not need more than 3 digit fraction
if rspTime > time.Second {
rspTime = rspTime.Round(time.Millisecond)
} else if rspTime > time.Millisecond {
rspTime = rspTime.Round(time.Microsecond)
}
fields["responsetime"] = rspTime.String()
fields["byteswritten"] = util.BytesWritten()
fields["status"] = statusCode

logger := requestlog.GetRequestLogger(r)
var level logrus.Level = logrus.InfoLevel
if statusCode >= 500 {
level = logrus.ErrorLevel
} else if statusCode >= 300 {
level = logrus.WarnLevel
}
logger.WithFields(fields).
Log(level, mw.executeTextTemplate(util))
}

// MiddlewareFunc makes AccessLogMiddleware implement the Middleware interface.
Expand All @@ -52,35 +141,14 @@ func (mw *AccessLogMiddleware) MiddlewareFunc(h rest.HandlerFunc) rest.HandlerFu

mw.convertFormat()

// This middleware depends on RecorderMiddleware to work
mw.recorder = new(rest.RecorderMiddleware)
return func(w rest.ResponseWriter, r *rest.Request) {

// call the handler
h(w, r)

util := &accessLogUtil{w, r}
logger := requestlog.GetRequestLogger(r)
logged := false
log := logger.WithFields(logrus.Fields{
"type": TypeHTTP,
"ts": util.StartTime().Round(0),
"status": util.StatusCode(),
"responsetime": util.ResponseTime().Seconds(),
"byteswritten": util.BytesWritten(),
"method": r.Method,
"path": r.URL.Path,
"qs": r.URL.RawQuery,
})
for pathSuffix, status := range DebugLogsByPathSuffix {
if util.StatusCode() == status && strings.HasSuffix(r.URL.Path, pathSuffix) {
log.Debug(mw.executeTextTemplate(util))
logged = true
break
}
}

if !logged {
log.Print(mw.executeTextTemplate(util))
}
startTime := time.Now()
r.Env["START_TIME"] = &startTime
defer mw.LogFunc(startTime, w, r)
// call the handler inside recorder context
mw.recorder.MiddlewareFunc(h)(w, r)
}
}

Expand Down
195 changes: 71 additions & 124 deletions accesslog/middleware_gin.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -17,151 +17,98 @@ package accesslog
import (
"fmt"
"net/http"
"runtime"
"strings"
"time"

"github.com/gin-gonic/gin"
"github.com/mendersoftware/go-lib-micro/log"
"github.com/mendersoftware/go-lib-micro/rest.utils"
"github.com/pkg/errors"
"github.com/sirupsen/logrus"
)

const MaxTraceback = 32

func funcname(fn string) string {
// strip package path
i := strings.LastIndex(fn, "/")
fn = fn[i+1:]
// strip package name.
i = strings.Index(fn, ".")
fn = fn[i+1:]
return fn
type AccessLogger struct {
DisableLog func(c *gin.Context) bool
}

func panicHandler(c *gin.Context, startTime time.Time) {
func (a AccessLogger) LogFunc(c *gin.Context, startTime time.Time) {
logCtx := logrus.Fields{
"clientip": c.ClientIP(),
"method": c.Request.Method,
"path": c.Request.URL.Path,
"qs": c.Request.URL.RawQuery,
"ts": startTime.
Truncate(time.Millisecond).
Format(time.RFC3339Nano),
"type": c.Request.Proto,
"useragent": c.Request.UserAgent(),
}
if r := recover(); r != nil {
l := log.FromContext(c.Request.Context())
latency := time.Since(startTime)
trace := [MaxTraceback]uintptr{}
// Skip 3
// = runtime.Callers + runtime.extern.Callers + runtime.gopanic
num := runtime.Callers(3, trace[:])
var traceback strings.Builder
for i := 0; i < num; i++ {
fn := runtime.FuncForPC(trace[i])
if fn == nil {
fmt.Fprintf(&traceback, "\n???")
continue
}
file, line := fn.FileLine(trace[i])
fmt.Fprintf(&traceback, "\n%s(%s):%d",
file, funcname(fn.Name()), line,
)
}
trace := collectTrace()
logCtx["trace"] = trace
logCtx["panic"] = r

logCtx := log.Ctx{
"clientip": c.ClientIP(),
"method": c.Request.Method,
"path": c.Request.URL.Path,
"qs": c.Request.URL.RawQuery,
"responsetime": fmt.Sprintf("%dus",
latency.Round(time.Microsecond).Microseconds()),
"status": 500,
"ts": startTime.Format(time.RFC3339),
"type": c.Request.Proto,
"useragent": c.Request.UserAgent(),
"trace": traceback.String()[1:],
}
l = l.F(logCtx)
func() {
// Panic is going to panic, but we
// immediately want to recover.
defer func() { recover() }() //nolint:errcheck
l.Panicf("[request panic] %s", r)
// Try to respond with an internal server error.
// If the connection is broken it might panic again.
defer func() { recover() }() // nolint:errcheck
rest.RenderError(c,
http.StatusInternalServerError,
errors.New("internal error"),
)
}()
} else if a.DisableLog != nil && a.DisableLog(c) {
return
}
latency := time.Since(startTime)
// We do not need more than 3 digit fraction
if latency > time.Second {
latency = latency.Round(time.Millisecond)
} else if latency > time.Millisecond {
latency = latency.Round(time.Microsecond)
}
code := c.Writer.Status()
logCtx["responsetime"] = latency.String()
logCtx["status"] = c.Writer.Status()
logCtx["byteswritten"] = c.Writer.Size()

// Try to respond with an internal server error.
// If the connection is broken it might panic again.
defer func() { recover() }() // nolint:errcheck
rest.RenderError(c,
http.StatusInternalServerError,
errors.New("internal error"),
)
var logLevel logrus.Level = logrus.InfoLevel
if code >= 500 {
logLevel = logrus.ErrorLevel
} else if code >= 400 {
logLevel = logrus.WarnLevel
}
if len(c.Errors) > 0 {
errs := c.Errors.Errors()
var errMsg string
if len(errs) == 1 {
errMsg = errs[0]
} else {
for i, err := range errs {
errMsg = errMsg + fmt.Sprintf(
"#%02d: %s\n", i+1, err,
)
}
}
logCtx["error"] = errMsg
}
log.FromContext(c.Request.Context()).
WithFields(logCtx).
Log(logLevel)
}

func (a AccessLogger) Middleware(c *gin.Context) {
startTime := time.Now()
defer a.LogFunc(c, startTime)
c.Next()
}

// Middleware provides accesslog middleware for the gin-gonic framework.
// This middleware will recover any panic from the occurring in the API
// handler and log it to panic level.
// This middleware will recover any panic from occurring in the API
// handler and log it to error level with panic and trace showing the panic
// message and traceback respectively.
// If an error status is returned in the response, the middleware tries
// to pop the topmost error from the gin.Context (c.Error) and puts it in
// the "error" context to the final log entry.
func Middleware() gin.HandlerFunc {
return func(c *gin.Context) {
startTime := time.Now()
defer panicHandler(c, startTime)

c.Next()

l := log.FromContext(c.Request.Context())
latency := time.Since(startTime)
code := c.Writer.Status()
// Add status and response time to log context
size := c.Writer.Size()
if size < 0 {
size = 0
}
logCtx := log.Ctx{
"byteswritten": size,
"clientip": c.ClientIP(),
"method": c.Request.Method,
"path": c.Request.URL.Path,
"qs": c.Request.URL.RawQuery,
"responsetime": fmt.Sprintf("%dus",
latency.Round(time.Microsecond).Microseconds()),
"status": code,
"ts": startTime.Format(time.RFC3339),
"type": c.Request.Proto,
"useragent": c.Request.UserAgent(),
}
l = l.F(logCtx)

if code < 400 {
logged := false
for pathSuffix, status := range DebugLogsByPathSuffix {
if code == status && strings.HasSuffix(c.Request.URL.Path, pathSuffix) {
l.Debug()
logged = true
break
}
}

if !logged {
l.Info()
}
} else {
if len(c.Errors) > 0 {
errs := c.Errors.Errors()
var errMsg string
if len(errs) == 1 {
errMsg = errs[0]
} else {
for i, err := range errs {
errMsg = errMsg + fmt.Sprintf(
"#%02d: %s\n", i+1, err,
)
}
}
l = l.F(log.Ctx{
"error": errMsg,
})
} else {
l = l.F(log.Ctx{
"error": http.StatusText(code),
})
}
l.Error()
}
}
return AccessLogger{}.Middleware
}
Loading

0 comments on commit 1cac297

Please sign in to comment.