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

0.0

/accesslog/middleware.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 (
        "bytes"
        "fmt"
        "net"
        "net/http"
        "os"
        "path"
        "runtime"
        "strings"
        "text/template"
        "time"

        "github.com/ant0ine/go-json-rest/rest"
        "github.com/sirupsen/logrus"

        "github.com/mendersoftware/go-lib-micro/requestlog"
)

type AccessLogFormat string

const (
        DefaultLogFormat = "%t %S\033[0m \033[36;1m%Dμs\033[0m \"%r\" \033[1;30m%u \"%{User-Agent}i\"\033[0m"
        SimpleLogFormat  = "%s %Dμs %r %u %{User-Agent}i"

        TypeHTTP = "http"
)

// AccesLogMiddleware is a customized version of the AccessLogApacheMiddleware.
// It uses the request-specific custom logger (created by requestlog), which appends the Mender-specific request context.
type AccessLogMiddleware struct {
        Format       AccessLogFormat
        textTemplate *template.Template

        recorder *rest.RecorderMiddleware
}

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,
                "method": r.Method,
                "path":   r.URL.Path,
                "qs":     r.URL.RawQuery,
        }

        if panic := recover(); panic != nil {
                var (
                        trace     [MaxTraceback]uintptr
                        traceback strings.Builder
                )
                n := runtime.Callers(3, 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--
                }
                // 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)
                fields["panic"] = panic
                fields["trace"] = traceback.String()
        }
        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()
        statusCode := util.StatusCode()
        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.
func (mw *AccessLogMiddleware) MiddlewareFunc(h rest.HandlerFunc) rest.HandlerFunc {
        if mw.Format == "" {
                mw.Format = DefaultLogFormat
        }

        mw.convertFormat()

        // This middleware depends on RecorderMiddleware to work
        mw.recorder = new(rest.RecorderMiddleware)
        return mw.recorder.MiddlewareFunc(func(w rest.ResponseWriter, r *rest.Request) {
                startTime := time.Now()
                r.Env["START_TIME"] = startTime
                defer mw.LogFunc(startTime, w, r)
                // call the handler
                h(w, r)
        })
}

var apacheAdapter = strings.NewReplacer(
        "%b", "{{.BytesWritten | dashIf0}}",
        "%B", "{{.BytesWritten}}",
        "%D", "{{.ResponseTime | microseconds}}",
        "%h", "{{.ApacheRemoteAddr}}",
        "%H", "{{.R.Proto}}",
        "%l", "-",
        "%m", "{{.R.Method}}",
        "%P", "{{.Pid}}",
        "%q", "{{.ApacheQueryString}}",
        "%r", "{{.R.Method}} {{.R.URL.RequestURI}} {{.R.Proto}}",
        "%s", "{{.StatusCode}}",
        "%S", "\033[{{.StatusCode | statusCodeColor}}m{{.StatusCode}}",
        "%t", "{{if .StartTime}}{{.StartTime.Format \"02/Jan/2006:15:04:05 -0700\"}}{{end}}",
        "%T", "{{if .ResponseTime}}{{.ResponseTime.Seconds | printf \"%.3f\"}}{{end}}",
        "%u", "{{.RemoteUser | dashIfEmptyStr}}",
        "%{User-Agent}i", "{{.R.UserAgent | dashIfEmptyStr}}",
        "%{Referer}i", "{{.R.Referer | dashIfEmptyStr}}",
)

// Execute the text template with the data derived from the request, and return a string.
func (mw *AccessLogMiddleware) executeTextTemplate(util *accessLogUtil) string {
        buf := bytes.NewBufferString("")
        err := mw.textTemplate.Execute(buf, util)
        if err != nil {
                panic(err)
        }
        return buf.String()
}

func (mw *AccessLogMiddleware) convertFormat() {

        tmplText := apacheAdapter.Replace(string(mw.Format))

        funcMap := template.FuncMap{
                "dashIfEmptyStr": func(value string) string {
                        if value == "" {
                                return "-"
                        }
                        return value
                },
                "dashIf0": func(value int64) string {
                        if value == 0 {
                                return "-"
                        }
                        return fmt.Sprintf("%d", value)
                },
                "microseconds": func(dur *time.Duration) string {
                        if dur != nil {
                                return fmt.Sprintf("%d", dur.Nanoseconds()/1000)
                        }
                        return ""
                },
                "statusCodeColor": func(statusCode int) string {
                        if statusCode >= 400 && statusCode < 500 {
                                return "1;33"
                        } else if statusCode >= 500 {
                                return "0;31"
                        }
                        return "0;32"
                },
        }

        var err error
        mw.textTemplate, err = template.New("accessLog").Funcs(funcMap).Parse(tmplText)
        if err != nil {
                panic(err)
        }
}

