requests-log db

scnserver/README.md

@@ -3,7 +3,10 @@
   TODO
 ========
 
--------------------------------------------------------------------------------------------------------------------------------
+
+#### BEFORE RELEASE
+
+- tests (!)
 
  - migration script for existing data
 
@@ -11,21 +14,14 @@
 
  - route to re-check all pro-token (for me)
 
- - tests (!)
-
  - deploy
 
  - diff my currently used scnsend script vs the one in the docs here
 
- - Pagination for ListChannels / ListSubscriptions / ListClients / ListChannelSubscriptions / ListUserSubscriptions
-
- - cannot open sqlite in dbbrowsr (cannot parse schema?)
- -> https://github.com/sqlitebrowser/sqlitebrowser/issues/292 -> https://github.com/sqlitebrowser/sqlitebrowser/issues/29266
-
 - (?) use str-ids (also prevents wrong-joins) -> see psycho
   -> how does it work with existing data? (do i care, there are only 2 active users... (are there?))
 
- - error logging as goroutine, get sall errors via channel,
+ - error logging as goroutine, gets all errors via channel,
    (channel buffered - nonblocking send, second channel that gets a message when sender failed )
    (then all errors end up in _second_ sqlite table)
    due to message channel etc everything is non blocking and cant fail in main
@@ -40,11 +36,11 @@
    (or add another /kuma endpoint)
    -> https://webhook.site/
 
--------------------------------------------------------------------------------------------------------------------------------
+#### PERSONAL
 
  - in my script: use `srvname` for sendername
 
--------------------------------------------------------------------------------------------------------------------------------
+#### UNSURE
 
  - (?) default-priority for channels
 
@@ -56,3 +52,10 @@
 
  - (?) desktop client for notifications
 
+#### LATER
+
+- Pagination for ListChannels / ListSubscriptions / ListClients / ListChannelSubscriptions / ListUserSubscriptions
+
+- cannot open sqlite in dbbrowsr (cannot parse schema?)
+  -> https://github.com/sqlitebrowser/sqlitebrowser/issues/292 -> https://github.com/sqlitebrowser/sqlitebrowser/issues/29266
+

scnserver/api/ginresp/resp.go

