From 863df602eae9971f86d1a8d37f8870d86707c5b8 Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 14:28:58 +1100 Subject: [PATCH 1/9] logging rework wip --- core/requests.go | 18 +++++++++++++----- server/audit/audit_init.go | 3 +-- server/audit/audit_log.go | 28 ++++++++++++++++++++-------- server/audit/spans.go | 4 ++-- 4 files changed, 36 insertions(+), 17 deletions(-) diff --git a/core/requests.go b/core/requests.go index bbba8bf..da1e524 100644 --- a/core/requests.go +++ b/core/requests.go @@ -32,10 +32,17 @@ func init() { retryClient.RetryWaitMin = config.GlobalConfig.APIBaseTimeout retryClient.RetryWaitMax = config.GlobalConfig.APIMaxBackoffTime retryClient.HTTPClient = utils.HttpClient + retryClient.Logger = nil // Disables the default logger in go-retryablehttp } // retryRequest performs a request with automatic retries and token management -func retryRequest(ctx context.Context, reqFunc func(context.Context, string) (*retryablehttp.Request, error), userToken string, isPost bool) (*SimpleHTTPResponse, error) { +func retryRequest( + ctx context.Context, + reqFunc func(context.Context, string) (*retryablehttp.Request, error), + userToken string, + isPost bool, + url string, // used for logging in audit.LogAPIRoundTrip only +) (*SimpleHTTPResponse, error) { var lastErr error tokenManager := config.GlobalConfig.TokenManager @@ -88,14 +95,15 @@ Please refer the following documentation for additional information: } audit.LogAPIRoundTrip(audit.APIRequestSpan{ + StartTime: start, + EndTime: end, RequestId: request_context.GetFromContext(ctx).RequestId, Response: resp, Error: err, Method: req.Method, + Url: url, Token: tokenValue, Body: string(body), - StartTime: start, - EndTime: end, }) if resp.StatusCode == http.StatusOK { @@ -140,7 +148,7 @@ func API_GET(ctx context.Context, url string, userToken string) (*SimpleHTTPResp Value: token, }) return req, nil - }, userToken, false) + }, userToken, false, url) } // API_GET_UnwrapJson performs a GET request and unwraps the JSON response @@ -192,7 +200,7 @@ func API_POST(ctx context.Context, url, payload, userToken, csrf string, isJSON req.Header.Add("Content-Type", "application/x-www-form-urlencoded; charset=utf-8") } return req, nil - }, userToken, true) + }, userToken, true, url) return err } diff --git a/server/audit/audit_init.go b/server/audit/audit_init.go index 5b27400..1d953a0 100644 --- a/server/audit/audit_init.go +++ b/server/audit/audit_init.go @@ -1,7 +1,6 @@ package audit import ( - "log" "os" "codeberg.org/vnpower/pixivfe/v2/config" @@ -25,7 +24,7 @@ func Init(saveResponse bool) error { savePath := config.GlobalConfig.ResponseSaveLocation if err := os.MkdirAll(savePath, 0o700); err != nil { - log.Printf("Error creating response save directory: %v", err) + standardLog("ERROR", "Failed to create response save directory", err) return i18n.Errorf("failed to create response save directory: %w", err) } diff --git a/server/audit/audit_log.go b/server/audit/audit_log.go index bd99e60..44b099b 100644 --- a/server/audit/audit_log.go +++ b/server/audit/audit_log.go @@ -1,8 +1,7 @@ -// Package audit provides functionality for logging and recording various types of spans -// in the application, including server requests and API calls. package audit import ( + "fmt" "log" "os" "path" @@ -20,11 +19,22 @@ var Logger = log.New(os.Stderr, "", 0) // RecordedSpans stores a slice of recorded Span objects for later analysis or debugging. var RecordedSpans = []Span{} +// standardLog logs messages in a standardized format. +func standardLog(logType string, message string, err error) { + timestamp := time.Now().Format("2006-01-02 15:04:05.000") + errStr := "" + if err != nil { + errStr = fmt.Sprintf(" error=%v", err) + } + Logger.Printf("%s %s %s locale=%s%s", timestamp, logType, message, i18n.GetLocale(), errStr) +} + // LogAndRecord logs the given span and optionally records it in the RecordedSpans slice. // It manages the RecordedSpans slice to maintain a maximum number of recorded spans. func LogAndRecord(span Span) { - // Log the span with a formatted timestamp, duration, and log line - Logger.Printf("%v +%-5.3f %s locale=%s", span.GetStartTime().Format("2006-01-02 15:04:05.000"), float64(Duration(span))/float64(time.Second), span.LogLine(), i18n.GetLocale()) + duration := float64(Duration(span)) / float64(time.Second) + message := fmt.Sprintf("+%-5.3f %s", duration, span.LogLine()) + standardLog("INFO", message, nil) // If MaxRecordedCount is set, manage the RecordedSpans slice if MaxRecordedCount != 0 { @@ -41,7 +51,7 @@ func LogAndRecord(span Span) { // It also logs any internal server errors that occurred during the request. func LogServerRoundTrip(perf ServedRequestSpan) { if perf.Error != nil { - log.Printf("Internal Server Error: %s", perf.Error) + standardLog("ERROR", "Internal Server Error", perf.Error) } LogAndRecord(perf) @@ -56,12 +66,12 @@ func LogAPIRoundTrip(perf APIRequestSpan) { var err error perf.ResponseFilename, err = writeResponseBodyToFile(perf.Body) if err != nil { - log.Print("When saving response to file: ", err) + standardLog("ERROR", "Failed to save response to file", err) } } // Log a warning for non-2xx status codes if !(300 > perf.Response.StatusCode && perf.Response.StatusCode >= 200) { - log.Print("(WARN) non-2xx response from pixiv:") + standardLog("WARN", fmt.Sprintf("Non-2xx response from pixiv: %d", perf.Response.StatusCode), nil) } } @@ -73,13 +83,15 @@ func LogAPIRoundTrip(perf APIRequestSpan) { func writeResponseBodyToFile(body string) (string, error) { // Generate a unique ID using ULID id := ulid.Make().String() + // Create a filename using the last 6 characters of the ID filename := path.Join(config.GlobalConfig.ResponseSaveLocation, id[len(id)-6:]) + // Write the body to the file with read/write permissions for the owner only err := os.WriteFile(filename, []byte(body), 0o600) if err != nil { return "", i18n.Errorf("failed to write response body to file %s: %w", filename, err) } - log.Printf("Successfully wrote response body to file: %s", filename) + return filename, nil } diff --git a/server/audit/spans.go b/server/audit/spans.go index 35d6221..4986f99 100644 --- a/server/audit/spans.go +++ b/server/audit/spans.go @@ -39,7 +39,7 @@ func (span ServedRequestSpan) GetRequestId() string { return span.RequestId } func (span ServedRequestSpan) LogLine() string { - return fmt.Sprintf("%v %v %v %v", span.Method, span.Path, span.Status, span.Error) + return fmt.Sprintf("SERVER method=%s path=%s status=%d error=%v", span.Method, span.Path, span.Status, span.Error) } type APIRequestSpan struct { @@ -65,5 +65,5 @@ func (span APIRequestSpan) GetRequestId() string { return span.RequestId } func (span APIRequestSpan) LogLine() string { - return fmt.Sprintf("-> %v %v %v %v", span.Method, span.Url, span.Error, span.ResponseFilename) + return fmt.Sprintf("API method=%s url=%s error=%v responseFile=%s", span.Method, span.Url, span.Error, span.ResponseFilename) } From adc226dd72a276b24432678587e6ca32a40aa070 Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 14:59:39 +1100 Subject: [PATCH 2/9] zap for logging wip --- go.mod | 2 ++ go.sum | 6 ++++ i18n/converter/main.go | 2 +- i18n/exceptions.go | 14 +++++----- i18n/locale/en/code.json | 1 + server/audit/audit_init.go | 18 +++++++++++- server/audit/audit_log.go | 41 ++++++++++++++-------------- server/audit/spans.go | 53 ++++++++++++++++++++++++++++++++---- server/routes/diagnostics.go | 16 ++++++++++- server/routes/user.go | 26 +++++++++--------- server/template/render.go | 10 +++++-- 11 files changed, 138 insertions(+), 51 deletions(-) diff --git a/go.mod b/go.mod index 4e3aa73..21bd638 100644 --- a/go.mod +++ b/go.mod @@ -23,6 +23,7 @@ require ( github.com/timandy/routine v1.1.4 github.com/yargevad/filepathx v1.0.0 github.com/zeebo/xxh3 v1.0.2 + go.uber.org/zap v1.27.0 golang.org/x/net v0.30.0 ) @@ -32,5 +33,6 @@ require ( github.com/klauspost/cpuid/v2 v2.0.9 // indirect github.com/tidwall/match v1.1.1 // indirect github.com/tidwall/pretty v1.2.0 // indirect + go.uber.org/multierr v1.11.0 // indirect golang.org/x/text v0.19.0 // indirect ) diff --git a/go.sum b/go.sum index 276ac64..3b61723 100644 --- a/go.sum +++ b/go.sum @@ -58,6 +58,12 @@ github.com/zeebo/assert v1.3.0 h1:g7C04CbJuIDKNPFHmsk4hwZDO5O+kntRxzaUoNXj+IQ= github.com/zeebo/assert v1.3.0/go.mod h1:Pq9JiuJQpG8JLJdtkwrJESF0Foym2/D9XMU5ciN/wJ0= github.com/zeebo/xxh3 v1.0.2 h1:xZmwmqxHZA8AI603jOQ0tMqmBr9lPeFwGg6d+xy9DC0= github.com/zeebo/xxh3 v1.0.2/go.mod h1:5NWz9Sef7zIDm2JHfFlcQvNekmcEl9ekUZQQKCYaDcA= +go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto= +go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE= +go.uber.org/multierr v1.11.0 h1:blXXJkSxSSfBVBlC76pxqeO+LN3aDfLQo+309xJstO0= +go.uber.org/multierr v1.11.0/go.mod h1:20+QtiLqy0Nd6FdQB9TLXag12DsQkrbs3htMFfDN80Y= +go.uber.org/zap v1.27.0 h1:aJMhYGrd5QSmlpLMr2MftRKl7t8J8PTZPA732ud/XR8= +go.uber.org/zap v1.27.0/go.mod h1:GB2qFLM7cTU87MWRP2mPIjqfIDnGu+VIO4V/SdhGo2E= golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w= golang.org/x/crypto v0.0.0-20210921155107-089bfa567519/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc= golang.org/x/mod v0.6.0-dev.0.20220419223038-86c51ed26bb4/go.mod h1:jJ57K6gSWd91VN4djpZkiMVwK6gcyfeH4XE8wZrZaV4= diff --git a/i18n/converter/main.go b/i18n/converter/main.go index d045228..d666c30 100644 --- a/i18n/converter/main.go +++ b/i18n/converter/main.go @@ -23,6 +23,6 @@ func main() { } encoder := json.NewEncoder(os.Stdout) encoder.SetEscapeHTML(false) - encoder.SetIndent("", " ") + encoder.SetIndent("", " ") encoder.Encode(translation_map) } diff --git a/i18n/exceptions.go b/i18n/exceptions.go index 6f68045..38bca9b 100644 --- a/i18n/exceptions.go +++ b/i18n/exceptions.go @@ -1,10 +1,10 @@ package i18n -var IgnoreTheseStrings = map[string]bool { - "": true, - "»": true, - "▶": true, - "⧉ {{ .Pages }}": true, - "PixivFE": true, - "pixiv.net/i/{{ .ID }}": true, +var IgnoreTheseStrings = map[string]bool{ + "": true, + "»": true, + "▶": true, + "⧉ {{ .Pages }}": true, + "PixivFE": true, + "pixiv.net/i/{{ .ID }}": true, } diff --git a/i18n/locale/en/code.json b/i18n/locale/en/code.json index da2d671..0cca096 100644 --- a/i18n/locale/en/code.json +++ b/i18n/locale/en/code.json @@ -31,6 +31,7 @@ "core/requests.go:y3v5nQwdU0s": "All tokens (%d) are timed out, resetting all tokens to their initial good state.\nConsider providing additional tokens in PIXIVFE_TOKEN or reviewing API request level backoff configuration.\nPlease refer the following documentation for additional information:\n- https://pixivfe-docs.pages.dev/hosting/obtaining-pixivfe-token/\n- https://pixivfe-docs.pages.dev/hosting/environment-variables/#exponential-backoff-configuration", "core/user.go:1itpJBE-3VI": "Invalid page number.", "core/user.go:T3RwaHcnsYQ": "Invalid work category: %#v. Only \"%s\", \"%s\", \"%s\", \"%s\", \"%s\" and \"%s\" are available", + "server/audit/audit_init.go:RVQo5OR9IKs": "failed to initialize zap logger: %w", "server/audit/audit_init.go:k5XgFtfJlBA": "failed to create response save directory: %w", "server/audit/audit_log.go:PoqY_pYG5lo": "failed to write response body to file %s: %w", "server/middleware/router.go:HORkE0Obn1U": "Failed to redirect to %s", diff --git a/server/audit/audit_init.go b/server/audit/audit_init.go index 1d953a0..7d9db2b 100644 --- a/server/audit/audit_init.go +++ b/server/audit/audit_init.go @@ -5,10 +5,13 @@ import ( "codeberg.org/vnpower/pixivfe/v2/config" "codeberg.org/vnpower/pixivfe/v2/i18n" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" ) var optionSaveResponse bool var MaxRecordedCount = 0 +var logger *zap.Logger // Init initializes the audit package and sets up response saving if enabled. // saveResponse is passed as a boolean from main.go. @@ -16,6 +19,16 @@ var MaxRecordedCount = 0 func Init(saveResponse bool) error { optionSaveResponse = saveResponse + // Initialize zap logger + zapConfig := zap.NewProductionConfig() + zapConfig.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder + zapConfig.OutputPaths = []string{"stderr"} + var err error + logger, err = zapConfig.Build() + if err != nil { + return i18n.Errorf("failed to initialize zap logger: %w", err) + } + if !optionSaveResponse { return nil } @@ -24,7 +37,10 @@ func Init(saveResponse bool) error { savePath := config.GlobalConfig.ResponseSaveLocation if err := os.MkdirAll(savePath, 0o700); err != nil { - standardLog("ERROR", "Failed to create response save directory", err) + logger.Error("Failed to create response save directory", + zap.Error(err), + zap.String("path", savePath), + ) return i18n.Errorf("failed to create response save directory: %w", err) } diff --git a/server/audit/audit_log.go b/server/audit/audit_log.go index 44b099b..c1bb202 100644 --- a/server/audit/audit_log.go +++ b/server/audit/audit_log.go @@ -1,40 +1,32 @@ package audit import ( - "fmt" - "log" "os" "path" "time" "github.com/oklog/ulid/v2" + "go.uber.org/zap" "codeberg.org/vnpower/pixivfe/v2/config" "codeberg.org/vnpower/pixivfe/v2/i18n" ) -// Logger is a custom logger with no timestamp prefix, as we control the timestamps in our log messages. -var Logger = log.New(os.Stderr, "", 0) - // RecordedSpans stores a slice of recorded Span objects for later analysis or debugging. var RecordedSpans = []Span{} -// standardLog logs messages in a standardized format. -func standardLog(logType string, message string, err error) { - timestamp := time.Now().Format("2006-01-02 15:04:05.000") - errStr := "" - if err != nil { - errStr = fmt.Sprintf(" error=%v", err) - } - Logger.Printf("%s %s %s locale=%s%s", timestamp, logType, message, i18n.GetLocale(), errStr) -} - // LogAndRecord logs the given span and optionally records it in the RecordedSpans slice. // It manages the RecordedSpans slice to maintain a maximum number of recorded spans. func LogAndRecord(span Span) { duration := float64(Duration(span)) / float64(time.Second) - message := fmt.Sprintf("+%-5.3f %s", duration, span.LogLine()) - standardLog("INFO", message, nil) + + logger.Info("Span recorded", + zap.String("timestamp", span.GetStartTime().Format(time.RFC3339)), + zap.String("component", span.Component()), + zap.Any("action", span.Action()), + zap.Any("outcome", span.Outcome()), + zap.Float64("duration", duration), + ) // If MaxRecordedCount is set, manage the RecordedSpans slice if MaxRecordedCount != 0 { @@ -51,7 +43,10 @@ func LogAndRecord(span Span) { // It also logs any internal server errors that occurred during the request. func LogServerRoundTrip(perf ServedRequestSpan) { if perf.Error != nil { - standardLog("ERROR", "Internal Server Error", perf.Error) + logger.Error("Internal Server Error", + zap.Error(perf.Error), + zap.String("requestId", perf.RequestId), + ) } LogAndRecord(perf) @@ -66,12 +61,18 @@ func LogAPIRoundTrip(perf APIRequestSpan) { var err error perf.ResponseFilename, err = writeResponseBodyToFile(perf.Body) if err != nil { - standardLog("ERROR", "Failed to save response to file", err) + logger.Error("Failed to save response to file", + zap.Error(err), + zap.String("requestId", perf.RequestId), + ) } } // Log a warning for non-2xx status codes if !(300 > perf.Response.StatusCode && perf.Response.StatusCode >= 200) { - standardLog("WARN", fmt.Sprintf("Non-2xx response from pixiv: %d", perf.Response.StatusCode), nil) + logger.Warn("Non-2xx response from pixiv", + zap.Int("status", perf.Response.StatusCode), + zap.String("requestId", perf.RequestId), + ) } } diff --git a/server/audit/spans.go b/server/audit/spans.go index 4986f99..07c9feb 100644 --- a/server/audit/spans.go +++ b/server/audit/spans.go @@ -1,7 +1,7 @@ package audit import ( - "fmt" + "codeberg.org/vnpower/pixivfe/v2/i18n" "net/http" "time" ) @@ -10,7 +10,9 @@ type Span interface { GetStartTime() time.Time GetEndTime() time.Time GetRequestId() string - LogLine() string + Component() string + Action() map[string]interface{} + Outcome() map[string]interface{} } func Duration(span Span) time.Duration { @@ -38,8 +40,25 @@ func (span ServedRequestSpan) GetEndTime() time.Time { func (span ServedRequestSpan) GetRequestId() string { return span.RequestId } -func (span ServedRequestSpan) LogLine() string { - return fmt.Sprintf("SERVER method=%s path=%s status=%d error=%v", span.Method, span.Path, span.Status, span.Error) +func (span ServedRequestSpan) Component() string { + return "SERVER" +} +func (span ServedRequestSpan) Action() map[string]interface{} { + return map[string]interface{}{ + "method": span.Method, + "path": span.Path, + } +} +func (span ServedRequestSpan) Outcome() map[string]interface{} { + outcome := map[string]interface{}{ + "status": span.Status, + "error": "", + "locale": i18n.GetLocale(), + } + if span.Error != nil { + outcome["error"] = span.Error.Error() + } + return outcome } type APIRequestSpan struct { @@ -64,6 +83,28 @@ func (span APIRequestSpan) GetEndTime() time.Time { func (span APIRequestSpan) GetRequestId() string { return span.RequestId } -func (span APIRequestSpan) LogLine() string { - return fmt.Sprintf("API method=%s url=%s error=%v responseFile=%s", span.Method, span.Url, span.Error, span.ResponseFilename) +func (span APIRequestSpan) Component() string { + return "API" +} +func (span APIRequestSpan) Action() map[string]interface{} { + return map[string]interface{}{ + "method": span.Method, + "url": span.Url, + "response_file": span.ResponseFilename, + } +} +func (span APIRequestSpan) Outcome() map[string]interface{} { + outcome := map[string]interface{}{ + "status": "success", + "error": "", + "locale": i18n.GetLocale(), + } + if span.Error != nil { + outcome["status"] = "error" + outcome["error"] = span.Error.Error() + } + if span.Response != nil { + outcome["status_code"] = span.Response.StatusCode + } + return outcome } diff --git a/server/routes/diagnostics.go b/server/routes/diagnostics.go index 379dc7f..2b2611a 100644 --- a/server/routes/diagnostics.go +++ b/server/routes/diagnostics.go @@ -1,7 +1,9 @@ package routes import ( + "fmt" "net/http" + "time" "github.com/goccy/go-json" "github.com/soluble-ai/go-jnode" @@ -19,6 +21,18 @@ func ResetDiagnosticsData(w http.ResponseWriter, r *http.Request) { utils.RedirectToWhenceYouCame(w, r) } +// formatSpanSummary creates a SpanSummary string from audit.Span +func formatSpanSummary(span audit.Span) string { + duration := float64(audit.Duration(span)) / float64(time.Second) + return fmt.Sprintf("%s - %s - %v - %v - %.3fs", + span.GetStartTime().Format(time.RFC3339), + span.Component(), + span.Action(), + span.Outcome(), + duration, + ) +} + func DiagnosticsData(w http.ResponseWriter, _ *http.Request) error { data := jnode.NewArrayNode() for _, span := range audit.RecordedSpans { @@ -30,7 +44,7 @@ func DiagnosticsData(w http.ResponseWriter, _ *http.Request) error { if err != nil { return err } - obj.Put("LogLine", span.LogLine()) + obj.Put("SpanSummary", formatSpanSummary(span)) data.Append(obj) } w.Header().Set("content-type", "application/json") diff --git a/server/routes/user.go b/server/routes/user.go index 604cc2b..fbcb6e8 100644 --- a/server/routes/user.go +++ b/server/routes/user.go @@ -50,12 +50,12 @@ func fetchData(r *http.Request, getTags bool) (userPageData, error) { worksCount = user.CategoryItemCount pageLimit := int(math.Ceil(float64(worksCount) / worksPerPage)) - return userPageData{ - user: user, - category: category, - pageLimit: pageLimit, - page: page, - }, nil + return userPageData{ + user: user, + category: category, + pageLimit: pageLimit, + page: page, + }, nil } func UserPage(w http.ResponseWriter, r *http.Request) error { @@ -65,13 +65,13 @@ func UserPage(w http.ResponseWriter, r *http.Request) error { } return RenderHTML(w, r, Data_user{ - Title: data.user.Name, - User: data.user, - Category: data.category, - PageLimit: data.pageLimit, - Page: data.page, - MetaImage: data.user.BackgroundImage, -}) + Title: data.user.Name, + User: data.user, + Category: data.category, + PageLimit: data.pageLimit, + Page: data.page, + MetaImage: data.user.BackgroundImage, + }) } func UserAtomFeed(w http.ResponseWriter, r *http.Request) error { diff --git a/server/template/render.go b/server/template/render.go index 1bb5406..bde7436 100644 --- a/server/template/render.go +++ b/server/template/render.go @@ -55,11 +55,17 @@ func GetTemplatingVariables(r *http.Request) jet.VarMap { pageURL := r.URL.String() cookies := map[string]string{} - cookies_ordered := []struct{k string; v string}{} + cookies_ordered := []struct { + k string + v string + }{} for _, name := range session.AllCookieNames { value := session.GetCookie(r, name) cookies[string(name)] = value - cookies_ordered = append(cookies_ordered, struct{k string; v string}{string(name), value}) + cookies_ordered = append(cookies_ordered, struct { + k string + v string + }{string(name), value}) } queries := make(map[string]string) From 9b8efff3b61c53cbedca46e3d4a667bc6a687347 Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 15:03:31 +1100 Subject: [PATCH 3/9] audit: rename perf variable to requestSpan --- server/audit/audit_log.go | 28 ++++++++++++++-------------- 1 file changed, 14 insertions(+), 14 deletions(-) diff --git a/server/audit/audit_log.go b/server/audit/audit_log.go index c1bb202..a4c4d8f 100644 --- a/server/audit/audit_log.go +++ b/server/audit/audit_log.go @@ -41,42 +41,42 @@ func LogAndRecord(span Span) { // LogServerRoundTrip logs and records a server request span. // It also logs any internal server errors that occurred during the request. -func LogServerRoundTrip(perf ServedRequestSpan) { - if perf.Error != nil { +func LogServerRoundTrip(requestSpan ServedRequestSpan) { + if requestSpan.Error != nil { logger.Error("Internal Server Error", - zap.Error(perf.Error), - zap.String("requestId", perf.RequestId), + zap.Error(requestSpan.Error), + zap.String("requestId", requestSpan.RequestId), ) } - LogAndRecord(perf) + LogAndRecord(requestSpan) } // LogAPIRoundTrip logs and records an API request span. // It handles saving the response body to a file if enabled and logs warnings for non-2xx status codes. -func LogAPIRoundTrip(perf APIRequestSpan) { - if perf.Response != nil { +func LogAPIRoundTrip(requestSpan APIRequestSpan) { + if requestSpan.Response != nil { // Save response body to file if enabled and body is not empty - if perf.Body != "" && optionSaveResponse { + if requestSpan.Body != "" && optionSaveResponse { var err error - perf.ResponseFilename, err = writeResponseBodyToFile(perf.Body) + requestSpan.ResponseFilename, err = writeResponseBodyToFile(requestSpan.Body) if err != nil { logger.Error("Failed to save response to file", zap.Error(err), - zap.String("requestId", perf.RequestId), + zap.String("requestId", requestSpan.RequestId), ) } } // Log a warning for non-2xx status codes - if !(300 > perf.Response.StatusCode && perf.Response.StatusCode >= 200) { + if !(300 > requestSpan.Response.StatusCode && requestSpan.Response.StatusCode >= 200) { logger.Warn("Non-2xx response from pixiv", - zap.Int("status", perf.Response.StatusCode), - zap.String("requestId", perf.RequestId), + zap.Int("status", requestSpan.Response.StatusCode), + zap.String("requestId", requestSpan.RequestId), ) } } - LogAndRecord(perf) + LogAndRecord(requestSpan) } // writeResponseBodyToFile saves the given response body to a file in the ResponseSaveLocation directory. From ba7646942252df8ba0209e04c8bec8ed17bd311c Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 15:26:34 +1100 Subject: [PATCH 4/9] logging configuration --- .env.example | 5 ++++ config/config.go | 9 +++++++ server/audit/audit_init.go | 51 +++++++++++++++++++++++++++++++++++--- server/audit/spans.go | 6 ++--- 4 files changed, 64 insertions(+), 7 deletions(-) diff --git a/.env.example b/.env.example index b3db250..5e86686 100644 --- a/.env.example +++ b/.env.example @@ -34,3 +34,8 @@ PIXIVFE_HOST='127.0.0.1' ### Development options # PIXIVFE_DEV= # PIXIVFE_RESPONSE_SAVE_LOCATION + +### Logging options +# PIXIVFE_LOG_LEVEL= +# PIXIVFE_LOG_OUTPUTS= +# PIXIVFE_LOG_FORMAT= diff --git a/config/config.go b/config/config.go index ce8664a..ec006b2 100644 --- a/config/config.go +++ b/config/config.go @@ -68,6 +68,11 @@ type ServerConfig struct { // Development options InDevelopment bool `env:"PIXIVFE_DEV"` ResponseSaveLocation string `env:"PIXIVFE_RESPONSE_SAVE_LOCATION,overwrite"` + + // Logging configuration + LogLevel string `env:"PIXIVFE_LOG_LEVEL,overwrite"` + LogOutputs []string `env:"PIXIVFE_LOG_OUTPUTS,overwrite"` + LogFormat string `env:"PIXIVFE_LOG_FORMAT,overwrite"` } // parseRevision extracts RevisionDate, RevisionHash, and IsDirty status from the Revision string @@ -144,6 +149,10 @@ func (s *ServerConfig) LoadConfig() error { s.ResponseSaveLocation = "/tmp/pixivfe/responses" + s.LogLevel = "info" + s.LogOutputs = []string{"stdout"} + s.LogFormat = "console" + // load config from from env vars if err := envconfig.Process(context.Background(), s); err != nil { return err diff --git a/server/audit/audit_init.go b/server/audit/audit_init.go index 7d9db2b..042dba5 100644 --- a/server/audit/audit_init.go +++ b/server/audit/audit_init.go @@ -17,12 +17,56 @@ var logger *zap.Logger // saveResponse is passed as a boolean from main.go. // The response save location is taken from the global configuration. func Init(saveResponse bool) error { + // Initialize the auditing parameter optionSaveResponse = saveResponse - // Initialize zap logger + // Read configuration values from GlobalConfig + savePath := config.GlobalConfig.ResponseSaveLocation + logLevel := config.GlobalConfig.LogLevel + logOutputs := config.GlobalConfig.LogOutputs + logFormat := config.GlobalConfig.LogFormat + + // Initialize zap logger with custom configuration zapConfig := zap.NewProductionConfig() + + // Adjust log encoding format based on config + switch logFormat { + case "json": + zapConfig.Encoding = "json" + case "console": + fallthrough + default: + zapConfig.Encoding = "console" + } + + // Adjust log level based on config + var atom zap.AtomicLevel + switch logLevel { + case "debug": + atom = zap.NewAtomicLevelAt(zap.DebugLevel) + case "info": + atom = zap.NewAtomicLevelAt(zap.InfoLevel) + case "warn": + atom = zap.NewAtomicLevelAt(zap.WarnLevel) + case "error": + atom = zap.NewAtomicLevelAt(zap.ErrorLevel) + default: + atom = zap.NewAtomicLevelAt(zap.InfoLevel) // Default to info level + } + zapConfig.Level = atom + + // Set custom output paths + if len(logOutputs) > 0 { + zapConfig.OutputPaths = logOutputs + } else { + // Default to standard error if logOutputs is empty + zapConfig.OutputPaths = []string{"stdout"} + } + + // Use console-friendly time encoding zapConfig.EncoderConfig.EncodeTime = zapcore.ISO8601TimeEncoder - zapConfig.OutputPaths = []string{"stderr"} + + // Build and assign the logger var err error logger, err = zapConfig.Build() if err != nil { @@ -33,9 +77,8 @@ func Init(saveResponse bool) error { return nil } + // Handle saving responses MaxRecordedCount = 128 - savePath := config.GlobalConfig.ResponseSaveLocation - if err := os.MkdirAll(savePath, 0o700); err != nil { logger.Error("Failed to create response save directory", zap.Error(err), diff --git a/server/audit/spans.go b/server/audit/spans.go index 07c9feb..b244026 100644 --- a/server/audit/spans.go +++ b/server/audit/spans.go @@ -88,9 +88,9 @@ func (span APIRequestSpan) Component() string { } func (span APIRequestSpan) Action() map[string]interface{} { return map[string]interface{}{ - "method": span.Method, - "url": span.Url, - "response_file": span.ResponseFilename, + "method": span.Method, + "url": span.Url, + "response_file": span.ResponseFilename, } } func (span APIRequestSpan) Outcome() map[string]interface{} { From 385b7de69d0e6b097811e63fd076751803f4124f Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 15:35:30 +1100 Subject: [PATCH 5/9] rm duplicate ts --- server/audit/audit_log.go | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/server/audit/audit_log.go b/server/audit/audit_log.go index a4c4d8f..27e6381 100644 --- a/server/audit/audit_log.go +++ b/server/audit/audit_log.go @@ -21,7 +21,8 @@ func LogAndRecord(span Span) { duration := float64(Duration(span)) / float64(time.Second) logger.Info("Span recorded", - zap.String("timestamp", span.GetStartTime().Format(time.RFC3339)), + // Zap already prefixes the log with a timestamp + // zap.String("timestamp", span.GetStartTime().Format(time.RFC3339)), zap.String("component", span.Component()), zap.Any("action", span.Action()), zap.Any("outcome", span.Outcome()), From 3a3f70dc12c43c3186f045f21d55de2c40e8f909 Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 15:37:48 +1100 Subject: [PATCH 6/9] rename SERVER to server --- server/audit/spans.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/server/audit/spans.go b/server/audit/spans.go index b244026..5ceb67e 100644 --- a/server/audit/spans.go +++ b/server/audit/spans.go @@ -41,7 +41,7 @@ func (span ServedRequestSpan) GetRequestId() string { return span.RequestId } func (span ServedRequestSpan) Component() string { - return "SERVER" + return "server" } func (span ServedRequestSpan) Action() map[string]interface{} { return map[string]interface{}{ From dcb1e4b34a0d344e0198679b4698f9f8fb4db3f2 Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 15:46:40 +1100 Subject: [PATCH 7/9] logging: renaming --- server/audit/audit_log.go | 34 +++++++++++++++++----------------- server/audit/spans.go | 14 +++++++------- 2 files changed, 24 insertions(+), 24 deletions(-) diff --git a/server/audit/audit_log.go b/server/audit/audit_log.go index 27e6381..4a7b46c 100644 --- a/server/audit/audit_log.go +++ b/server/audit/audit_log.go @@ -12,37 +12,37 @@ import ( "codeberg.org/vnpower/pixivfe/v2/i18n" ) -// RecordedSpans stores a slice of recorded Span objects for later analysis or debugging. -var RecordedSpans = []Span{} +// RecordedRequestSpans stores a slice of requestSpan objects. +var RecordedRequestSpans = []Span{} -// LogAndRecord logs the given span and optionally records it in the RecordedSpans slice. -// It manages the RecordedSpans slice to maintain a maximum number of recorded spans. -func LogAndRecord(span Span) { - duration := float64(Duration(span)) / float64(time.Second) +// LogAndRecord logs the given requestSpan and optionally records it in the RecordedRequestSpans slice. +// It manages the RecordedRequestSpans slice to maintain a maximum number of recorded spans. +func LogAndRecord(requestSpan Span) { + duration := float64(Duration(requestSpan)) / float64(time.Second) - logger.Info("Span recorded", + logger.Info("Request", // Zap already prefixes the log with a timestamp // zap.String("timestamp", span.GetStartTime().Format(time.RFC3339)), - zap.String("component", span.Component()), - zap.Any("action", span.Action()), - zap.Any("outcome", span.Outcome()), + zap.String("component", requestSpan.Component()), + zap.Any("action", requestSpan.Action()), + zap.Any("outcome", requestSpan.Outcome()), zap.Float64("duration", duration), ) - // If MaxRecordedCount is set, manage the RecordedSpans slice + // If MaxRecordedCount is set, manage the RecordedRequestSpans slice if MaxRecordedCount != 0 { // Remove the oldest span if we're at capacity - if len(RecordedSpans)+1 == MaxRecordedCount { - RecordedSpans = RecordedSpans[1:] + if len(RecordedRequestSpans)+1 == MaxRecordedCount { + RecordedRequestSpans = RecordedRequestSpans[1:] } // Append the new span - RecordedSpans = append(RecordedSpans, span) + RecordedRequestSpans = append(RecordedRequestSpans, requestSpan) } } -// LogServerRoundTrip logs and records a server request span. +// LogServerRoundTrip logs and records a ServerRequestSpan. // It also logs any internal server errors that occurred during the request. -func LogServerRoundTrip(requestSpan ServedRequestSpan) { +func LogServerRoundTrip(requestSpan ServerRequestSpan) { if requestSpan.Error != nil { logger.Error("Internal Server Error", zap.Error(requestSpan.Error), @@ -53,7 +53,7 @@ func LogServerRoundTrip(requestSpan ServedRequestSpan) { LogAndRecord(requestSpan) } -// LogAPIRoundTrip logs and records an API request span. +// LogAPIRoundTrip logs and records an APIRequestSpan. // It handles saving the response body to a file if enabled and logs warnings for non-2xx status codes. func LogAPIRoundTrip(requestSpan APIRequestSpan) { if requestSpan.Response != nil { diff --git a/server/audit/spans.go b/server/audit/spans.go index 5ceb67e..ba63197 100644 --- a/server/audit/spans.go +++ b/server/audit/spans.go @@ -19,7 +19,7 @@ func Duration(span Span) time.Duration { return span.GetEndTime().Sub(span.GetStartTime()) } -type ServedRequestSpan struct { +type ServerRequestSpan struct { StartTime time.Time EndTime time.Time RequestId string @@ -31,25 +31,25 @@ type ServedRequestSpan struct { Error error } -func (span ServedRequestSpan) GetStartTime() time.Time { +func (span ServerRequestSpan) GetStartTime() time.Time { return span.StartTime } -func (span ServedRequestSpan) GetEndTime() time.Time { +func (span ServerRequestSpan) GetEndTime() time.Time { return span.EndTime } -func (span ServedRequestSpan) GetRequestId() string { +func (span ServerRequestSpan) GetRequestId() string { return span.RequestId } -func (span ServedRequestSpan) Component() string { +func (span ServerRequestSpan) Component() string { return "server" } -func (span ServedRequestSpan) Action() map[string]interface{} { +func (span ServerRequestSpan) Action() map[string]interface{} { return map[string]interface{}{ "method": span.Method, "path": span.Path, } } -func (span ServedRequestSpan) Outcome() map[string]interface{} { +func (span ServerRequestSpan) Outcome() map[string]interface{} { outcome := map[string]interface{}{ "status": span.Status, "error": "", From d738741918c7f5e56bc3806a8fe9f05d149307d8 Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 16:17:17 +1100 Subject: [PATCH 8/9] update ServedRequestSpan to ServerRequestSpan --- server/middleware/logger.go | 2 +- server/routes/diagnostics.go | 4 ++-- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/server/middleware/logger.go b/server/middleware/logger.go index 5688e64..5193ac8 100644 --- a/server/middleware/logger.go +++ b/server/middleware/logger.go @@ -62,7 +62,7 @@ func LogRequest(h http.Handler) http.Handler { end_time := time.Now() // Log the request details using the audit package - audit.LogServerRoundTrip(audit.ServedRequestSpan{ + audit.LogServerRoundTrip(audit.ServerRequestSpan{ StartTime: start_time, EndTime: end_time, RequestId: request_context.Get(r).RequestId, diff --git a/server/routes/diagnostics.go b/server/routes/diagnostics.go index 2b2611a..1ab6317 100644 --- a/server/routes/diagnostics.go +++ b/server/routes/diagnostics.go @@ -17,7 +17,7 @@ func Diagnostics(w http.ResponseWriter, r *http.Request) error { } func ResetDiagnosticsData(w http.ResponseWriter, r *http.Request) { - audit.RecordedSpans = audit.RecordedSpans[:0] + audit.RecordedRequestSpans = audit.RecordedRequestSpans[:0] utils.RedirectToWhenceYouCame(w, r) } @@ -35,7 +35,7 @@ func formatSpanSummary(span audit.Span) string { func DiagnosticsData(w http.ResponseWriter, _ *http.Request) error { data := jnode.NewArrayNode() - for _, span := range audit.RecordedSpans { + for _, span := range audit.RecordedRequestSpans { bytes, err := json.Marshal(span) if err != nil { return err From 0792ad04beec16812ccc40e946912b58cb7e0451 Mon Sep 17 00:00:00 2001 From: perennial Date: Sun, 13 Oct 2024 16:23:06 +1100 Subject: [PATCH 9/9] fix diagnostic page --- server/routes/diagnostics.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/server/routes/diagnostics.go b/server/routes/diagnostics.go index 1ab6317..879ecca 100644 --- a/server/routes/diagnostics.go +++ b/server/routes/diagnostics.go @@ -44,7 +44,7 @@ func DiagnosticsData(w http.ResponseWriter, _ *http.Request) error { if err != nil { return err } - obj.Put("SpanSummary", formatSpanSummary(span)) + obj.Put("LogLine", formatSpanSummary(span)) data.Append(obj) } w.Header().Set("content-type", "application/json")