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/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/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 5b27400..042dba5 100644 --- a/server/audit/audit_init.go +++ b/server/audit/audit_init.go @@ -1,31 +1,89 @@ package audit import ( - "log" "os" "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. // The response save location is taken from the global configuration. func Init(saveResponse bool) error { + // Initialize the auditing parameter optionSaveResponse = saveResponse + // 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 + + // Build and assign the logger + var err error + logger, err = zapConfig.Build() + if err != nil { + return i18n.Errorf("failed to initialize zap logger: %w", err) + } + if !optionSaveResponse { return nil } + // Handle saving responses MaxRecordedCount = 128 - savePath := config.GlobalConfig.ResponseSaveLocation - if err := os.MkdirAll(savePath, 0o700); err != nil { - log.Printf("Error creating response save directory: %v", 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 bd99e60..4a7b46c 100644 --- a/server/audit/audit_log.go +++ b/server/audit/audit_log.go @@ -1,71 +1,83 @@ -// Package audit provides functionality for logging and recording various types of spans -// in the application, including server requests and API calls. package audit import ( - "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) +// RecordedRequestSpans stores a slice of requestSpan objects. +var RecordedRequestSpans = []Span{} -// RecordedSpans stores a slice of recorded Span objects for later analysis or debugging. -var RecordedSpans = []Span{} +// 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) -// 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()) + logger.Info("Request", + // Zap already prefixes the log with a timestamp + // zap.String("timestamp", span.GetStartTime().Format(time.RFC3339)), + 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(perf ServedRequestSpan) { - if perf.Error != nil { - log.Printf("Internal Server Error: %s", perf.Error) +func LogServerRoundTrip(requestSpan ServerRequestSpan) { + if requestSpan.Error != nil { + logger.Error("Internal Server Error", + zap.Error(requestSpan.Error), + zap.String("requestId", requestSpan.RequestId), + ) } - LogAndRecord(perf) + 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(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 { - log.Print("When saving response to file: ", err) + logger.Error("Failed to save response to file", + zap.Error(err), + zap.String("requestId", requestSpan.RequestId), + ) } } // 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:") + if !(300 > requestSpan.Response.StatusCode && requestSpan.Response.StatusCode >= 200) { + logger.Warn("Non-2xx response from pixiv", + 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. @@ -73,13 +85,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..ba63197 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,14 +10,16 @@ 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 { return span.GetEndTime().Sub(span.GetStartTime()) } -type ServedRequestSpan struct { +type ServerRequestSpan struct { StartTime time.Time EndTime time.Time RequestId string @@ -29,17 +31,34 @@ 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) LogLine() string { - return fmt.Sprintf("%v %v %v %v", span.Method, span.Path, span.Status, span.Error) +func (span ServerRequestSpan) Component() string { + return "server" +} +func (span ServerRequestSpan) Action() map[string]interface{} { + return map[string]interface{}{ + "method": span.Method, + "path": span.Path, + } +} +func (span ServerRequestSpan) 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("-> %v %v %v %v", 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/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 379dc7f..879ecca 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" @@ -15,13 +17,25 @@ 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) } +// 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 { + for _, span := range audit.RecordedRequestSpans { bytes, err := json.Marshal(span) if err != nil { return err @@ -30,7 +44,7 @@ func DiagnosticsData(w http.ResponseWriter, _ *http.Request) error { if err != nil { return err } - obj.Put("LogLine", span.LogLine()) + obj.Put("LogLine", 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)