1817314287

Committed 14 May 2025 09:36AM UTC coverage: 65.256% (+0.005%) from 65.251%

Build # 1817314287

Build Type

Pull #671

gitlab-ci

Committed by

alfrunes

Commit Message

perf: Put routing path and parameters in separate accesslog fields

By separating the two, it is much less complex to index paths in the log
parser.

Signed-off-by: Alf-Rune Siqveland <alf.rune@northern.tech>

Pull Request Pull Request #671: perf(accesslogs): Put routing path and parameters in separate fields

Run Details

14 of 14 new or added lines in 1 file covered. (100.0%)

6 existing lines in 2 files now uncovered.

31834 of 48783 relevant lines covered (65.26%)

1.37 hits per line

Source File
Press 'n' to go to next uncovered line, 'b' for previous

78.13

/backend/pkg/accesslog/middleware_gin.go

// Copyright 2024 Northern.tech AS
//
//    Licensed under the Apache License, Version 2.0 (the "License");
//    you may not use this file except in compliance with the License.
//    You may obtain a copy of the License at
//
//        http://www.apache.org/licenses/LICENSE-2.0
//
//    Unless required by applicable law or agreed to in writing, software
//    distributed under the License is distributed on an "AS IS" BASIS,
//    WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
//    See the License for the specific language governing permissions and
//    limitations under the License.

package accesslog

import (
        "context"
        "fmt"
        "net"
        "net/http"
        "strings"
        "time"

        "github.com/gin-gonic/gin"
        "github.com/pkg/errors"
        "github.com/sirupsen/logrus"

        "github.com/mendersoftware/mender-server/pkg/log"
        "github.com/mendersoftware/mender-server/pkg/rest.utils"
)

type AccessLogger struct {
        DisableLog   func(c *gin.Context) bool
        ClientIPHook func(r *http.Request) net.IP
}

func formatPathParams(c *gin.Context) string {
        var b strings.Builder
        l := len(c.Params) - 1
        d := ","
        for i, p := range c.Params {
                if i == l {
                        d = ""
                }
                fmt.Fprintf(&b, "%s=%s%s", p.Key, p.Value, d)
        }
        return b.String()
}

func (a AccessLogger) LogFunc(
        ctx context.Context,
        c *gin.Context,
        startTime time.Time,
) {
        logCtx := logrus.Fields{
                "method":      c.Request.Method,
                "path":        c.FullPath(),
                "path_params": formatPathParams(c),
                "qs":          c.Request.URL.RawQuery,
                "ts": startTime.
                        Truncate(time.Millisecond).
                        Format(time.RFC3339Nano),
                "type":      c.Request.Proto,
                "useragent": c.Request.UserAgent(),
        }
        if a.ClientIPHook != nil {
                logCtx["clientip"] = a.ClientIPHook(c.Request)
        }
        lc := fromContext(ctx)
        if lc != nil {
                lc.addFields(logCtx)
        }
        if r := recover(); r != nil {
                trace := collectTrace()
                logCtx["trace"] = trace
                logCtx["panic"] = r

                func() {
                        // 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()
        select {
        case <-ctx.Done():
                if errors.Is(ctx.Err(), context.Canceled) {
                        code = StatusClientClosedConnection
                }
        default:
        }
        logCtx["responsetime"] = latency.String()
        logCtx["status"] = c.Writer.Status()
        logCtx["byteswritten"] = c.Writer.Size()

        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)
}

// Middleware implementsa gin compatible MiddlewareFunc
//
// NOTE: This accesslog middleware also implements the legacy requestlog
// middleware.
func (a AccessLogger) Middleware(c *gin.Context) {
        ctx := c.Request.Context()
        startTime := time.Now()
        ctx = log.WithContext(ctx, log.New(log.Ctx{}))
        ctx = withContext(ctx, &logContext{maxErrors: DefaultMaxErrors})
        c.Request = c.Request.WithContext(ctx)
        defer a.LogFunc(ctx, c, startTime)
        c.Next()
}

// Middleware provides accesslog middleware for the gin-gonic framework.
// 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 AccessLogger{ClientIPHook: getClientIPFromEnv()}.Middleware
}

