1102564227

Committed 11 Dec 2023 12:05PM UTC coverage: 75.937% (-24.1%) from 100.0%

Build # 1102564227

Build Type

Pull #219

gitlab-ci

Committed by

alfrunes

Commit Message

fix: Improving legacy accesslog middleware by logging panic traces

The new middleware aligns better with the gin counterpart. The
responsetime is now logged with up to 3-digit precision in the
appropriate unit.

Changelog: None
Ticket:	MC-7155
Signed-off-by: Alf-Rune Siqveland <alf.rune@northern.tech>

Pull Request Pull Request #219: fix: Improving legacy accesslog middleware by logging panic traces

Run Details

0 of 67 new or added lines in 1 file covered. (0.0%)

43 existing lines in 2 files now uncovered.

1398 of 1841 relevant lines covered (75.94%)

3.95 hits per line

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

95.54

/accesslog/middleware_gin.go

// Copyright 2023 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 (
        "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"
)

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
}

func panicHandler(c *gin.Context, startTime time.Time) {
        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,
                        )
                }

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

// 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.
// 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()
                }
        }
}

1	// Copyright 2023 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	"fmt"
19	"net/http"
20	"runtime"
21	"strings"
22	"time"
23
24	"github.com/gin-gonic/gin"
25	"github.com/mendersoftware/go-lib-micro/log"
26	"github.com/mendersoftware/go-lib-micro/rest.utils"
27	"github.com/pkg/errors"
28	)
29
30	const MaxTraceback = 32
31
32	func funcname(fn string) string {	9✔
33	// strip package path	9✔
34	i := strings.LastIndex(fn, "/")	9✔
35	fn = fn[i+1:]	9✔
36	// strip package name.	9✔
37	i = strings.Index(fn, ".")	9✔
38	fn = fn[i+1:]	9✔
39	return fn	9✔
40	}	9✔
41
42	func panicHandler(c *gin.Context, startTime time.Time) {	5✔
43	if r := recover(); r != nil {	6✔
44	l := log.FromContext(c.Request.Context())	1✔
45	latency := time.Since(startTime)	1✔
46	trace := [MaxTraceback]uintptr{}	1✔
47	// Skip 3	1✔
48	// = runtime.Callers + runtime.extern.Callers + runtime.gopanic	1✔
49	num := runtime.Callers(3, trace[:])	1✔
50	var traceback strings.Builder	1✔
51	for i := 0; i < num; i++ {	10✔
52	fn := runtime.FuncForPC(trace[i])	9✔
53	if fn == nil {	9✔
54	fmt.Fprintf(&traceback, "\n???")	×
55	continue	×
56	}
57	file, line := fn.FileLine(trace[i])	9✔
58	fmt.Fprintf(&traceback, "\n%s(%s):%d",	9✔
59	file, funcname(fn.Name()), line,	9✔
60	)	9✔
61	}
62
63	logCtx := log.Ctx{	1✔
64	"clientip": c.ClientIP(),	1✔
65	"method": c.Request.Method,	1✔
66	"path": c.Request.URL.Path,	1✔
67	"qs": c.Request.URL.RawQuery,	1✔
68	"responsetime": fmt.Sprintf("%dus",	1✔
69	latency.Round(time.Microsecond).Microseconds()),	1✔
70	"status": 500,	1✔
71	"ts": startTime.Format(time.RFC3339),	1✔
72	"type": c.Request.Proto,	1✔
73	"useragent": c.Request.UserAgent(),	1✔
74	"trace": traceback.String()[1:],	1✔
75	}	1✔
76	l = l.F(logCtx)	1✔
77	func() {	2✔
78	// Panic is going to panic, but we	1✔
79	// immediately want to recover.	1✔
80	defer func() { recover() }() //nolint:errcheck	2✔
81	l.Panicf("[request panic] %s", r)	1✔
82	}()
83
84	// Try to respond with an internal server error.
85	// If the connection is broken it might panic again.
86	defer func() { recover() }() // nolint:errcheck	2✔
87	rest.RenderError(c,	1✔
88	http.StatusInternalServerError,	1✔
89	errors.New("internal error"),	1✔
90	)	1✔
91	}
92	}
93
94	// Middleware provides accesslog middleware for the gin-gonic framework.
95	// This middleware will recover any panic from the occurring in the API
96	// handler and log it to panic level.
97	// If an error status is returned in the response, the middleware tries
98	// to pop the topmost error from the gin.Context (c.Error) and puts it in
99	// the "error" context to the final log entry.
100	func Middleware() gin.HandlerFunc {	5✔
101	return func(c *gin.Context) {	10✔
102	startTime := time.Now()	5✔
103	defer panicHandler(c, startTime)	5✔
104		5✔
105	c.Next()	5✔
106		5✔
107	l := log.FromContext(c.Request.Context())	5✔
108	latency := time.Since(startTime)	5✔
109	code := c.Writer.Status()	5✔
110	// Add status and response time to log context	5✔
111	size := c.Writer.Size()	5✔
112	if size < 0 {	6✔
113	size = 0	1✔
114	}	1✔
115	logCtx := log.Ctx{	4✔
116	"byteswritten": size,	4✔
117	"clientip": c.ClientIP(),	4✔
118	"method": c.Request.Method,	4✔
119	"path": c.Request.URL.Path,	4✔
120	"qs": c.Request.URL.RawQuery,	4✔
121	"responsetime": fmt.Sprintf("%dus",	4✔
122	latency.Round(time.Microsecond).Microseconds()),	4✔
123	"status": code,	4✔
124	"ts": startTime.Format(time.RFC3339),	4✔
125	"type": c.Request.Proto,	4✔
126	"useragent": c.Request.UserAgent(),	4✔
127	}	4✔
128	l = l.F(logCtx)	4✔
129		4✔
130	if code < 400 {	5✔
131	logged := false	1✔
132	for pathSuffix, status := range DebugLogsByPathSuffix {	3✔
133	if code == status && strings.HasSuffix(c.Request.URL.Path, pathSuffix) {	2✔
UNCOV 134	l.Debug()	×
UNCOV 135	logged = true	×
UNCOV 136	break	×
137	}
138	}
139
140	if !logged {	2✔
141	l.Info()	1✔
142	}	1✔
143	} else {	3✔
144	if len(c.Errors) > 0 {	5✔
145	errs := c.Errors.Errors()	2✔
146	var errMsg string	2✔
147	if len(errs) == 1 {	3✔
148	errMsg = errs[0]	1✔
149	} else {	2✔
150	for i, err := range errs {	3✔
151	errMsg = errMsg + fmt.Sprintf(	2✔
152	"#%02d: %s\n", i+1, err,	2✔
153	)	2✔
154	}	2✔
155	}
156	l = l.F(log.Ctx{	2✔
157	"error": errMsg,	2✔
158	})	2✔
159	} else {	1✔
160	l = l.F(log.Ctx{	1✔
161	"error": http.StatusText(code),	1✔
162	})	1✔
163	}	1✔
164	l.Error()	3✔
165	}
166	}
167	}

mendersoftware / go-lib-micro / 1102564227

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