Merge pull request 'zap-logging' (#127) from zap-logging into v2

Reviewed-on: https://codeberg.org/VnPower/PixivFE/pulls/127
This commit is contained in:
perennial
2024-10-13 05:26:20 +00:00
15 changed files with 241 additions and 77 deletions
+5
View File
@@ -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=
+9
View File
@@ -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
+13 -5
View File
@@ -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
}
+2
View File
@@ -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
)
+6
View File
@@ -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=
+1 -1
View File
@@ -23,6 +23,6 @@ func main() {
}
encoder := json.NewEncoder(os.Stdout)
encoder.SetEscapeHTML(false)
encoder.SetIndent("", " ")
encoder.SetIndent("", " ")
encoder.Encode(translation_map)
}
+7 -7
View File
@@ -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,
}
+1
View File
@@ -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",
+62 -4
View File
@@ -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)
}
+45 -31
View File
@@ -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
}
+51 -10
View File
@@ -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": "<none>",
"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": "<none>",
"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
}
+1 -1
View File
@@ -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,
+17 -3
View File
@@ -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")
+13 -13
View File
@@ -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 {
+8 -2
View File
@@ -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)