// accessLogUtil provides a collection of utility functions that devrive data from the Request object.
// This object is used to provide data to the Apache Style template and the the JSON log record.
type accessLogUtil struct {
        W rest.ResponseWriter
        R *rest.Request
}

// As stored by the auth middlewares.
func (u *accessLogUtil) RemoteUser() string {
        if u.R.Env["REMOTE_USER"] != nil {
                return u.R.Env["REMOTE_USER"].(string)
        }
        return ""
}

// If qs exists then return it with a leadin "?", apache log style.
func (u *accessLogUtil) ApacheQueryString() string {
        if u.R.URL.RawQuery != "" {
                return "?" + u.R.URL.RawQuery
        }
        return ""
}

// When the request entered the timer middleware.
func (u *accessLogUtil) StartTime() *time.Time {
        if u.R.Env["START_TIME"] != nil {
                return u.R.Env["START_TIME"].(*time.Time)
        }
        return nil
}

// If remoteAddr is set then return is without the port number, apache log style.
func (u *accessLogUtil) ApacheRemoteAddr() string {
        remoteAddr := u.R.RemoteAddr
        if remoteAddr != "" {
                if ip, _, err := net.SplitHostPort(remoteAddr); err == nil {
                        return ip
                }
        }
        return ""
}

// As recorded by the recorder middleware.
func (u *accessLogUtil) StatusCode() int {
        if u.R.Env["STATUS_CODE"] != nil {
                return u.R.Env["STATUS_CODE"].(int)
        }
        return 0
}

// As mesured by the timer middleware.
func (u *accessLogUtil) ResponseTime() *time.Duration {
        if u.R.Env["ELAPSED_TIME"] != nil {
                return u.R.Env["ELAPSED_TIME"].(*time.Duration)
        }
        return nil
}

// Process id.
func (u *accessLogUtil) Pid() int {
        return os.Getpid()
}

