feature/access logs

.github/workflows/alice-builder.yml

@@ -50,6 +50,11 @@ jobs:
     steps:
       - uses: actions/checkout@v4
       - uses: depot/setup-action@v1
+      - uses: docker/login-action@v3
+        with:
+          registry: ghcr.io
+          username: ${{ github.actor }}
+          password: ${{ secrets.GITHUB_TOKEN }}
       # https://git.luolix.topmunity/t/additional-function-s-lowercase-uppercase/140632
       - name: lowercase repository name
         run: |

cmd/main.go

@@ -42,18 +42,21 @@ func main() {
 
 	// application
 	app := cli.NewApp()
-	cli.VersionFlag = &cli.BoolFlag{Name: "version", Aliases: []string{"V"}}
+	cli.VersionFlag = &cli.BoolFlag{
+		Name:               "version",
+		Usage:              "show version",
+		Aliases:            []string{"V"},
+		DisableDefaultText: true,
+	}
 
 	app.Name = "alice"
 	app.Version = fmt.Sprintf("%s\t%s", version, buildtime)
-	app.Authors = []*cli.Author{
-		&cli.Author{
-			Name:  "MindHunter86",
-			Email: "mindhunter86@vkom.cc",
-		},
-	}
 	app.Copyright = "(c) 2024 mindhunter86\nwith love for AniLibria project"
 	app.Usage = "AniLibria legacy api cache service"
+	app.Authors = append(app.Authors, &cli.Author{
+		Name:  "MindHunter86",
+		Email: "mindhunter86@vkom.cc",
+	})
 
 	app.Flags = []cli.Flag{
 		// common settings
@@ -65,59 +68,78 @@ func main() {
 			EnvVars: []string{"LOG_LEVEL"},
 		},
 		&cli.BoolFlag{
-			Name:    "quite",
-			Aliases: []string{"q"},
-			Usage:   "Flag is equivalent to --log-level=quite",
+			Name:               "quite",
+			Aliases:            []string{"q"},
+			Usage:              "equivalent to --log-level=quite",
+			DisableDefaultText: true,
 		},
 
 		// common settings : syslog
 		&cli.StringFlag{
 			Name:    "syslog-server",
+			Usage:   "syslog server (optional); syslog sender is not used if value is empty",
 			Value:   "",
 			EnvVars: []string{"SYSLOG_ADDRESS"},
 		},
 		&cli.StringFlag{
 			Name:  "syslog-proto",
+			Usage: "syslog protocol (optional); tcp or udp is possible",
 			Value: "tcp",
 		},
 		&cli.StringFlag{
 			Name:  "syslog-tag",
+			Usage: "optional setting; more information in syslog RFC",
 			Value: "",
 		},
 
 		// fiber-server settings
 		&cli.StringFlag{
 			Name:  "http-listen-addr",
-			Usage: "Ex: 127.0.0.1:8080, :8080",
+			Usage: "format - 127.0.0.1:8080, :8080",
 			Value: "127.0.0.1:8080",
 		},
 		&cli.StringFlag{
 			Name:  "http-trusted-proxies",
-			Usage: "Ex: 10.0.0.0/8; Separated by comma",
+			Usage: "format - 192.168.0.0/16; can be separated by comma",
 		},
 		&cli.BoolFlag{
 			Name: "http-prefork",
-			Usage: `Enables use of the SO_REUSEPORT socket option;
+			Usage: `enables use of the SO_REUSEPORT socket option;
 			if enabled, the application will need to be ran
-			through a shell because prefork mode sets environment variables`,
+			through a shell because prefork mode sets environment variables;
+			EXPERIMENTAL! USE CAREFULLY!`,
+			DisableDefaultText: true,
 		},
 		&cli.BoolFlag{
-			Name:  "http-pprof-enable",
-			Usage: "enable golang http-pprof methods",
+			Name:               "http-pprof-enable",
+			Usage:              "enable golang http-pprof methods",
+			DisableDefaultText: true,
+		},
+		&cli.StringFlag{
+			Name:  "http-access-logs-level",
+			Usage: "set logger level for access-log logs",
+			Value: zerolog.LevelDebugValue,
 		},
 
 		// limiter settings
-		&cli.BoolFlag{
-			Name:  "limiter-use-bbolt",
-			Usage: "use bbolt key\value file database instead of memory database",
-		},
-		&cli.IntFlag{
-			Name:  "limiter-max-req",
-			Value: 200,
-		},
-		&cli.DurationFlag{
-			Name:  "limiter-records-duration",
-			Value: 5 * time.Minute,
+		// &cli.BoolFlag{
+		// 	Name:  "limiter-use-bbolt",
+		// 	Usage: "use bbolt key\value file database instead of memory database",
+		// },
+		// &cli.IntFlag{
+		// 	Name:  "limiter-max-req",
+		// 	Value: 200,
+		// },
+		// &cli.DurationFlag{
+		// 	Name:  "limiter-records-duration",
+		// 	Value: 5 * time.Minute,
+		// },
+
+		// rewriter settings
+		&cli.StringFlag{
+			Name:  "rewriter-response-header",
+			Usage: "header for parsed payload",
+			Value: "X-Parsed-Form",
 		},
 	}
 

go.mod

@@ -4,7 +4,6 @@ go 1.19
 
 require (
 	github.com/gofiber/fiber/v2 v2.52.4
-	github.com/gofiber/storage/bbolt v1.3.5
 	github.com/rs/zerolog v1.33.0
 	github.com/urfave/cli/v2 v2.27.2
 	github.com/valyala/fasthttp v1.55.0
@@ -13,7 +12,6 @@ require (
 require (
 	github.com/andybalholm/brotli v1.1.0 // indirect
 	github.com/cpuguy83/go-md2man/v2 v2.0.4 // indirect
-	github.com/gofiber/utils v1.0.1 // indirect
 	github.com/google/uuid v1.5.0 // indirect
 	github.com/klauspost/compress v1.17.9 // indirect
 	github.com/mattn/go-colorable v0.1.13 // indirect
@@ -24,6 +22,5 @@ require (
 	github.com/valyala/bytebufferpool v1.0.0 // indirect
 	github.com/valyala/tcplisten v1.0.0 // indirect
 	github.com/xrash/smetrics v0.0.0-20240312152122-5f08fbb34913 // indirect
-	go.etcd.io/bbolt v1.3.7 // indirect
 	golang.org/x/sys v0.21.0 // indirect
 )

go.sum

@@ -3,14 +3,9 @@ github.com/andybalholm/brotli v1.1.0/go.mod h1:sms7XGricyQI9K10gOSf56VKKWS4oLer5
 github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc=
 github.com/cpuguy83/go-md2man/v2 v2.0.4 h1:wfIWP927BUkWJb2NmU/kNDYIBTh/ziUX91+lVfRxZq4=
 github.com/cpuguy83/go-md2man/v2 v2.0.4/go.mod h1:tgQtvFlXSQOSOSIRvRPT7W67SCa46tRHOmNcaadrF8o=
-github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c=
 github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA=
 github.com/gofiber/fiber/v2 v2.52.4 h1:P+T+4iK7VaqUsq2PALYEfBBo6bJZ4q3FP8cZ84EggTM=
 github.com/gofiber/fiber/v2 v2.52.4/go.mod h1:KEOE+cXMhXG0zHc9d8+E38hoX+ZN7bhOtgeF2oT6jrQ=
-github.com/gofiber/storage/bbolt v1.3.5 h1:9ZDMTbeah5tfj3eX+hFu3F1AHiBO117ce3Gel7tkxlk=
-github.com/gofiber/storage/bbolt v1.3.5/go.mod h1:GibrOAQTFOzzzWWVCgq+V+gS8dUbaPeAMGI4FNZ32sI=
-github.com/gofiber/utils v1.0.1 h1:knct4cXwBipWQqFrOy1Pv6UcgPM+EXo9jDgc66V1Qio=
-github.com/gofiber/utils v1.0.1/go.mod h1:pacRFtghAE3UoknMOUiXh2Io/nLWSUHtQCi/3QASsOc=
 github.com/google/uuid v1.5.0 h1:1p67kYwdtXjb0gL0BPiP1Av9wiZPo5A8z2cWkTZ+eyU=
 github.com/google/uuid v1.5.0/go.mod h1:TIyPZe4MgqvfeYDBFedMoGGpEw/LqOeaOT+nhxU+yHo=
 github.com/klauspost/compress v1.17.9 h1:6KIumPrER1LHsvBVuDa0r5xaG0Es51mhhB9BQB2qeMA=
@@ -24,15 +19,13 @@ github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D
 github.com/mattn/go-runewidth v0.0.15 h1:UNAjwbU9l54TA3KzvqLGxwWjHmMgBUVhBiTjelZgg3U=
 github.com/mattn/go-runewidth v0.0.15/go.mod h1:Jdepj2loyihRzMpdS35Xk/zdY8IAYHsh153qUoGf23w=
 github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0=
-github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM=
 github.com/rivo/uniseg v0.2.0 h1:S1pD9weZBuJdFmowNwbpi7BJ8TNftyUImj/0WQi72jY=
 github.com/rivo/uniseg v0.2.0/go.mod h1:J6wj4VEh+S6ZtnVlnTBMWIodfgj8LQOQFoIToxlJtxc=
 github.com/rs/xid v1.5.0/go.mod h1:trrq9SKmegXys3aeAKXMUTdJsYXVwGY3RLcfgqegfbg=
 github.com/rs/zerolog v1.33.0 h1:1cU2KZkvPxNyfgEmhHAz/1A9Bz+llsdYzklWFzgp0r8=
 github.com/rs/zerolog v1.33.0/go.mod h1:/7mN4D5sKwJLZQ2b/znpjC3/GQWY/xaDXUM0kKWRHss=
 github.com/russross/blackfriday/v2 v2.1.0 h1:JIOH55/0cWyOuilr9/qlrm0BSXldqnqwMsf35Ld67mk=
 github.com/russross/blackfriday/v2 v2.1.0/go.mod h1:+Rmxgy9KzJVeS9/2gXHxylqXiyQDYRxCVz55jmeOWTM=
-github.com/stretchr/testify v1.8.1 h1:w7B6lhMri9wdJUVmEZPGGhZzrYTPvgJArz7wNPgYKsk=
 github.com/urfave/cli/v2 v2.27.2 h1:6e0H+AkS+zDckwPCUrZkKX38mRaau4nL2uipkJpbkcI=
 github.com/urfave/cli/v2 v2.27.2/go.mod h1:g0+79LmHHATl7DAcHO99smiR/T7uGLw84w8Y42x+4eM=
 github.com/valyala/bytebufferpool v1.0.0 h1:GqA5TC/0021Y/b9FG4Oi9Mr3q7XYx6KllzawFIhcdPw=
@@ -43,11 +36,8 @@ github.com/valyala/tcplisten v1.0.0 h1:rBHj/Xf+E1tRGZyWIWwJDiRY0zc1Js+CV5DqwacVS
 github.com/valyala/tcplisten v1.0.0/go.mod h1:T0xQ8SeCZGxckz9qRXTfG43PvQ/mcWh7FwZEA7Ioqkc=
 github.com/xrash/smetrics v0.0.0-20240312152122-5f08fbb34913 h1:+qGGcbkzsfDQNPPe9UDgpxAWQrhbbBXOYJFQDq/dtJw=
 github.com/xrash/smetrics v0.0.0-20240312152122-5f08fbb34913/go.mod h1:4aEEwZQutDLsQv2Deui4iYQ6DWTxR14g6m8Wv88+Xqk=
-go.etcd.io/bbolt v1.3.7 h1:j+zJOnnEjF/kyHlDDgGnVL/AIqIJPq8UoB2GSNfkUfQ=
-go.etcd.io/bbolt v1.3.7/go.mod h1:N9Mkw9X8x5fupy0IKsmuqVtoGDyxsaDlbk4Rd05IAQw=
 golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg=
 golang.org/x/sys v0.21.0 h1:rF+pYz3DAGSQAxAu1CbC7catZg4ebC4UIeIhKxBZvws=
 golang.org/x/sys v0.21.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA=
-gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=

internal/rewriter/rewriter.go

@@ -8,6 +8,7 @@ import (
 	"sort"
 	"sync"
 
+	"github.com/anilibria/alice/utils"
 	"github.com/gofiber/fiber/v2"
 	"github.com/valyala/fasthttp"
 )
@@ -73,6 +74,6 @@ func (*Rewriter) rewrite(c *fiber.Ctx) (e error) {
 		buf.WriteString(fmt.Sprintf("%s=%s&", v, c.FormValue(v)))
 	}
 
-	c.Set("X-Parsed-Form", string(buf.Bytes()[0:buf.Len()-1]))
+	c.Set(c.Locals(utils.FLKRewriterHeader).(string), string(buf.Bytes()[0:buf.Len()-1]))
 	return
 }

internal/service/router.go

@@ -1,18 +1,23 @@
 package service
 
 import (
+	"errors"
 	"fmt"
+	"io"
 	"os"
 	"runtime/debug"
+	"time"
 
 	"github.com/anilibria/alice/internal/rewriter"
+	"github.com/anilibria/alice/utils"
 	"github.com/gofiber/fiber/v2"
 	"github.com/gofiber/fiber/v2/middleware/compress"
 	"github.com/gofiber/fiber/v2/middleware/favicon"
 	"github.com/gofiber/fiber/v2/middleware/pprof"
 	"github.com/gofiber/fiber/v2/middleware/recover"
 	"github.com/gofiber/fiber/v2/middleware/requestid"
 	"github.com/gofiber/fiber/v2/middleware/skip"
+	"github.com/rs/zerolog"
 )
 
 func (m *Service) fiberMiddlewareInitialization() {
@@ -32,25 +37,62 @@ func (m *Service) fiberMiddlewareInitialization() {
 	// request id
 	m.fb.Use(requestid.New())
 
+	// insert payload for futher processing
+	m.fb.Use(func(c *fiber.Ctx) error {
+		c.Locals(utils.FLKRewriterHeader, gCli.String("rewriter-response-header"))
+		return c.Next()
+	})
+
 	// prefixed logger initialization
 	// - we send logs in syslog and stdout by default,
 	// - but if access-log-stdout is 0 we use syslog output only
-	// !!!
-	// !!!
-	// !!!
-	// m.fb.Use(func(c *fiber.Ctx) error {
-	// 	logger := gLog.With().Str("id", c.Locals("requestid").(string)).Logger().
-	// 		Level(m.runtime.Config.Get(runtime.ParamAccessLevel).(zerolog.Level))
-	// 	syslogger := logger.Output(m.syslogWriter)
-
-	// 	if m.runtime.Config.Get(runtime.ParamAccessStdout).(int) == 0 {
-	// 		logger = logger.Output(io.Discard)
-	// 	}
-
-	// 	c.Locals("logger", &logger)
-	// 	c.Locals("syslogger", &syslogger)
-	// 	return c.Next()
-	// })
+	m.fb.Use(func(c *fiber.Ctx) error {
+		logger := gLog.With().Str("id", c.Locals("requestid").(string)).Logger().
+			Level(m.accesslogLevel)
+		syslogger := logger.Output(m.syslogWriter)
+
+		if zerolog.GlobalLevel() > zerolog.DebugLevel {
+			logger = logger.Output(io.Discard)
+		}
+
+		c.Locals("logger", &logger)
+		c.Locals("syslogger", &syslogger)
+		return c.Next()
+	})
+
+	// time collector + logger
+	m.fb.Use(func(c *fiber.Ctx) (e error) {
+		started, e := time.Now(), c.Next()
+		stopped := time.Now()
+		elapsed := stopped.Sub(started).Round(time.Microsecond)
+
+		status, lvl, err := c.Response().StatusCode(), m.accesslogLevel, new(fiber.Error)
+		if errors.As(e, &err) || status >= fiber.StatusInternalServerError {
+			status, lvl = err.Code, zerolog.WarnLevel
+		}
+
+		// get rewriter payload
+		rpayload := c.Response().Header.Peek(c.Locals(utils.FLKRewriterHeader).(string))
+
+		rlog(c).WithLevel(lvl).
+			Int("status", status).
+			Str("method", c.Method()).
+			Str("path", c.Path()).
+			Str("ip", c.IP()).
+			Dur("latency", elapsed).
+			Str("payload", string(rpayload)).
+			Str("user-agent", c.Get(fiber.HeaderUserAgent)).Msg("")
+		rsyslog(c).WithLevel(lvl).
+			Int("status", status).
+			Str("method", c.Method()).
+			Str("path", c.Path()).
+			Str("ip", c.IP()).
+			Dur("latency", elapsed).
+			Str("payload", string(rpayload)).
+			Str("user-agent", c.Get(fiber.HeaderUserAgent)).Msg("")
+
+		return
+	})
 
 	// ! LIMITER
 	// media.Use(limiter.New(limiter.Config{