@@ -4,6 +4,7 @@ import (
 	scn "blackforestbytes.com/simplecloudnotifier"
 	"blackforestbytes.com/simplecloudnotifier/api/apierr"
 	"blackforestbytes.com/simplecloudnotifier/api/apihighlight"
+	"encoding/json"
 	"fmt"
 	"github.com/gin-gonic/gin"
 	"github.com/rs/zerolog/log"
@@ -14,6 +15,9 @@ import (
 
 type HTTPResponse interface {
 	Write(g *gin.Context)
+	Statuscode() int
+	BodyString() *string
+	ContentType() string
 }
 
 type jsonHTTPResponse struct {
@@ -25,6 +29,22 @@ func (j jsonHTTPResponse) Write(g *gin.Context) {
 	g.JSON(j.statusCode, j.data)
 }
 
+func (j jsonHTTPResponse) Statuscode() int {
+	return j.statusCode
+}
+
+func (j jsonHTTPResponse) BodyString() *string {
+	v, err := json.Marshal(j.data)
+	if err != nil {
+		return nil
+	}
+	return langext.Ptr(string(v))
+}
+
+func (j jsonHTTPResponse) ContentType() string {
+	return "application/json"
+}
+
 type emptyHTTPResponse struct {
 	statusCode int
 }
@@ -33,6 +53,18 @@ func (j emptyHTTPResponse) Write(g *gin.Context) {
 	g.Status(j.statusCode)
 }
 
+func (j emptyHTTPResponse) Statuscode() int {
+	return j.statusCode
+}
+
+func (j emptyHTTPResponse) BodyString() *string {
+	return nil
+}
+
+func (j emptyHTTPResponse) ContentType() string {
+	return ""
+}
+
 type textHTTPResponse struct {
 	statusCode int
 	data       string
@@ -42,6 +74,18 @@ func (j textHTTPResponse) Write(g *gin.Context) {
 	g.String(j.statusCode, "%s", j.data)
 }
 
+func (j textHTTPResponse) Statuscode() int {
+	return j.statusCode
+}
+
+func (j textHTTPResponse) BodyString() *string {
+	return langext.Ptr(j.data)
+}
+
+func (j textHTTPResponse) ContentType() string {
+	return "text/plain"
+}
+
 type dataHTTPResponse struct {
 	statusCode  int
 	data        []byte
@@ -52,6 +96,18 @@ func (j dataHTTPResponse) Write(g *gin.Context) {
 	g.Data(j.statusCode, j.contentType, j.data)
 }
 
+func (j dataHTTPResponse) Statuscode() int {
+	return j.statusCode
+}
+
+func (j dataHTTPResponse) BodyString() *string {
+	return langext.Ptr(string(j.data))
+}
+
+func (j dataHTTPResponse) ContentType() string {
+	return j.contentType
+}
+
 type errorHTTPResponse struct {
 	statusCode int
 	data       any
@@ -62,6 +118,22 @@ func (j errorHTTPResponse) Write(g *gin.Context) {
 	g.JSON(j.statusCode, j.data)
 }
 
+func (j errorHTTPResponse) Statuscode() int {
+	return j.statusCode
+}
+
+func (j errorHTTPResponse) BodyString() *string {
+	v, err := json.Marshal(j.data)
+	if err != nil {
+		return nil
+	}
+	return langext.Ptr(string(v))
+}
+
+func (j errorHTTPResponse) ContentType() string {
+	return "application/json"
+}
+
 func Status(sc int) HTTPResponse {
 	return &emptyHTTPResponse{statusCode: sc}
 }

scnserver/api/ginresp/wrapper.go

@@ -3,18 +3,24 @@ package ginresp
 import (
 	scn "blackforestbytes.com/simplecloudnotifier"
 	"blackforestbytes.com/simplecloudnotifier/api/apierr"
+	"blackforestbytes.com/simplecloudnotifier/models"
 	"errors"
 	"fmt"
 	"github.com/gin-gonic/gin"
 	"github.com/mattn/go-sqlite3"
 	"github.com/rs/zerolog/log"
 	"gogs.mikescher.com/BlackForestBytes/goext/dataext"
+	"gogs.mikescher.com/BlackForestBytes/goext/langext"
 	"time"
 )
 
 type WHandlerFunc func(*gin.Context) HTTPResponse
 
-func Wrap(fn WHandlerFunc) gin.HandlerFunc {
+type RequestLogAcceptor interface {
+	InsertRequestLog(data models.RequestLog)
+}
+
+func Wrap(rlacc RequestLogAcceptor, fn WHandlerFunc) gin.HandlerFunc {
 
 	maxRetry := scn.Conf.RequestMaxRetry
 	retrySleep := scn.Conf.RequestRetrySleep
@@ -27,6 +33,8 @@ func Wrap(fn WHandlerFunc) gin.HandlerFunc {
 			g.Request.Body = dataext.NewBufferedReadCloser(g.Request.Body)
 		}
 
+		t0 := time.Now()
+
 		for ctr := 1; ; ctr++ {
 
 			wrap, panicObj := callPanicSafe(fn, g)
@@ -36,6 +44,9 @@ func Wrap(fn WHandlerFunc) gin.HandlerFunc {
 			}
 
 			if g.Writer.Written() {
+				if scn.Conf.ReqLogEnabled {
+					rlacc.InsertRequestLog(createRequestLog(g, t0, ctr, nil, langext.Ptr("Writing in WrapperFunc is not supported")))
+				}
 				panic("Writing in WrapperFunc is not supported")
 			}
 
@@ -52,6 +63,9 @@ func Wrap(fn WHandlerFunc) gin.HandlerFunc {
 			}
 
 			if reqctx.Err() == nil {
+				if scn.Conf.ReqLogEnabled {
+					rlacc.InsertRequestLog(createRequestLog(g, t0, ctr, wrap, nil))
+				}
 				wrap.Write(g)
 			}
 
@@ -62,6 +76,62 @@ func Wrap(fn WHandlerFunc) gin.HandlerFunc {
 
 }
 
+func createRequestLog(g *gin.Context, t0 time.Time, ctr int, resp HTTPResponse, panicstr *string) models.RequestLog {
+
+	t1 := time.Now()
+
+	ua := g.Request.UserAgent()
+	auth := g.Request.Header.Get("Authorization")
+	ct := g.Request.Header.Get("Content-Type")
+
+	var reqbody []byte = nil
+	if g.Request.Body != nil {
+		brcbody, err := g.Request.Body.(dataext.BufferedReadCloser).BufferedAll()
+		if err == nil {
+			reqbody = brcbody
+		}
+	}
+	var strreqbody *string = nil
+	if len(reqbody) < scn.Conf.ReqLogMaxBodySize {
+		strreqbody = langext.Ptr(string(reqbody))
+	}
+
+	var respbody *string = nil
+
+	var strrespbody *string = nil
+	if resp != nil {
+		respbody = resp.BodyString()
+		if respbody != nil && len(*respbody) < scn.Conf.ReqLogMaxBodySize {
+			strrespbody = respbody
+		}
+	}
+
+	permObj, hasPerm := g.Get("perm")
+
+	return models.RequestLog{
+		Method:              g.Request.Method,
+		URI:                 g.Request.URL.String(),
+		UserAgent:           langext.Conditional(ua == "", nil, &ua),
+		Authentication:      langext.Conditional(auth == "", nil, &auth),
+		RequestBody:         strreqbody,
+		RequestBodySize:     int64(len(reqbody)),
+		RequestContentType:  ct,
+		RemoteIP:            g.RemoteIP(),
+		UserID:              langext.ConditionalFn10(hasPerm, func() *models.UserID { return permObj.(models.PermissionSet).UserID }, nil),
+		Permissions:         langext.ConditionalFn10(hasPerm, func() *string { return langext.Ptr(string(permObj.(models.PermissionSet).KeyType)) }, nil),
+		ResponseStatuscode:  langext.ConditionalFn10(resp != nil, func() *int64 { return langext.Ptr(int64(resp.Statuscode())) }, nil),
+		ResponseBodySize:    langext.ConditionalFn10(strrespbody != nil, func() *int64 { return langext.Ptr(int64(len(*respbody))) }, nil),
+		ResponseBody:        strrespbody,
+		ResponseContentType: langext.ConditionalFn10(resp != nil, func() string { return resp.ContentType() }, ""),
+		RetryCount:          int64(ctr),
+		Panicked:            panicstr != nil,
+		PanicStr:            panicstr,
+		ProcessingTime:      t1.Sub(t0),
+		TimestampStart:      t0,
+		TimestampFinish:     t1,
+	}
+}
+
 func callPanicSafe(fn WHandlerFunc, g *gin.Context) (res HTTPResponse, panicObj any) {
 	defer func() {
 		if rec := recover(); rec != nil {

scnserver/api/router.go

@@ -50,10 +50,10 @@ func (r *Router) Init(e *gin.Engine) {
 
 	commonAPI := e.Group("/api")
 	{
-		commonAPI.Any("/ping", ginresp.Wrap(r.commonHandler.Ping))
+		commonAPI.Any("/ping", r.Wrap(r.commonHandler.Ping))
-		commonAPI.POST("/db-test", ginresp.Wrap(r.commonHandler.DatabaseTest))
+		commonAPI.POST("/db-test", r.Wrap(r.commonHandler.DatabaseTest))
-		commonAPI.GET("/health", ginresp.Wrap(r.commonHandler.Health))
+		commonAPI.GET("/health", r.Wrap(r.commonHandler.Health))
-		commonAPI.POST("/sleep/:secs", ginresp.Wrap(r.commonHandler.Sleep))
+		commonAPI.POST("/sleep/:secs", r.Wrap(r.commonHandler.Sleep))
 	}
 
 	// ================ Swagger ================
@@ -61,48 +61,48 @@ func (r *Router) Init(e *gin.Engine) {
 	docs := e.Group("/documentation")
 	{
 		docs.GET("/swagger", ginext.RedirectTemporary("/documentation/swagger/"))
-		docs.GET("/swagger/*sub", ginresp.Wrap(swagger.Handle))
+		docs.GET("/swagger/*sub", r.Wrap(swagger.Handle))
 	}
 
 	// ================ Website ================
 
 	frontend := e.Group("")
 	{
-		frontend.GET("/", ginresp.Wrap(r.websiteHandler.Index))
+		frontend.GET("/", r.Wrap(r.websiteHandler.Index))
-		frontend.GET("/index.php", ginresp.Wrap(r.websiteHandler.Index))
+		frontend.GET("/index.php", r.Wrap(r.websiteHandler.Index))
-		frontend.GET("/index.html", ginresp.Wrap(r.websiteHandler.Index))
+		frontend.GET("/index.html", r.Wrap(r.websiteHandler.Index))
-		frontend.GET("/index", ginresp.Wrap(r.websiteHandler.Index))
+		frontend.GET("/index", r.Wrap(r.websiteHandler.Index))
 
-		frontend.GET("/api", ginresp.Wrap(r.websiteHandler.APIDocs))
+		frontend.GET("/api", r.Wrap(r.websiteHandler.APIDocs))
-		frontend.GET("/api.php", ginresp.Wrap(r.websiteHandler.APIDocs))
+		frontend.GET("/api.php", r.Wrap(r.websiteHandler.APIDocs))
-		frontend.GET("/api.html", ginresp.Wrap(r.websiteHandler.APIDocs))
+		frontend.GET("/api.html", r.Wrap(r.websiteHandler.APIDocs))
 
-		frontend.GET("/api_more", ginresp.Wrap(r.websiteHandler.APIDocsMore))
+		frontend.GET("/api_more", r.Wrap(r.websiteHandler.APIDocsMore))
-		frontend.GET("/api_more.php", ginresp.Wrap(r.websiteHandler.APIDocsMore))
+		frontend.GET("/api_more.php", r.Wrap(r.websiteHandler.APIDocsMore))
-		frontend.GET("/api_more.html", ginresp.Wrap(r.websiteHandler.APIDocsMore))
+		frontend.GET("/api_more.html", r.Wrap(r.websiteHandler.APIDocsMore))
 
-		frontend.GET("/message_sent", ginresp.Wrap(r.websiteHandler.MessageSent))
+		frontend.GET("/message_sent", r.Wrap(r.websiteHandler.MessageSent))
-		frontend.GET("/message_sent.php", ginresp.Wrap(r.websiteHandler.MessageSent))
+		frontend.GET("/message_sent.php", r.Wrap(r.websiteHandler.MessageSent))
-		frontend.GET("/message_sent.html", ginresp.Wrap(r.websiteHandler.MessageSent))
+		frontend.GET("/message_sent.html", r.Wrap(r.websiteHandler.MessageSent))
 
-		frontend.GET("/favicon.ico", ginresp.Wrap(r.websiteHandler.FaviconIco))
+		frontend.GET("/favicon.ico", r.Wrap(r.websiteHandler.FaviconIco))
-		frontend.GET("/favicon.png", ginresp.Wrap(r.websiteHandler.FaviconPNG))
+		frontend.GET("/favicon.png", r.Wrap(r.websiteHandler.FaviconPNG))
 
-		frontend.GET("/js/:fn", ginresp.Wrap(r.websiteHandler.Javascript))
+		frontend.GET("/js/:fn", r.Wrap(r.websiteHandler.Javascript))
-		frontend.GET("/css/:fn", ginresp.Wrap(r.websiteHandler.CSS))
+		frontend.GET("/css/:fn", r.Wrap(r.websiteHandler.CSS))
 	}
 
 	// ================ Compat (v1) ================
 
 	compat := e.Group("/api/")
 	{
-		compat.GET("/register.php", ginresp.Wrap(r.compatHandler.Register))
+		compat.GET("/register.php", r.Wrap(r.compatHandler.Register))
-		compat.GET("/info.php", ginresp.Wrap(r.compatHandler.Info))
+		compat.GET("/info.php", r.Wrap(r.compatHandler.Info))
-		compat.GET("/ack.php", ginresp.Wrap(r.compatHandler.Ack))
+		compat.GET("/ack.php", r.Wrap(r.compatHandler.Ack))
-		compat.GET("/requery.php", ginresp.Wrap(r.compatHandler.Requery))
+		compat.GET("/requery.php", r.Wrap(r.compatHandler.Requery))
-		compat.GET("/update.php", ginresp.Wrap(r.compatHandler.Update))
+		compat.GET("/update.php", r.Wrap(r.compatHandler.Update))
-		compat.GET("/expand.php", ginresp.Wrap(r.compatHandler.Expand))
+		compat.GET("/expand.php", r.Wrap(r.compatHandler.Expand))
-		compat.GET("/upgrade.php", ginresp.Wrap(r.compatHandler.Upgrade))
+		compat.GET("/upgrade.php", r.Wrap(r.compatHandler.Upgrade))
 	}
 
 	// ================ Manage API ================
@@ -110,44 +110,48 @@ func (r *Router) Init(e *gin.Engine) {
 	apiv2 := e.Group("/api/")
 	{
 
-		apiv2.POST("/users", ginresp.Wrap(r.apiHandler.CreateUser))
+		apiv2.POST("/users", r.Wrap(r.apiHandler.CreateUser))
-		apiv2.GET("/users/:uid", ginresp.Wrap(r.apiHandler.GetUser))
+		apiv2.GET("/users/:uid", r.Wrap(r.apiHandler.GetUser))
-		apiv2.PATCH("/users/:uid", ginresp.Wrap(r.apiHandler.UpdateUser))
+		apiv2.PATCH("/users/:uid", r.Wrap(r.apiHandler.UpdateUser))
 
-		apiv2.GET("/users/:uid/clients", ginresp.Wrap(r.apiHandler.ListClients))
+		apiv2.GET("/users/:uid/clients", r.Wrap(r.apiHandler.ListClients))
-		apiv2.GET("/users/:uid/clients/:cid", ginresp.Wrap(r.apiHandler.GetClient))
+		apiv2.GET("/users/:uid/clients/:cid", r.Wrap(r.apiHandler.GetClient))
-		apiv2.POST("/users/:uid/clients", ginresp.Wrap(r.apiHandler.AddClient))
+		apiv2.POST("/users/:uid/clients", r.Wrap(r.apiHandler.AddClient))
-		apiv2.DELETE("/users/:uid/clients/:cid", ginresp.Wrap(r.apiHandler.DeleteClient))
+		apiv2.DELETE("/users/:uid/clients/:cid", r.Wrap(r.apiHandler.DeleteClient))
 
-		apiv2.GET("/users/:uid/channels", ginresp.Wrap(r.apiHandler.ListChannels))
+		apiv2.GET("/users/:uid/channels", r.Wrap(r.apiHandler.ListChannels))
-		apiv2.POST("/users/:uid/channels", ginresp.Wrap(r.apiHandler.CreateChannel))
+		apiv2.POST("/users/:uid/channels", r.Wrap(r.apiHandler.CreateChannel))
-		apiv2.GET("/users/:uid/channels/:cid", ginresp.Wrap(r.apiHandler.GetChannel))
+		apiv2.GET("/users/:uid/channels/:cid", r.Wrap(r.apiHandler.GetChannel))
-		apiv2.PATCH("/users/:uid/channels/:cid", ginresp.Wrap(r.apiHandler.UpdateChannel))
+		apiv2.PATCH("/users/:uid/channels/:cid", r.Wrap(r.apiHandler.UpdateChannel))
-		apiv2.GET("/users/:uid/channels/:cid/messages", ginresp.Wrap(r.apiHandler.ListChannelMessages))
+		apiv2.GET("/users/:uid/channels/:cid/messages", r.Wrap(r.apiHandler.ListChannelMessages))
-		apiv2.GET("/users/:uid/channels/:cid/subscriptions", ginresp.Wrap(r.apiHandler.ListChannelSubscriptions))
+		apiv2.GET("/users/:uid/channels/:cid/subscriptions", r.Wrap(r.apiHandler.ListChannelSubscriptions))
 
-		apiv2.GET("/users/:uid/subscriptions", ginresp.Wrap(r.apiHandler.ListUserSubscriptions))
+		apiv2.GET("/users/:uid/subscriptions", r.Wrap(r.apiHandler.ListUserSubscriptions))
-		apiv2.POST("/users/:uid/subscriptions", ginresp.Wrap(r.apiHandler.CreateSubscription))
+		apiv2.POST("/users/:uid/subscriptions", r.Wrap(r.apiHandler.CreateSubscription))
-		apiv2.GET("/users/:uid/subscriptions/:sid", ginresp.Wrap(r.apiHandler.GetSubscription))
+		apiv2.GET("/users/:uid/subscriptions/:sid", r.Wrap(r.apiHandler.GetSubscription))
-		apiv2.DELETE("/users/:uid/subscriptions/:sid", ginresp.Wrap(r.apiHandler.CancelSubscription))
+		apiv2.DELETE("/users/:uid/subscriptions/:sid", r.Wrap(r.apiHandler.CancelSubscription))
-		apiv2.PATCH("/users/:uid/subscriptions/:sid", ginresp.Wrap(r.apiHandler.UpdateSubscription))
+		apiv2.PATCH("/users/:uid/subscriptions/:sid", r.Wrap(r.apiHandler.UpdateSubscription))
 
-		apiv2.GET("/messages", ginresp.Wrap(r.apiHandler.ListMessages))
+		apiv2.GET("/messages", r.Wrap(r.apiHandler.ListMessages))
-		apiv2.GET("/messages/:mid", ginresp.Wrap(r.apiHandler.GetMessage))
+		apiv2.GET("/messages/:mid", r.Wrap(r.apiHandler.GetMessage))
-		apiv2.DELETE("/messages/:mid", ginresp.Wrap(r.apiHandler.DeleteMessage))
+		apiv2.DELETE("/messages/:mid", r.Wrap(r.apiHandler.DeleteMessage))
 	}
 
 	// ================ Send API ================
 
 	sendAPI := e.Group("")
 	{
-		sendAPI.POST("/", ginresp.Wrap(r.messageHandler.SendMessage))
+		sendAPI.POST("/", r.Wrap(r.messageHandler.SendMessage))
-		sendAPI.POST("/send", ginresp.Wrap(r.messageHandler.SendMessage))
+		sendAPI.POST("/send", r.Wrap(r.messageHandler.SendMessage))
-		sendAPI.POST("/send.php", ginresp.Wrap(r.messageHandler.SendMessageCompat))
+		sendAPI.POST("/send.php", r.Wrap(r.messageHandler.SendMessageCompat))
 	}
 
 	if r.app.Config.ReturnRawErrors {
-		e.NoRoute(ginresp.Wrap(r.commonHandler.NoRoute))
+		e.NoRoute(r.Wrap(r.commonHandler.NoRoute))
 	}
 
 }
+
+func (r *Router) Wrap(fn ginresp.WHandlerFunc) gin.HandlerFunc {
+	return ginresp.Wrap(r.app, fn)
+}

scnserver/cmd/scnserver/main.go

@@ -59,7 +59,9 @@ func main() {
 
 	jobRetry := jobs.NewDeliveryRetryJob(app)
 
-	app.Init(conf, ginengine, nc, apc, []logic.Job{jobRetry})
+	jobReqCollector := jobs.NewRequestLogCollectorJob(app)
+
+	app.Init(conf, ginengine, nc, apc, []logic.Job{jobRetry, jobReqCollector})
 
 	router.Init(ginengine)
 

scnserver/config.go

@@ -5,6 +5,7 @@ import (
 	"github.com/rs/zerolog"
 	"github.com/rs/zerolog/log"
 	"gogs.mikescher.com/BlackForestBytes/goext/confext"
+	"gogs.mikescher.com/BlackForestBytes/goext/timeext"
 	"os"
 	"time"
 )
@@ -37,6 +38,10 @@ type Config struct {
 	GoogleAPIPrivateKey      string        `env:"SCN_GOOG_PRIVATEKEY"`
 	GooglePackageName        string        `env:"SCN_GOOG_PACKAGENAME"`
 	GoogleProProductID       string        `env:"SCN_GOOG_PROPRODUCTID"`
+	ReqLogEnabled            bool          `env:"SCN_REQUESTLOG_ENABLED"`
+	ReqLogMaxBodySize        int           `env:"SCN_REQUESTLOG_MAXBODYSIZE"`
+	ReqLogHistoryMaxCount    int           `env:"SCN_REQUESTLOG_HISTORY_MAXCOUNT"`
+	ReqLogHistoryMaxDuration time.Duration `env:"SCN_REQUESTLOG_HISTORY_MAXDURATION"`
 }
 
 type DBConfig struct {
@@ -112,6 +117,10 @@ var configLocHost = func() Config {
 		GooglePackageName:        "",
 		GoogleProProductID:       "",
 		Cors:                     true,
+		ReqLogEnabled:            true,
+		ReqLogMaxBodySize:        2048,
+		ReqLogHistoryMaxCount:    1638,
+		ReqLogHistoryMaxDuration: timeext.FromDays(60),
 	}
 }
 
@@ -174,6 +183,9 @@ var configLocDocker = func() Config {
 		GooglePackageName:        "",
 		GoogleProProductID:       "",
 		Cors:                     true,
+		ReqLogMaxBodySize:        2048,
+		ReqLogHistoryMaxCount:    1638,
+		ReqLogHistoryMaxDuration: timeext.FromDays(60),
 	}
 }
 
@@ -236,6 +248,9 @@ var configDev = func() Config {
 		GooglePackageName:        confEnv("SCN_GOOG_PACKAGENAME"),
 		GoogleProProductID:       confEnv("SCN_GOOG_PROPRODUCTID"),
 		Cors:                     true,
+		ReqLogMaxBodySize:        2048,
+		ReqLogHistoryMaxCount:    1638,
+		ReqLogHistoryMaxDuration: timeext.FromDays(60),
 	}
 }
 
@@ -298,6 +313,9 @@ var configStag = func() Config {
 		GooglePackageName:        confEnv("SCN_GOOG_PACKAGENAME"),
 		GoogleProProductID:       confEnv("SCN_GOOG_PROPRODUCTID"),
 		Cors:                     true,
+		ReqLogMaxBodySize:        2048,
+		ReqLogHistoryMaxCount:    1638,
+		ReqLogHistoryMaxDuration: timeext.FromDays(60),
 	}
 }
 
@@ -360,6 +378,9 @@ var configProd = func() Config {
 		GooglePackageName:        confEnv("SCN_SCN_GOOG_PACKAGENAME"),
 		GoogleProProductID:       confEnv("SCN_SCN_GOOG_PROPRODUCTID"),
 		Cors:                     true,
+		ReqLogMaxBodySize:        2048,
+		ReqLogHistoryMaxCount:    1638,
+		ReqLogHistoryMaxDuration: timeext.FromDays(60),
 	}
 }
 

scnserver/db/impl/requests/requestlogs.go

@@ -0,0 +1,96 @@
+package requests
+
+import (
+	"blackforestbytes.com/simplecloudnotifier/models"
+	"context"
+	"gogs.mikescher.com/BlackForestBytes/goext/sq"
+	"time"
+)
+
+func (db *Database) InsertRequestLog(ctx context.Context, data models.RequestLogDB) (models.RequestLogDB, error) {
+
+	now := time.Now()
+
+	res, err := db.db.Exec(ctx, "INSERT INTO requests (method, uri, user_agent, authentication, request_body, request_body_size, request_content_type, remote_ip, userid, permissions, response_statuscode, response_body_size, response_body, response_content_type, retry_count, panicked, panic_str, processing_time, timestamp_created, timestamp_start, timestamp_finish) VALUES (:method, :uri, :user_agent, :authentication, :request_body, :request_body_size, :request_content_type, :remote_ip, :userid, :permissions, :response_statuscode, :response_body_size, :response_body, :response_content_type, :retry_count, :panicked, :panic_str, :processing_time, :timestamp_created, :timestamp_start, :timestamp_finish)", sq.PP{
+		"method":                data.Method,
+		"uri":                   data.URI,
+		"user_agent":            data.UserAgent,
+		"authentication":        data.Authentication,
+		"request_body":          data.RequestBody,
+		"request_body_size":     data.RequestBodySize,
+		"request_content_type":  data.RequestContentType,
+		"remote_ip":             data.RemoteIP,
+		"userid":                data.UserID,
+		"permissions":           data.Permissions,
+		"response_statuscode":   data.ResponseStatuscode,
+		"response_body_size":    data.ResponseBodySize,
+		"response_body":         data.ResponseBody,
+		"response_content_type": data.ResponseContentType,
+		"retry_count":           data.RetryCount,
+		"panicked":              data.Panicked,
+		"panic_str":             data.PanicStr,
+		"processing_time":       data.ProcessingTime,
+		"timestamp_created":     now.UnixMilli(),
+		"timestamp_start":       data.TimestampStart,
+		"timestamp_finish":      data.TimestampFinish,
+	})
+	if err != nil {
+		return models.RequestLogDB{}, err
+	}
+
+	liid, err := res.LastInsertId()
+	if err != nil {
+		return models.RequestLogDB{}, err
+	}
+
+	return models.RequestLogDB{
+		RequestID:           models.RequestID(liid),
+		Method:              data.Method,
+		URI:                 data.URI,
+		UserAgent:           data.UserAgent,
+		Authentication:      data.Authentication,
+		RequestBody:         data.RequestBody,
+		RequestBodySize:     data.RequestBodySize,
+		RequestContentType:  data.RequestContentType,
+		RemoteIP:            data.RemoteIP,
+		UserID:              data.UserID,
+		Permissions:         data.Permissions,
+		ResponseStatuscode:  data.ResponseStatuscode,
+		ResponseBodySize:    data.ResponseBodySize,
+		ResponseBody:        data.ResponseBody,
+		ResponseContentType: data.ResponseContentType,
+		RetryCount:          data.RetryCount,
+		Panicked:            data.Panicked,
+		PanicStr:            data.PanicStr,
+		ProcessingTime:      data.ProcessingTime,
+		TimestampCreated:    now.UnixMilli(),
+		TimestampStart:      data.TimestampStart,
+		TimestampFinish:     data.TimestampFinish,
+	}, nil
+}
+
+func (db *Database) Cleanup(ctx context.Context, count int, duration time.Duration) (int64, error) {
+	res1, err := db.db.Exec(ctx, "DELETE FROM requests WHERE request_id NOT IN ( SELECT request_id FROM requests ORDER BY timestamp_created DESC LIMIT :lim ) ", sq.PP{
+		"lim": count,
+	})
+	if err != nil {
+		return 0, err
+	}
+	affected1, err := res1.RowsAffected()
+	if err != nil {
+		return 0, err
+	}
+
+	res2, err := db.db.Exec(ctx, "DELETE FROM requests WHERE timestamp_created < :tslim", sq.PP{
+		"tslim": time.Now().Add(-duration).UnixMilli(),
+	})
+	if err != nil {
+		return 0, err
+	}
+	affected2, err := res2.RowsAffected()
+	if err != nil {
+		return 0, err
+	}
+
+	return affected1 + affected2, nil
+}

scnserver/db/impl/requests/schema/schema_1.ddl

@@ -1,8 +1,32 @@
 
 CREATE TABLE `requests`
 (
-    request_id           INTEGER        PRIMARY KEY,
+    request_id            INTEGER                                PRIMARY KEY AUTOINCREMENT,
-    timestamp_created    INTEGER        NOT NULL
+
+    method                TEXT                                   NOT NULL,
+    uri                   TEXT                                   NOT NULL,
+    user_agent            TEXT                                       NULL,
+    authentication        TEXT                                       NULL,
+    request_body          TEXT                                       NULL,
+    request_body_size     INTEGER                                NOT NULL,
+    request_content_type  TEXT                                   NOT NULL,
+    remote_ip             TEXT                                   NOT NULL,
+
+    userid                TEXT                                       NULL,
+    permissions           TEXT                                       NULL,
+
+    response_statuscode   INTEGER                                NOT NULL,
+    response_body_size    INTEGER                                NOT NULL,
+    response_body         TEXT                                       NULL,
+    response_content_type TEXT                                   NOT NULL,
+    processing_time       INTEGER                                NOT NULL,
+    retry_count           INTEGER                                NOT NULL,
+    panicked              INTEGER    CHECK(panicked IN (0, 1))   NOT NULL,
+    panic_str             TEXT                                       NULL,
+
+    timestamp_created     INTEGER                                NOT NULL,
+    timestamp_start       INTEGER                                NOT NULL,
+    timestamp_finish      INTEGER                                NOT NULL
 
 ) STRICT;
 

scnserver/go.mod

@@ -7,7 +7,7 @@ require (
 	github.com/jmoiron/sqlx v1.3.5
 	github.com/mattn/go-sqlite3 v1.14.16
 	github.com/rs/zerolog v1.28.0
-	gogs.mikescher.com/BlackForestBytes/goext v0.0.55
+	gogs.mikescher.com/BlackForestBytes/goext v0.0.56
 	gopkg.in/loremipsum.v1 v1.1.0
 )
 

scnserver/go.sum

@@ -79,6 +79,8 @@ gogs.mikescher.com/BlackForestBytes/goext v0.0.50 h1:WuhfxFVyywR7J4+hSTTW/wE87aF
 gogs.mikescher.com/BlackForestBytes/goext v0.0.50/go.mod h1:ZEXyKUr8t0EKdPN1FYdk0klY7N8OwXxipGE9lWgpVE8=
 gogs.mikescher.com/BlackForestBytes/goext v0.0.55 h1:mzX/s+EBhnaRbiz3+6iwDJyJFS0F+jkbssiLDr9eJYY=
 gogs.mikescher.com/BlackForestBytes/goext v0.0.55/go.mod h1:ZEXyKUr8t0EKdPN1FYdk0klY7N8OwXxipGE9lWgpVE8=
+gogs.mikescher.com/BlackForestBytes/goext v0.0.56 h1:nl+2mP3BmkeB3kT6zFNXqYkOLc3JnFF3m8QwhxZJf2A=
+gogs.mikescher.com/BlackForestBytes/goext v0.0.56/go.mod h1:ZEXyKUr8t0EKdPN1FYdk0klY7N8OwXxipGE9lWgpVE8=
 golang.org/x/crypto v0.0.0-20210711020723-a769d52b0f97/go.mod h1:GvvjBRRGRdwPK5ydBHafDWAxML/pGHZbMvKqRZ5+Abc=
 golang.org/x/crypto v0.4.0 h1:UVQgzMY87xqpKNgb+kDsll2Igd33HszWHFLmpaRMq/8=
 golang.org/x/crypto v0.4.0/go.mod h1:3quD/ATkf6oY+rnes5c3ExXTbLc8mueNue5/DoinL80=

scnserver/jobs/DeliveryRetryJob.go

@@ -3,58 +3,106 @@ package jobs
 import (
 	"blackforestbytes.com/simplecloudnotifier/logic"
 	"blackforestbytes.com/simplecloudnotifier/models"
+	"errors"
+	"fmt"
 	"github.com/rs/zerolog/log"
+	"gogs.mikescher.com/BlackForestBytes/goext/syncext"
 	"time"
 )
 
 type DeliveryRetryJob struct {
 	app        *logic.Application
-	running     bool
+	name       string
-	stopChannel chan bool
+	isRunning  *syncext.AtomicBool
+	isStarted  bool
+	sigChannel chan string
 }
 
 func NewDeliveryRetryJob(app *logic.Application) *DeliveryRetryJob {
 	return &DeliveryRetryJob{
 		app:        app,
-		running:     true,
+		name:       "DeliveryRetryJob",
-		stopChannel: make(chan bool, 8),
+		isRunning:  syncext.NewAtomicBool(false),
+		isStarted:  false,
+		sigChannel: make(chan string),
 	}
 }
 
-func (j *DeliveryRetryJob) Start() {
+func (j *DeliveryRetryJob) Start() error {
-	if !j.running {
+	if j.isRunning.Get() {
-		panic("cannot re-start job")
+		return errors.New("job already running")
+	}
+	if j.isStarted {
+		return errors.New("job was already started") // re-start after stop is not allowed
 	}
 
+	j.isStarted = true
+
 	go j.mainLoop()
+
+	return nil
 }
 
 func (j *DeliveryRetryJob) Stop() {
-	j.running = false
+	log.Info().Msg(fmt.Sprintf("Stopping Job [%s]", j.name))
+	syncext.WriteNonBlocking(j.sigChannel, "stop")
+	j.isRunning.Wait(false)
+	log.Info().Msg(fmt.Sprintf("Stopped Job [%s]", j.name))
+}
+
+func (j *DeliveryRetryJob) Running() bool {
+	return j.isRunning.Get()
 }
 
 func (j *DeliveryRetryJob) mainLoop() {
-	fastRerun := false
+	j.isRunning.Set(true)
 
-	for j.running {
+	var fastRerun bool = false
+	var err error = nil
+
+	for {
+		interval := 30 * time.Second
 		if fastRerun {
-			j.sleep(1 * time.Second)
+			interval = 1 * time.Second
+		}
+
+		signal, okay := syncext.ReadChannelWithTimeout(j.sigChannel, interval)
+		if okay {
+			if signal == "stop" {
+				log.Info().Msg(fmt.Sprintf("Job [%s] received <stop> signal", j.name))
+				break
+			} else if signal == "run" {
+				log.Info().Msg(fmt.Sprintf("Job [%s] received <run> signal", j.name))
+				continue
 			} else {
-			j.sleep(30 * time.Second)
+				log.Error().Msg(fmt.Sprintf("Received unknown job signal: <%s> in job [%s]", signal, j.name))
 			}
-		if !j.running {
-			return
 		}
 
-		fastRerun = j.run()
+		log.Debug().Msg(fmt.Sprintf("Run job [%s]", j.name))
+
+		t0 := time.Now()
+		fastRerun, err = j.execute()
+		if err != nil {
+			log.Err(err).Msg(fmt.Sprintf("Failed to execute job [%s]: %s", j.name, err.Error()))
+		} else {
+			t1 := time.Now()
+			log.Debug().Msg(fmt.Sprintf("Job [%s] finished successfully after %f minutes", j.name, (t1.Sub(t0)).Minutes()))
+		}
 
 	}
+
+	log.Info().Msg(fmt.Sprintf("Job [%s] exiting main-loop", j.name))
+
+	j.isRunning.Set(false)
 }
 
-func (j *DeliveryRetryJob) run() bool {
+func (j *DeliveryRetryJob) execute() (fastrr bool, err error) {
 	defer func() {
 		if rec := recover(); rec != nil {
 			log.Error().Interface("recover", rec).Msg("Recovered panic in DeliveryRetryJob")
+			err = errors.New(fmt.Sprintf("Panic recovered: %v", rec))
+			fastrr = false
 		}
 	}()
 
@@ -63,14 +111,12 @@ func (j *DeliveryRetryJob) run() bool {
 
 	deliveries, err := j.app.Database.Primary.ListRetrieableDeliveries(ctx, 32)
 	if err != nil {
-		log.Err(err).Msg("Failed to query retrieable deliveries")
+		return false, err
-		return false
 	}
 
 	err = ctx.CommitTransaction()
 	if err != nil {
-		log.Err(err).Msg("Failed to commit")
+		return false, err
-		return false
 	}
 
 	if len(deliveries) == 32 {
@@ -81,7 +127,7 @@ func (j *DeliveryRetryJob) run() bool {
 		j.redeliver(ctx, delivery)
 	}
 
-	return len(deliveries) == 32
+	return len(deliveries) == 32, nil
 }
 
 func (j *DeliveryRetryJob) redeliver(ctx *logic.SimpleContext, delivery models.Delivery) {
@@ -139,19 +185,3 @@ func (j *DeliveryRetryJob) redeliver(ctx *logic.SimpleContext, delivery models.D
 	err = ctx.CommitTransaction()
 
 }
-
-func (j *DeliveryRetryJob) sleep(d time.Duration) {
-	if !j.running {
-		return
-	}
-	afterCh := time.After(d)
-	for {
-		select {
-		case <-j.stopChannel:
-			j.stopChannel <- true
-			return
-		case <-afterCh:
-			return
-		}
-	}
-}

scnserver/jobs/RequestLogCleanupJob.go

@@ -0,0 +1,114 @@
+package jobs
+
+import (
+	"blackforestbytes.com/simplecloudnotifier/logic"
+	"errors"
+	"fmt"
+	"github.com/rs/zerolog/log"
+	"gogs.mikescher.com/BlackForestBytes/goext/syncext"
+	"time"
+)
+
+type RequestLogCleanupJob struct {
+	app        *logic.Application
+	name       string
+	isRunning  *syncext.AtomicBool
+	isStarted  bool
+	sigChannel chan string
+}
+
+func NewRequestLogCleanupJob(app *logic.Application) *DeliveryRetryJob {
+	return &DeliveryRetryJob{
+		app:        app,
+		name:       "RequestLogCleanupJob",
+		isRunning:  syncext.NewAtomicBool(false),
+		isStarted:  false,
+		sigChannel: make(chan string),
+	}
+}
+
+func (j *RequestLogCleanupJob) Start() error {
+	if j.isRunning.Get() {
+		return errors.New("job already running")
+	}
+	if j.isStarted {
+		return errors.New("job was already started") // re-start after stop is not allowed
+	}
+
+	j.isStarted = true
+
+	go j.mainLoop()
+
+	return nil
+}
+
+func (j *RequestLogCleanupJob) Stop() {
+	log.Info().Msg(fmt.Sprintf("Stopping Job [%s]", j.name))
+	syncext.WriteNonBlocking(j.sigChannel, "stop")
+	j.isRunning.Wait(false)
+	log.Info().Msg(fmt.Sprintf("Stopped Job [%s]", j.name))
+}
+
+func (j *RequestLogCleanupJob) Running() bool {
+	return j.isRunning.Get()
+}
+
+func (j *RequestLogCleanupJob) mainLoop() {
+	j.isRunning.Set(true)
+
+	var err error = nil
+
+	for {
+		interval := 1 * time.Hour
+
+		signal, okay := syncext.ReadChannelWithTimeout(j.sigChannel, interval)
+		if okay {
+			if signal == "stop" {
+				log.Info().Msg(fmt.Sprintf("Job [%s] received <stop> signal", j.name))
+				break
+			} else if signal == "run" {
+				log.Info().Msg(fmt.Sprintf("Job [%s] received <run> signal", j.name))
+				continue
+			} else {
+				log.Error().Msg(fmt.Sprintf("Received unknown job signal: <%s> in job [%s]", signal, j.name))
+			}
+		}
+
+		log.Debug().Msg(fmt.Sprintf("Run job [%s]", j.name))
+
+		t0 := time.Now()
+		err = j.execute()
+		if err != nil {
+			log.Err(err).Msg(fmt.Sprintf("Failed to execute job [%s]: %s", j.name, err.Error()))
+		} else {
+			t1 := time.Now()
+			log.Debug().Msg(fmt.Sprintf("Job [%s] finished successfully after %f minutes", j.name, (t1.Sub(t0)).Minutes()))
+		}
+
+	}
+
+	log.Info().Msg(fmt.Sprintf("Job [%s] exiting main-loop", j.name))
+
+	j.isRunning.Set(false)
+}
+
+func (j *RequestLogCleanupJob) execute() (err error) {
+	defer func() {
+		if rec := recover(); rec != nil {
+			log.Error().Interface("recover", rec).Msg("Recovered panic in DeliveryRetryJob")
+			err = errors.New(fmt.Sprintf("Panic recovered: %v", rec))
+		}
+	}()
+
+	ctx := j.app.NewSimpleTransactionContext(10 * time.Second)
+	defer ctx.Cancel()
+
+	deleted, err := j.app.Database.Requests.Cleanup(ctx, j.app.Config.ReqLogHistoryMaxCount, j.app.Config.ReqLogHistoryMaxDuration)
+	if err != nil {
+		return err
+	}
+
+	log.Warn().Msgf("Deleted %d entries from the request-log table", deleted)
+
+	return nil
+}

scnserver/jobs/RequestLogCollectorJob.go

@@ -0,0 +1,100 @@
+package jobs
+
+import (
+	"blackforestbytes.com/simplecloudnotifier/logic"
+	"blackforestbytes.com/simplecloudnotifier/models"
+	"context"
+	"errors"
+	"fmt"
+	"github.com/rs/zerolog/log"
+	"gogs.mikescher.com/BlackForestBytes/goext/syncext"
+	"time"
+)
+
+type RequestLogCollectorJob struct {
+	app        *logic.Application
+	name       string
+	isRunning  *syncext.AtomicBool
+	isStarted  bool
+	sigChannel chan string
+}
+
+func NewRequestLogCollectorJob(app *logic.Application) *RequestLogCollectorJob {
+	return &RequestLogCollectorJob{
+		app:        app,
+		name:       "RequestLogCollectorJob",
+		isRunning:  syncext.NewAtomicBool(false),
+		isStarted:  false,
+		sigChannel: make(chan string),
+	}
+}
+
+func (j *RequestLogCollectorJob) Start() error {
+	if j.isRunning.Get() {
+		return errors.New("job already running")
+	}
+	if j.isStarted {
+		return errors.New("job was already started") // re-start after stop is not allowed
+	}
+
+	j.isStarted = true
+
+	go j.mainLoop()
+
+	return nil
+}
+
+func (j *RequestLogCollectorJob) Stop() {
+	log.Info().Msg(fmt.Sprintf("Stopping Job [%s]", j.name))
+	syncext.WriteNonBlocking(j.sigChannel, "stop")
+	j.isRunning.Wait(false)
+	log.Info().Msg(fmt.Sprintf("Stopped Job [%s]", j.name))
+}
+
+func (j *RequestLogCollectorJob) Running() bool {
+	return j.isRunning.Get()
+}
+
+func (j *RequestLogCollectorJob) mainLoop() {
+	j.isRunning.Set(true)
+
+mainLoop:
+	for {
+		select {
+		case signal := <-j.sigChannel:
+			if signal == "stop" {
+				log.Info().Msg(fmt.Sprintf("Job [%s] received <stop> signal", j.name))
+				break mainLoop
+			} else if signal == "run" {
+				log.Info().Msg(fmt.Sprintf("Job [%s] received <run> signal", j.name))
+				continue
+			} else {
+				log.Error().Msg(fmt.Sprintf("Received unknown job signal: <%s> in job [%s]", signal, j.name))
+			}
+		case obj := <-j.app.RequestLogQueue:
+			err := j.insertLog(obj)
+			if err != nil {
+				log.Error().Err(err).Msg(fmt.Sprintf("Failed to insert RequestLog {%s} into DB", obj.RequestID))
+			} else {
+				log.Debug().Msg(fmt.Sprintf("Inserted RequestLog '%s' into DB", obj.RequestID))
+			}
+		}
+	}
+
+	log.Info().Msg(fmt.Sprintf("Job [%s] exiting main-loop", j.name))
+
+	j.isRunning.Set(false)
+}
+
+func (j *RequestLogCollectorJob) insertLog(rl models.RequestLog) error {
+
+	ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second)
+	defer cancel()
+
+	_, err := j.app.Database.Requests.InsertRequestLog(ctx, rl.DB())
+	if err != nil {
+		return err
+	}
+
+	return nil
+}

scnserver/logic/appcontext.go

@@ -4,6 +4,7 @@ import (
 	"blackforestbytes.com/simplecloudnotifier/api/apierr"
 	"blackforestbytes.com/simplecloudnotifier/api/ginresp"
 	"blackforestbytes.com/simplecloudnotifier/db"
+	"blackforestbytes.com/simplecloudnotifier/models"
 	"context"
 	"errors"
 	"github.com/gin-gonic/gin"
@@ -17,7 +18,7 @@ type AppContext struct {
 	cancelFunc  context.CancelFunc
 	cancelled   bool
 	transaction sq.Tx
-	permissions PermissionSet
+	permissions models.PermissionSet
 	ginContext  *gin.Context
 }
 
@@ -27,7 +28,7 @@ func CreateAppContext(g *gin.Context, innerCtx context.Context, cancelFn context
 		cancelFunc:  cancelFn,
 		cancelled:   false,
 		transaction: nil,
-		permissions: NewEmptyPermissions(),
+		permissions: models.NewEmptyPermissions(),
 		ginContext:  g,
 	}
 }

scnserver/logic/application.go

@@ -24,6 +24,10 @@ import (
 	"time"
 )
 
+var rexWhitespaceStart = regexp.MustCompile("^\\s+")
+
+var rexWhitespaceEnd = regexp.MustCompile("\\s+$")
+
 type Application struct {
 	Config           scn.Config
 	Gin              *gin.Engine
@@ -34,6 +38,7 @@ type Application struct {
 	stopChan         chan bool
 	Port             string
 	IsRunning        *syncext.AtomicBool
+	RequestLogQueue  chan models.RequestLog
 }
 
 func NewApp(db *DBPool) *Application {
@@ -41,6 +46,7 @@ func NewApp(db *DBPool) *Application {
 		Database:        db,
 		stopChan:        make(chan bool),
 		IsRunning:       syncext.NewAtomicBool(false),
+		RequestLogQueue: make(chan models.RequestLog, 1024),
 	}
 }
 
@@ -94,7 +100,10 @@ func (app *Application) Run() {
 	signal.Notify(sigstop, os.Interrupt, syscall.SIGTERM)
 
 	for _, job := range app.Jobs {
-		job.Start()
+		err := job.Start()
+		if err != nil {
+			log.Fatal().Err(err).Msg("Failed to start job")
+		}
 	}
 
 	select {
@@ -243,6 +252,7 @@ func (app *Application) StartRequest(g *gin.Context, uri any, query any, body an
 	}
 
 	actx.permissions = perm
+	g.Set("perm", perm)
 
 	return actx, nil
 }
@@ -252,33 +262,33 @@ func (app *Application) NewSimpleTransactionContext(timeout time.Duration) *Simp
 	return CreateSimpleContext(ictx, cancel)
 }
 
-func (app *Application) getPermissions(ctx *AppContext, hdr string) (PermissionSet, error) {
+func (app *Application) getPermissions(ctx *AppContext, hdr string) (models.PermissionSet, error) {
 	if hdr == "" {
-		return NewEmptyPermissions(), nil
+		return models.NewEmptyPermissions(), nil
 	}
 
 	if !strings.HasPrefix(hdr, "SCN ") {
-		return NewEmptyPermissions(), nil
+		return models.NewEmptyPermissions(), nil
 	}
 
 	key := strings.TrimSpace(hdr[4:])
 
 	user, err := app.Database.Primary.GetUserByKey(ctx, key)
 	if err != nil {
-		return PermissionSet{}, err
+		return models.PermissionSet{}, err
 	}
 
 	if user != nil && user.SendKey == key {
-		return PermissionSet{UserID: langext.Ptr(user.UserID), KeyType: PermKeyTypeUserSend}, nil
+		return models.PermissionSet{UserID: langext.Ptr(user.UserID), KeyType: models.PermKeyTypeUserSend}, nil
 	}
 	if user != nil && user.ReadKey == key {
-		return PermissionSet{UserID: langext.Ptr(user.UserID), KeyType: PermKeyTypeUserRead}, nil
+		return models.PermissionSet{UserID: langext.Ptr(user.UserID), KeyType: models.PermKeyTypeUserRead}, nil
 	}
 	if user != nil && user.AdminKey == key {
-		return PermissionSet{UserID: langext.Ptr(user.UserID), KeyType: PermKeyTypeUserAdmin}, nil
+		return models.PermissionSet{UserID: langext.Ptr(user.UserID), KeyType: models.PermKeyTypeUserAdmin}, nil
 	}
 
-	return NewEmptyPermissions(), nil
+	return models.NewEmptyPermissions(), nil
 }
 
 func (app *Application) GetOrCreateChannel(ctx *AppContext, userid models.UserID, displayChanName string, intChanName string) (models.Channel, error) {
@@ -307,9 +317,6 @@ func (app *Application) GetOrCreateChannel(ctx *AppContext, userid models.UserID
 	return newChan, nil
 }
 
-var rexWhitespaceStart = regexp.MustCompile("^\\s+")
-var rexWhitespaceEnd = regexp.MustCompile("\\s+$")
-
 func (app *Application) NormalizeChannelDisplayName(v string) string {
 	v = strings.TrimSpace(v)
 	v = rexWhitespaceStart.ReplaceAllString(v, "")
@@ -348,3 +355,10 @@ func (app *Application) DeliverMessage(ctx context.Context, client models.Client
 		return langext.Ptr(""), nil
 	}
 }
+
+func (app *Application) InsertRequestLog(data models.RequestLog) {
+	ok := syncext.WriteNonBlocking(app.RequestLogQueue, data)
+	if !ok {
+		log.Error().Msg("failed to insert request-log (queue full)")
+	}
+}

scnserver/logic/jobs.go

@@ -1,6 +1,7 @@
 package logic
 
 type Job interface {
-	Start()
+	Start() error
 	Stop()
+	Running() bool
 }

scnserver/logic/permissions.go

@@ -7,33 +7,12 @@ import (
 	"gogs.mikescher.com/BlackForestBytes/goext/langext"
 )
 
-type PermKeyType string
-
-const (
-	PermKeyTypeNone      PermKeyType = "NONE"       // (nothing)
-	PermKeyTypeUserSend  PermKeyType = "USER_SEND"  // send-messages
-	PermKeyTypeUserRead  PermKeyType = "USER_READ"  // send-messages, list-messages, read-user
-	PermKeyTypeUserAdmin PermKeyType = "USER_ADMIN" // send-messages, list-messages, read-user, delete-messages, update-user
-)
-
-type PermissionSet struct {
-	UserID  *models.UserID
-	KeyType PermKeyType
-}
-
-func NewEmptyPermissions() PermissionSet {
-	return PermissionSet{
-		UserID:  nil,
-		KeyType: PermKeyTypeNone,
-	}
-}
-
 func (ac *AppContext) CheckPermissionUserRead(userid models.UserID) *ginresp.HTTPResponse {
 	p := ac.permissions
-	if p.UserID != nil && *p.UserID == userid && p.KeyType == PermKeyTypeUserRead {
+	if p.UserID != nil && *p.UserID == userid && p.KeyType == models.PermKeyTypeUserRead {
 		return nil
 	}
-	if p.UserID != nil && *p.UserID == userid && p.KeyType == PermKeyTypeUserAdmin {
+	if p.UserID != nil && *p.UserID == userid && p.KeyType == models.PermKeyTypeUserAdmin {
 		return nil
 	}
 
@@ -42,10 +21,10 @@ func (ac *AppContext) CheckPermissionUserRead(userid models.UserID) *ginresp.HTT
 
 func (ac *AppContext) CheckPermissionRead() *ginresp.HTTPResponse {
 	p := ac.permissions
-	if p.UserID != nil && p.KeyType == PermKeyTypeUserRead {
+	if p.UserID != nil && p.KeyType == models.PermKeyTypeUserRead {
 		return nil
 	}
-	if p.UserID != nil && p.KeyType == PermKeyTypeUserAdmin {
+	if p.UserID != nil && p.KeyType == models.PermKeyTypeUserAdmin {
 		return nil
 	}
 
@@ -54,7 +33,7 @@ func (ac *AppContext) CheckPermissionRead() *ginresp.HTTPResponse {
 
 func (ac *AppContext) CheckPermissionUserAdmin(userid models.UserID) *ginresp.HTTPResponse {
 	p := ac.permissions
-	if p.UserID != nil && *p.UserID == userid && p.KeyType == PermKeyTypeUserAdmin {
+	if p.UserID != nil && *p.UserID == userid && p.KeyType == models.PermKeyTypeUserAdmin {
 		return nil
 	}
 
@@ -63,10 +42,10 @@ func (ac *AppContext) CheckPermissionUserAdmin(userid models.UserID) *ginresp.HT
 
 func (ac *AppContext) CheckPermissionSend() *ginresp.HTTPResponse {
 	p := ac.permissions
-	if p.UserID != nil && p.KeyType == PermKeyTypeUserSend {
+	if p.UserID != nil && p.KeyType == models.PermKeyTypeUserSend {
 		return nil
 	}
-	if p.UserID != nil && p.KeyType == PermKeyTypeUserAdmin {
+	if p.UserID != nil && p.KeyType == models.PermKeyTypeUserAdmin {
 		return nil
 	}
 
@@ -75,7 +54,7 @@ func (ac *AppContext) CheckPermissionSend() *ginresp.HTTPResponse {
 
 func (ac *AppContext) CheckPermissionAny() *ginresp.HTTPResponse {
 	p := ac.permissions
-	if p.KeyType == PermKeyTypeNone {
+	if p.KeyType == models.PermKeyTypeNone {
 		return langext.Ptr(ginresp.APIError(ac.ginContext, 401, apierr.USER_AUTH_FAILED, "You are not authorized for this action", nil))
 	}
 
@@ -84,10 +63,10 @@ func (ac *AppContext) CheckPermissionAny() *ginresp.HTTPResponse {
 
 func (ac *AppContext) CheckPermissionMessageReadDirect(msg models.Message) bool {
 	p := ac.permissions
-	if p.UserID != nil && msg.OwnerUserID == *p.UserID && p.KeyType == PermKeyTypeUserRead {
+	if p.UserID != nil && msg.OwnerUserID == *p.UserID && p.KeyType == models.PermKeyTypeUserRead {
 		return true
 	}
-	if p.UserID != nil && msg.OwnerUserID == *p.UserID && p.KeyType == PermKeyTypeUserAdmin {
+	if p.UserID != nil && msg.OwnerUserID == *p.UserID && p.KeyType == models.PermKeyTypeUserAdmin {
 		return true
 	}
 
@@ -104,15 +83,15 @@ func (ac *AppContext) GetPermissionUserID() *models.UserID {
 
 func (ac *AppContext) IsPermissionUserRead() bool {
 	p := ac.permissions
-	return p.KeyType == PermKeyTypeUserRead || p.KeyType == PermKeyTypeUserAdmin
+	return p.KeyType == models.PermKeyTypeUserRead || p.KeyType == models.PermKeyTypeUserAdmin
 }
 
 func (ac *AppContext) IsPermissionUserSend() bool {
 	p := ac.permissions
-	return p.KeyType == PermKeyTypeUserSend || p.KeyType == PermKeyTypeUserAdmin
+	return p.KeyType == models.PermKeyTypeUserSend || p.KeyType == models.PermKeyTypeUserAdmin
 }
 
 func (ac *AppContext) IsPermissionUserAdmin() bool {
 	p := ac.permissions
-	return p.KeyType == PermKeyTypeUserAdmin
+	return p.KeyType == models.PermKeyTypeUserAdmin
 }

scnserver/models/ids.go

@@ -66,3 +66,13 @@ func (id ClientID) IntID() int64 {
 func (id ClientID) String() string {
 	return strconv.FormatInt(int64(id), 10)
 }
+
+type RequestID int64
+
+func (id RequestID) IntID() int64 {
+	return int64(id)
+}
+
+func (id RequestID) String() string {
+	return strconv.FormatInt(int64(id), 10)
+}

scnserver/models/permissions.go

@@ -0,0 +1,22 @@
+package models
+
+type PermKeyType string
+
+const (
+	PermKeyTypeNone      PermKeyType = "NONE"       // (nothing)
+	PermKeyTypeUserSend  PermKeyType = "USER_SEND"  // send-messages
+	PermKeyTypeUserRead  PermKeyType = "USER_READ"  // send-messages, list-messages, read-user
+	PermKeyTypeUserAdmin PermKeyType = "USER_ADMIN" // send-messages, list-messages, read-user, delete-messages, update-user
+)
+
+type PermissionSet struct {
+	UserID  *UserID
+	KeyType PermKeyType
+}
+
+func NewEmptyPermissions() PermissionSet {
+	return PermissionSet{
+		UserID:  nil,
+		KeyType: PermKeyTypeNone,
+	}
+}

scnserver/models/requestlog.go

@@ -0,0 +1,181 @@
+package models
+
+import (
+	"github.com/jmoiron/sqlx"
+	"gogs.mikescher.com/BlackForestBytes/goext/langext"
+	"gogs.mikescher.com/BlackForestBytes/goext/sq"
+	"gogs.mikescher.com/BlackForestBytes/goext/timeext"
+	"time"
+)
+
+type RequestLog struct {
+	RequestID           RequestID
+	Method              string
+	URI                 string
+	UserAgent           *string
+	Authentication      *string
+	RequestBody         *string
+	RequestBodySize     int64
+	RequestContentType  string
+	RemoteIP            string
+	UserID              *UserID
+	Permissions         *string
+	ResponseStatuscode  *int64
+	ResponseBodySize    *int64
+	ResponseBody        *string
+	ResponseContentType string
+	RetryCount          int64
+	Panicked            bool
+	PanicStr            *string
+	ProcessingTime      time.Duration
+	TimestampCreated    time.Time
+	TimestampStart      time.Time
+	TimestampFinish     time.Time
+}
+
+func (c RequestLog) JSON() RequestLogJSON {
+	return RequestLogJSON{
+		RequestID:           c.RequestID,
+		Method:              c.Method,
+		URI:                 c.URI,
+		UserAgent:           c.UserAgent,
+		Authentication:      c.Authentication,
+		RequestBody:         c.RequestBody,
+		RequestBodySize:     c.RequestBodySize,
+		RequestContentType:  c.RequestContentType,
+		RemoteIP:            c.RemoteIP,
+		UserID:              c.UserID,
+		Permissions:         c.Permissions,
+		ResponseStatuscode:  c.ResponseStatuscode,
+		ResponseBodySize:    c.ResponseBodySize,
+		ResponseBody:        c.ResponseBody,
+		ResponseContentType: c.ResponseContentType,
+		RetryCount:          c.RetryCount,
+		Panicked:            c.Panicked,
+		PanicStr:            c.PanicStr,
+		ProcessingTime:      c.ProcessingTime.Seconds(),
+		TimestampCreated:    c.TimestampCreated.Format(time.RFC3339Nano),
+		TimestampStart:      c.TimestampStart.Format(time.RFC3339Nano),
+		TimestampFinish:     c.TimestampFinish.Format(time.RFC3339Nano),
+	}
+}
+
+func (c RequestLog) DB() RequestLogDB {
+	return RequestLogDB{
+		RequestID:           c.RequestID,
+		Method:              c.Method,
+		URI:                 c.URI,
+		UserAgent:           c.UserAgent,
+		Authentication:      c.Authentication,
+		RequestBody:         c.RequestBody,
+		RequestBodySize:     c.RequestBodySize,
+		RequestContentType:  c.RequestContentType,
+		RemoteIP:            c.RemoteIP,
+		UserID:              c.UserID,
+		Permissions:         c.Permissions,
+		ResponseStatuscode:  c.ResponseStatuscode,
+		ResponseBodySize:    c.ResponseBodySize,
+		ResponseBody:        c.ResponseBody,
+		ResponseContentType: c.ResponseContentType,
+		RetryCount:          c.RetryCount,
+		Panicked:            langext.Conditional[int64](c.Panicked, 1, 0),
+		PanicStr:            c.PanicStr,
+		ProcessingTime:      c.ProcessingTime.Milliseconds(),
+		TimestampCreated:    c.TimestampCreated.UnixMilli(),
+		TimestampStart:      c.TimestampStart.UnixMilli(),
+		TimestampFinish:     c.TimestampFinish.UnixMilli(),
+	}
+}
+
+type RequestLogJSON struct {
+	RequestID           RequestID `json:"requestLog_id"`
+	Method              string    `json:"method"`
+	URI                 string    `json:"uri"`
+	UserAgent           *string   `json:"user_agent"`
+	Authentication      *string   `json:"authentication"`
+	RequestBody         *string   `json:"request_body"`
+	RequestBodySize     int64     `json:"request_body_size"`
+	RequestContentType  string    `json:"request_content_type"`
+	RemoteIP            string    `json:"remote_ip"`
+	UserID              *UserID   `json:"userid"`
+	Permissions         *string   `json:"permissions"`
+	ResponseStatuscode  *int64    `json:"response_statuscode"`
+	ResponseBodySize    *int64    `json:"response_body_size"`
+	ResponseBody        *string   `json:"response_body"`
+	ResponseContentType string    `json:"response_content_type"`
+	RetryCount          int64     `json:"retry_count"`
+	Panicked            bool      `json:"panicked"`
+	PanicStr            *string   `json:"panic_str"`
+	ProcessingTime      float64   `json:"processing_time"`
+	TimestampCreated    string    `json:"timestamp_created"`
+	TimestampStart      string    `json:"timestamp_start"`
+	TimestampFinish     string    `json:"timestamp_finish"`
+}
+
+type RequestLogDB struct {
+	RequestID           RequestID `db:"requestLog_id"`
+	Method              string    `db:"method"`
+	URI                 string    `db:"uri"`
+	UserAgent           *string   `db:"user_agent"`
+	Authentication      *string   `db:"authentication"`
+	RequestBody         *string   `db:"request_body"`
+	RequestBodySize     int64     `db:"request_body_size"`
+	RequestContentType  string    `db:"request_content_type"`
+	RemoteIP            string    `db:"remote_ip"`
+	UserID              *UserID   `db:"userid"`
+	Permissions         *string   `db:"permissions"`
+	ResponseStatuscode  *int64    `db:"response_statuscode"`
+	ResponseBodySize    *int64    `db:"response_body_size"`
+	ResponseBody        *string   `db:"response_body"`
+	ResponseContentType string    `db:"request_content_type"`
+	RetryCount          int64     `db:"retry_count"`
+	Panicked            int64     `db:"panicked"`
+	PanicStr            *string   `db:"panic_str"`
+	ProcessingTime      int64     `db:"processing_time"`
+	TimestampCreated    int64     `db:"timestamp_created"`
+	TimestampStart      int64     `db:"timestamp_start"`
+	TimestampFinish     int64     `db:"timestamp_finish"`
+}
+
+func (c RequestLogDB) Model() RequestLog {
+	return RequestLog{
+		RequestID:           c.RequestID,
+		Method:              c.Method,
+		URI:                 c.URI,
+		UserAgent:           c.UserAgent,
+		Authentication:      c.Authentication,
+		RequestBody:         c.RequestBody,
+		RequestBodySize:     c.RequestBodySize,
+		RequestContentType:  c.RequestContentType,
+		RemoteIP:            c.RemoteIP,
+		UserID:              c.UserID,
+		Permissions:         c.Permissions,
+		ResponseStatuscode:  c.ResponseStatuscode,
+		ResponseBodySize:    c.ResponseBodySize,
+		ResponseBody:        c.ResponseBody,
+		ResponseContentType: c.ResponseContentType,
+		RetryCount:          c.RetryCount,
+		Panicked:            c.Panicked != 0,
+		PanicStr:            c.PanicStr,
+		ProcessingTime:      timeext.FromMilliseconds(c.ProcessingTime),
+		TimestampCreated:    time.UnixMilli(c.TimestampCreated),
+		TimestampStart:      time.UnixMilli(c.TimestampStart),
+		TimestampFinish:     time.UnixMilli(c.TimestampFinish),
+	}
+}
+
+func DecodeRequestLog(r *sqlx.Rows) (RequestLog, error) {
+	data, err := sq.ScanSingle[RequestLogDB](r, sq.SModeFast, sq.Safe, true)
+	if err != nil {
+		return RequestLog{}, err
+	}
+	return data.Model(), nil
+}
+
+func DecodeRequestLogs(r *sqlx.Rows) ([]RequestLog, error) {
+	data, err := sq.ScanAll[RequestLogDB](r, sq.SModeFast, sq.Safe, true)
+	if err != nil {
+		return nil, err
+	}
+	return langext.ArrMap(data, func(v RequestLogDB) RequestLog { return v.Model() }), nil
+}

scnserver/test/errorlog_test.go

@@ -0,0 +1,3 @@
+package test
+
+//TODO test errorlog

scnserver/test/message_test.go

@@ -28,7 +28,7 @@ func TestSearchMessageFTSSimple(t *testing.T) {
 }
 
 func TestSearchMessageFTSMulti(t *testing.T) {
-	//TODO search for messages by FTS
+	t.SkipNow() //TODO search for messages by FTS
 }
 
 //TODO more search/list/filter message tests

scnserver/test/requestlog_test.go

@@ -0,0 +1,3 @@
+package test
+
+//TODO test requestlog

scnserver/test/util/webserver.go

@@ -119,8 +119,10 @@ func StartSimpleWebserver(t *testing.T) (*logic.Application, string, func()) {
 
 	apc := google.NewDummy()
 
-	jobRetry := jobs.NewDeliveryRetryJob(app)
+	app.Init(conf, ginengine, nc, apc, []logic.Job{
-	app.Init(conf, ginengine, nc, apc, []logic.Job{jobRetry})
+		jobs.NewDeliveryRetryJob(app),
+		jobs.NewRequestLogCollectorJob(app),
+	})
 
 	router.Init(ginengine)