// As recorded by the recorder middleware.
func (u *accessLogUtil) BytesWritten() int64 {
        if u.R.Env["BYTES_WRITTEN"] != nil {
                return u.R.Env["BYTES_WRITTEN"].(int64)
        }
        return 0
}

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	package accesslog
15
16	import (
17	"bytes"
18	"fmt"
19	"net"
20	"net/http"
21	"os"
22	"path"
23	"runtime"
24	"strings"
25	"text/template"
26	"time"
27
28	"github.com/ant0ine/go-json-rest/rest"
29	"github.com/sirupsen/logrus"
30
31	"github.com/mendersoftware/go-lib-micro/requestlog"
32	)
33
34	type AccessLogFormat string
35
36	const (
37	DefaultLogFormat = "%t %S\033[0m \033[36;1m%Dμs\033[0m \"%r\" \033[1;30m%u \"%{User-Agent}i\"\033[0m"
38	SimpleLogFormat = "%s %Dμs %r %u %{User-Agent}i"
39
40	TypeHTTP = "http"
41	)
42
43	// AccesLogMiddleware is a customized version of the AccessLogApacheMiddleware.
44	// It uses the request-specific custom logger (created by requestlog), which appends the Mender-specific request context.
45	type AccessLogMiddleware struct {
46	Format AccessLogFormat
47	textTemplate *template.Template
48
49	recorder *rest.RecorderMiddleware
50	}
51
NEW 52	func (mw AccessLogMiddleware) LogFunc(startTime time.Time, w rest.ResponseWriter, r rest.Request) {	×
NEW 53	util := &accessLogUtil{w, r}	×
NEW 54	fields := logrus.Fields{	×
NEW 55	"type": r.Proto,	×
NEW 56	"ts": startTime,	×
NEW 57	"method": r.Method,	×
NEW 58	"path": r.URL.Path,	×
NEW 59	"qs": r.URL.RawQuery,	×
NEW 60	}	×
NEW 61		×
NEW 62	if panic := recover(); panic != nil {	×
NEW 63	var (	×
NEW 64	trace [MaxTraceback]uintptr	×
NEW 65	traceback strings.Builder	×
NEW 66	)	×
NEW 67	n := runtime.Callers(3, trace[:])	×
NEW 68	frames := runtime.CallersFrames(trace[:n])	×
NEW 69	for frame, more := frames.Next(); frame.PC != 0 &&	×
NEW 70	n >= 0; frame, more = frames.Next() {	×
NEW 71	funcName := frame.Function	×
NEW 72	if funcName == "" {	×
NEW 73	fmt.Fprint(&traceback, "???\n")	×
NEW 74	} else {	×
NEW 75	fmt.Fprintf(&traceback, "%s@%s:%d",	×
NEW 76	frame.Function,	×
NEW 77	path.Base(frame.File),	×
NEW 78	frame.Line,	×
NEW 79	)	×
NEW 80	}	×
NEW 81	if more {	×
NEW 82	fmt.Fprintln(&traceback)	×
NEW 83	}	×
NEW 84	n--	×
85	}
86	// Wrap in recorder middleware to make sure the response is recorded
NEW 87	mw.recorder.MiddlewareFunc(func(w rest.ResponseWriter, r *rest.Request) {	×
NEW 88	rest.Error(w, "Internal Server Error", http.StatusInternalServerError)	×
NEW 89	})(w, r)	×
NEW 90	fields["panic"] = panic	×
NEW 91	fields["trace"] = traceback.String()	×
92	}
NEW 93	rspTime := time.Since(startTime)	×
NEW 94	r.Env["ELAPSED_TIME"] = &rspTime	×
NEW 95	// We do not need more than 3 digit fraction	×
NEW 96	if rspTime > time.Second {	×
NEW 97	rspTime = rspTime.Round(time.Millisecond)	×
NEW 98	} else if rspTime > time.Millisecond {	×
NEW 99	rspTime = rspTime.Round(time.Microsecond)	×
NEW 100	}	×
NEW 101	fields["responsetime"] = rspTime.String()	×
NEW 102	fields["byteswritten"] = util.BytesWritten()	×
NEW 103	statusCode := util.StatusCode()	×
NEW 104	fields["status"] = statusCode	×
NEW 105		×
NEW 106	logger := requestlog.GetRequestLogger(r)	×
NEW 107	var level logrus.Level = logrus.InfoLevel	×
NEW 108	if statusCode >= 500 {	×
NEW 109	level = logrus.ErrorLevel	×
NEW 110	} else if statusCode >= 300 {	×
NEW 111	level = logrus.WarnLevel	×
NEW 112	}	×
NEW 113	logger.WithFields(fields).	×
NEW 114	Log(level, mw.executeTextTemplate(util))	×
115	}
116
117	// MiddlewareFunc makes AccessLogMiddleware implement the Middleware interface.
118	func (mw *AccessLogMiddleware) MiddlewareFunc(h rest.HandlerFunc) rest.HandlerFunc {	×
119	if mw.Format == "" {	×
120	mw.Format = DefaultLogFormat	×
121	}	×
122
123	mw.convertFormat()	×
124		×
NEW 125	// This middleware depends on RecorderMiddleware to work	×
NEW 126	mw.recorder = new(rest.RecorderMiddleware)	×
NEW 127	return mw.recorder.MiddlewareFunc(func(w rest.ResponseWriter, r *rest.Request) {	×
NEW 128	startTime := time.Now()	×
NEW 129	r.Env["START_TIME"] = startTime	×
NEW 130	defer mw.LogFunc(startTime, w, r)	×
131	// call the handler	×
132	h(w, r)	×
NEW 133	})	×
134	}
135
136	var apacheAdapter = strings.NewReplacer(
137	"%b", "{{.BytesWritten \| dashIf0}}",
138	"%B", "{{.BytesWritten}}",
139	"%D", "{{.ResponseTime \| microseconds}}",
140	"%h", "{{.ApacheRemoteAddr}}",
141	"%H", "{{.R.Proto}}",
142	"%l", "-",
143	"%m", "{{.R.Method}}",
144	"%P", "{{.Pid}}",
145	"%q", "{{.ApacheQueryString}}",
146	"%r", "{{.R.Method}} {{.R.URL.RequestURI}} {{.R.Proto}}",
147	"%s", "{{.StatusCode}}",
148	"%S", "\033[{{.StatusCode \| statusCodeColor}}m{{.StatusCode}}",
149	"%t", "{{if .StartTime}}{{.StartTime.Format \"02/Jan/2006:15:04:05 -0700\"}}{{end}}",
150	"%T", "{{if .ResponseTime}}{{.ResponseTime.Seconds \| printf \"%.3f\"}}{{end}}",
151	"%u", "{{.RemoteUser \| dashIfEmptyStr}}",
152	"%{User-Agent}i", "{{.R.UserAgent \| dashIfEmptyStr}}",
153	"%{Referer}i", "{{.R.Referer \| dashIfEmptyStr}}",
154	)
155
156	// Execute the text template with the data derived from the request, and return a string.
UNCOV 157	func (mw AccessLogMiddleware) executeTextTemplate(util accessLogUtil) string {	×
UNCOV 158	buf := bytes.NewBufferString("")	×
UNCOV 159	err := mw.textTemplate.Execute(buf, util)	×
UNCOV 160	if err != nil {	×
UNCOV 161	panic(err)	×
162	}
UNCOV 163	return buf.String()	×
164	}
165
UNCOV 166	func (mw *AccessLogMiddleware) convertFormat() {	×
UNCOV 167		×
UNCOV 168	tmplText := apacheAdapter.Replace(string(mw.Format))	×
UNCOV 169		×
UNCOV 170	funcMap := template.FuncMap{	×
UNCOV 171	"dashIfEmptyStr": func(value string) string {	×
UNCOV 172	if value == "" {	×
UNCOV 173	return "-"	×
UNCOV 174	}	×
UNCOV 175	return value	×
176	},
177	"dashIf0": func(value int64) string {	×
178	if value == 0 {	×
179	return "-"	×
180	}	×
UNCOV 181	return fmt.Sprintf("%d", value)	×
182	},
UNCOV 183	"microseconds": func(dur *time.Duration) string {	×
UNCOV 184	if dur != nil {	×
185	return fmt.Sprintf("%d", dur.Nanoseconds()/1000)	×
186	}	×
187	return ""	×
188	},
189	"statusCodeColor": func(statusCode int) string {	×
190	if statusCode >= 400 && statusCode < 500 {	×
191	return "1;33"	×
192	} else if statusCode >= 500 {	×
193	return "0;31"	×
194	}	×
UNCOV 195	return "0;32"	×
196	},
197	}
198
199	var err error	×
200	mw.textTemplate, err = template.New("accessLog").Funcs(funcMap).Parse(tmplText)	×
UNCOV 201	if err != nil {	×
202	panic(err)	×
203	}
204	}
205
206	// accessLogUtil provides a collection of utility functions that devrive data from the Request object.
207	// This object is used to provide data to the Apache Style template and the the JSON log record.
208	type accessLogUtil struct {
209	W rest.ResponseWriter
210	R *rest.Request
211	}
212
213	// As stored by the auth middlewares.
214	func (u *accessLogUtil) RemoteUser() string {	×
UNCOV 215	if u.R.Env["REMOTE_USER"] != nil {	×
UNCOV 216	return u.R.Env["REMOTE_USER"].(string)	×
UNCOV 217	}	×
218	return ""	×
219	}
220
221	// If qs exists then return it with a leadin "?", apache log style.
UNCOV 222	func (u *accessLogUtil) ApacheQueryString() string {	×
UNCOV 223	if u.R.URL.RawQuery != "" {	×
UNCOV 224	return "?" + u.R.URL.RawQuery	×
UNCOV 225	}	×
UNCOV 226	return ""	×
227	}
228
229	// When the request entered the timer middleware.
UNCOV 230	func (u accessLogUtil) StartTime() time.Time {	×
UNCOV 231	if u.R.Env["START_TIME"] != nil {	×
UNCOV 232	return u.R.Env["START_TIME"].(*time.Time)	×
233	}	×
234	return nil	×
235	}
236
237	// If remoteAddr is set then return is without the port number, apache log style.
UNCOV 238	func (u *accessLogUtil) ApacheRemoteAddr() string {	×
UNCOV 239	remoteAddr := u.R.RemoteAddr	×
UNCOV 240	if remoteAddr != "" {	×
241	if ip, _, err := net.SplitHostPort(remoteAddr); err == nil {	×
242	return ip	×
243	}	×
244	}
245	return ""	×
246	}
247
248	// As recorded by the recorder middleware.
249	func (u *accessLogUtil) StatusCode() int {	×
250	if u.R.Env["STATUS_CODE"] != nil {	×
251	return u.R.Env["STATUS_CODE"].(int)	×
252	}	×
253	return 0	×
254	}
255
256	// As mesured by the timer middleware.
257	func (u accessLogUtil) ResponseTime() time.Duration {	×
258	if u.R.Env["ELAPSED_TIME"] != nil {	×
259	return u.R.Env["ELAPSED_TIME"].(*time.Duration)	×
260	}	×
261	return nil	×
262	}
263
264	// Process id.
UNCOV 265	func (u *accessLogUtil) Pid() int {	×
UNCOV 266	return os.Getpid()	×
UNCOV 267	}	×
268
269	// As recorded by the recorder middleware.
270	func (u *accessLogUtil) BytesWritten() int64 {	×
271	if u.R.Env["BYTES_WRITTEN"] != nil {	×
272	return u.R.Env["BYTES_WRITTEN"].(int64)	×
UNCOV 273	}	×
UNCOV 274	return 0	×
275	}

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