1	// Copyright 2024 Northern.tech AS
2	//
3	// Licensed under the Apache License, Version 2.0 (the "License");
4	// you may not use this file except in compliance with the License.
5	// You may obtain a copy of the License at
6	//
7	// http://www.apache.org/licenses/LICENSE-2.0
8	//
9	// Unless required by applicable law or agreed to in writing, software
10	// distributed under the License is distributed on an "AS IS" BASIS,
11	// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12	// See the License for the specific language governing permissions and
13	// limitations under the License.
14
15	package accesslog
16
17	import (
18	"context"
19	"fmt"
20	"net"
21	"net/http"
22	"strings"
23	"time"
24
25	"github.com/gin-gonic/gin"
26	"github.com/pkg/errors"
27	"github.com/sirupsen/logrus"
28
29	"github.com/mendersoftware/mender-server/pkg/log"
30	"github.com/mendersoftware/mender-server/pkg/rest.utils"
31	)
32
33	type AccessLogger struct {
34	DisableLog func(c *gin.Context) bool
35	ClientIPHook func(r *http.Request) net.IP
36	}
37
38	func formatPathParams(c *gin.Context) string {	4✔
39	var b strings.Builder	4✔
40	l := len(c.Params) - 1	4✔
41	d := ","	4✔
42	for i, p := range c.Params {	8✔
43	if i == l {	8✔
44	d = ""	4✔
45	}	4✔
46	fmt.Fprintf(&b, "%s=%s%s", p.Key, p.Value, d)	4✔
47	}
48	return b.String()	4✔
49	}
50
51	func (a AccessLogger) LogFunc(
52	ctx context.Context,
53	c *gin.Context,
54	startTime time.Time,
55	) {	4✔
56	logCtx := logrus.Fields{	4✔
57	"method": c.Request.Method,	4✔
58	"path": c.FullPath(),	4✔
59	"path_params": formatPathParams(c),	4✔
60	"qs": c.Request.URL.RawQuery,	4✔
61	"ts": startTime.	4✔
62	Truncate(time.Millisecond).	4✔
63	Format(time.RFC3339Nano),	4✔
64	"type": c.Request.Proto,	4✔
65	"useragent": c.Request.UserAgent(),	4✔
66	}	4✔
67	if a.ClientIPHook != nil {	4✔
UNCOV 68	logCtx["clientip"] = a.ClientIPHook(c.Request)	×
69	}	×
70	lc := fromContext(ctx)	4✔
71	if lc != nil {	8✔
72	lc.addFields(logCtx)	4✔
73	}	4✔
74	if r := recover(); r != nil {	4✔
UNCOV 75	trace := collectTrace()	×
76	logCtx["trace"] = trace	×
77	logCtx["panic"] = r	×
78		×
79	func() {	×
80	// Try to respond with an internal server error.	×
81	// If the connection is broken it might panic again.	×
82	defer func() { recover() }() // nolint:errcheck	×
83	rest.RenderError(c,	×
84	http.StatusInternalServerError,	×
85	errors.New("internal error"),	×
86	)	×
87	}()
88	} else if a.DisableLog != nil && a.DisableLog(c) {	4✔
UNCOV 89	return	×
90	}	×
91	latency := time.Since(startTime)	4✔
92	// We do not need more than 3 digit fraction	4✔
93	if latency > time.Second {	5✔
94	latency = latency.Round(time.Millisecond)	1✔
95	} else if latency > time.Millisecond {	9✔
96	latency = latency.Round(time.Microsecond)	4✔
97	}	4✔
98	code := c.Writer.Status()	4✔
99	select {	4✔
UNCOV 100	case <-ctx.Done():	×
101	if errors.Is(ctx.Err(), context.Canceled) {	×
102	code = StatusClientClosedConnection	×
103	}	×
104	default:	4✔
105	}
106	logCtx["responsetime"] = latency.String()	4✔
107	logCtx["status"] = c.Writer.Status()	4✔
108	logCtx["byteswritten"] = c.Writer.Size()	4✔
109		4✔
110	var logLevel logrus.Level = logrus.InfoLevel	4✔
111	if code >= 500 {	4✔
UNCOV 112	logLevel = logrus.ErrorLevel	×
113	} else if code >= 400 {	7✔
114	logLevel = logrus.WarnLevel	3✔
115	}	3✔
116	if len(c.Errors) > 0 {	6✔
117	errs := c.Errors.Errors()	2✔
118	var errMsg string	2✔
119	if len(errs) == 1 {	4✔
120	errMsg = errs[0]	2✔
121	} else {	3✔
122	for i, err := range errs {	2✔
123	errMsg = errMsg + fmt.Sprintf(	1✔
124	"#%02d: %s\n", i+1, err,	1✔
125	)	1✔
126	}	1✔
127	}
128	logCtx["error"] = errMsg	2✔
129	}
130	log.FromContext(c.Request.Context()).	4✔
131	WithFields(logCtx).	4✔
132	Log(logLevel)	4✔
133	}
134
135	// Middleware implementsa gin compatible MiddlewareFunc
136	//
137	// NOTE: This accesslog middleware also implements the legacy requestlog
138	// middleware.
139	func (a AccessLogger) Middleware(c *gin.Context) {	4✔
140	ctx := c.Request.Context()	4✔
141	startTime := time.Now()	4✔
142	ctx = log.WithContext(ctx, log.New(log.Ctx{}))	4✔
143	ctx = withContext(ctx, &logContext{maxErrors: DefaultMaxErrors})	4✔
144	c.Request = c.Request.WithContext(ctx)	4✔
145	defer a.LogFunc(ctx, c, startTime)	4✔
146	c.Next()	4✔
147	}	4✔
148
149	// Middleware provides accesslog middleware for the gin-gonic framework.
150	// This middleware will recover any panic from occurring in the API
151	// handler and log it to error level with panic and trace showing the panic
152	// message and traceback respectively.
153	// If an error status is returned in the response, the middleware tries
154	// to pop the topmost error from the gin.Context (c.Error) and puts it in
155	// the "error" context to the final log entry.
156	func Middleware() gin.HandlerFunc {	4✔
157	return AccessLogger{ClientIPHook: getClientIPFromEnv()}.Middleware	4✔
158	}	4✔

mendersoftware / mender-server / 1817314287

Source File Press 'n' to go to next uncovered line, 'b' for previous

Source File
Press 'n' to go to next uncovered line, 'b' for previous