log: include caller in debug storage logging

includes the location where Set*Key/Delete*Key was called.

config/config-base.json

@@ -395,6 +395,123 @@
                     "type": "password",
                     "value": "",
                     "description": "Leave blank for no Authentication."
+                },
+                "debug_log_emails": {
+                    "name": "Debug Storage Logging: Emails",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_discord": {
+                    "name": "Debug Storage Logging: Discord",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_telegram": {
+                    "name": "Debug Storage Logging: Telegram",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_matrix": {
+                    "name": "Debug Storage Logging: Matrix",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_invites": {
+                    "name": "Debug Storage Logging: Invites",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_announcements": {
+                    "name": "Debug Storage Logging: Announcements",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_expiries": {
+                    "name": "Debug Storage Logging: User Expiries",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_profiles": {
+                    "name": "Debug Storage Logging: Profiles",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
+                },
+                "debug_log_custom_content": {
+                    "name": "Debug Storage Logging: Custom Message Content",
+                    "required": false,
+                    "requires_restart": true,
+                    "type": "select",
+                    "options": [
+                        ["none", "None"],
+                        ["all", "All Writes"],
+                        ["deletion", "Deletion Only*"]
+                    ],
+                    "value": "none",
+                    "description": "Extra debug logging for writes to the database. *: Deletion also includes blanking out major fields, e.g. an email address."
                 }
             }
         },

logger/logger.go

@@ -28,9 +28,10 @@ type Logger struct {
 	fatalFunc func(err interface{})
 }
 
-func Lshortfile() string {
+// Lshortfile is a re-implemented log.Lshortfile with a modifiable call level.
+func Lshortfile(level int) string {
 	// 0 = This function, 1 = Print/Printf/Println, 2 = Caller of Print/Printf/Println
-	_, file, line, ok := runtime.Caller(2)
+	_, file, line, ok := runtime.Caller(level)
 	lineString := strconv.Itoa(line)
 	if !ok {
 		return ""
@@ -47,6 +48,10 @@ func Lshortfile() string {
 	return file + ":" + lineString + ":"
 }
 
+func lshortfile() string {
+	return Lshortfile(2)
+}
+
 func NewLogger(out io.Writer, prefix string, flag int, color c.Attribute) (l *Logger) {
 	l = &Logger{}
 	// Use reimplemented Lshortfile since wrapping the log functions messes them up
@@ -73,7 +78,7 @@ func (l *Logger) Printf(format string, v ...interface{}) {
 	}
 	var out string
 	if l.shortfile {
-		out = Lshortfile()
+		out = lshortfile()
 	}
 	out += " " + l.printer.Sprintf(format, v...)
 	l.logger.Print(out)
@@ -85,7 +90,7 @@ func (l *Logger) Print(v ...interface{}) {
 	}
 	var out string
 	if l.shortfile {
-		out = Lshortfile()
+		out = lshortfile()
 	}
 	out += " " + l.printer.Sprint(v...)
 	l.logger.Print(out)
@@ -97,7 +102,7 @@ func (l *Logger) Println(v ...interface{}) {
 	}
 	var out string
 	if l.shortfile {
-		out = Lshortfile()
+		out = lshortfile()
 	}
 	out += " " + l.printer.Sprintln(v...)
 	l.logger.Print(out)
@@ -109,7 +114,7 @@ func (l *Logger) Fatal(v ...interface{}) {
 	}
 	var out string
 	if l.shortfile {
-		out = Lshortfile()
+		out = lshortfile()
 	}
 	out += " " + l.printer.Sprint(v...)
 	l.logger.Fatal(out)
@@ -121,7 +126,7 @@ func (l *Logger) Fatalf(format string, v ...interface{}) {
 	}
 	var out string
 	if l.shortfile {
-		out = Lshortfile()
+		out = lshortfile()
 	}
 	out += " " + l.printer.Sprintf(format, v...)
 	if l.fatalFunc != nil {

main.go

@@ -246,8 +246,12 @@ func start(asDaemon, firstCall bool) {
 	}
 	if debugMode {
 		app.debug = logger.NewLogger(os.Stdout, "[DEBUG] ", log.Ltime|log.Lshortfile, color.FgYellow)
+		// Bind debug log
+		app.storage.debug = app.debug
+		app.storage.logActions = generateLogActions(app.config)
 	} else {
 		app.debug = logger.NewEmptyLogger()
+		app.storage.debug = nil
 	}
 	if *PPROF {
 		app.info.Print(warning("\n\nWARNING: Don't use pprof in production.\n\n"))

storage.go

@@ -10,8 +10,10 @@ import (
 	"strings"
 	"time"
 
+	"github.com/hrfee/jfa-go/logger"
 	"github.com/hrfee/mediabrowser"
 	"github.com/timshannon/badgerhold/v4"
+	"gopkg.in/ini.v1"
 )
 
 type discordStore map[string]DiscordUser
@@ -24,7 +26,18 @@ type UserExpiry struct {
 	Expiry     time.Time
 }
 
+type DebugLogAction int
+
+const (
+	NoLog DebugLogAction = iota
+	LogAll
+	LogDeletion // Logs deletion, and wiping of main field in new data, e.g. setting email.addr to "".
+)
+
 type Storage struct {
+	debug      *logger.Logger
+	logActions map[string]DebugLogAction
+
 	timePattern string
 
 	db_path string
@@ -47,6 +60,76 @@ type Storage struct {
 	lang                                                                                                                                                                                                                                Lang
 }
 
+type StoreType int
+
+// Used for debug logging of storage.
+const (
+	StoredEmails StoreType = iota
+	StoredDiscord
+	StoredTelegram
+	StoredMatrix
+	StoredInvites
+	StoredAnnouncements
+	StoredExpiries
+	StoredProfiles
+	StoredCustomContent
+)
+
+// DebugWatch logs database writes according on the advanced debugging settings in the Advanced section
+func (st *Storage) DebugWatch(storeType StoreType, key, mainData string) {
+	if st.debug == nil {
+		return
+	}
+	actionKey := ""
+	switch storeType {
+	case StoredEmails:
+		actionKey = "emails"
+	case StoredDiscord:
+		actionKey = "discord"
+	case StoredTelegram:
+		actionKey = "telegram"
+	case StoredMatrix:
+		actionKey = "matrix"
+	case StoredInvites:
+		actionKey = "invites"
+	case StoredAnnouncements:
+		actionKey = "announcements"
+	case StoredExpiries:
+		actionKey = "expiries"
+	case StoredProfiles:
+		actionKey = "profiles"
+	case StoredCustomContent:
+		actionKey = "custom_content"
+	}
+
+	logAction := st.logActions[actionKey]
+	if logAction == NoLog {
+		return
+	}
+	actionString := "WRITE"
+	if mainData == "" {
+		actionString = "DELETE"
+	}
+	if logAction == LogAll || mainData == "" {
+		st.debug.Printf("%s @ %s %s[%s] = \"%s\"\n", actionString, logger.Lshortfile(3), actionKey, key, mainData)
+	}
+}
+
+func generateLogActions(c *ini.File) map[string]DebugLogAction {
+	m := map[string]DebugLogAction{}
+	for _, v := range []string{"emails", "discord", "telegram", "matrix", "invites", "announcements", "expirires", "profiles", "custom_content"} {
+		switch c.Section("advanced").Key("debug_log_" + v).MustString("none") {
+		case "none":
+			m[v] = NoLog
+		case "all":
+			m[v] = LogAll
+		case "deletion":
+			m[v] = LogDeletion
+		}
+	}
+	return m
+}
+
 func (app *appContext) ConnectDB() {
 	opts := badgerhold.DefaultOptions
 	opts.Dir = app.storage.db_path
@@ -83,6 +166,7 @@ func (st *Storage) GetEmailsKey(k string) (EmailAddress, bool) {
 
 // SetEmailsKey stores value v in key k.
 func (st *Storage) SetEmailsKey(k string, v EmailAddress) {
+	st.DebugWatch(StoredEmails, k, v.Addr)
 	v.JellyfinID = k
 	err := st.db.Upsert(k, v)
 	if err != nil {
@@ -92,6 +176,7 @@ func (st *Storage) SetEmailsKey(k string, v EmailAddress) {
 
 // DeleteEmailKey deletes value at key k.
 func (st *Storage) DeleteEmailsKey(k string) {
+	st.DebugWatch(StoredEmails, k, "")
 	st.db.Delete(k, EmailAddress{})
 }
 
@@ -119,6 +204,7 @@ func (st *Storage) GetDiscordKey(k string) (DiscordUser, bool) {
 
 // SetDiscordKey stores value v in key k.
 func (st *Storage) SetDiscordKey(k string, v DiscordUser) {
+	st.DebugWatch(StoredDiscord, k, v.Username)
 	v.JellyfinID = k
 	err := st.db.Upsert(k, v)
 	if err != nil {
@@ -128,6 +214,7 @@ func (st *Storage) SetDiscordKey(k string, v DiscordUser) {
 
 // DeleteDiscordKey deletes value at key k.
 func (st *Storage) DeleteDiscordKey(k string) {
+	st.DebugWatch(StoredDiscord, k, "")
 	st.db.Delete(k, DiscordUser{})
 }
 
@@ -155,6 +242,7 @@ func (st *Storage) GetTelegramKey(k string) (TelegramUser, bool) {
 
 // SetTelegramKey stores value v in key k.
 func (st *Storage) SetTelegramKey(k string, v TelegramUser) {
+	st.DebugWatch(StoredTelegram, k, v.Username)
 	v.JellyfinID = k
 	err := st.db.Upsert(k, v)
 	if err != nil {
@@ -164,6 +252,7 @@ func (st *Storage) SetTelegramKey(k string, v TelegramUser) {
 
 // DeleteTelegramKey deletes value at key k.
 func (st *Storage) DeleteTelegramKey(k string) {
+	st.DebugWatch(StoredTelegram, k, "")
 	st.db.Delete(k, TelegramUser{})
 }
 
@@ -191,6 +280,7 @@ func (st *Storage) GetMatrixKey(k string) (MatrixUser, bool) {
 
 // SetMatrixKey stores value v in key k.
 func (st *Storage) SetMatrixKey(k string, v MatrixUser) {
+	st.DebugWatch(StoredMatrix, k, v.UserID)
 	v.JellyfinID = k
 	err := st.db.Upsert(k, v)
 	if err != nil {
@@ -200,6 +290,7 @@ func (st *Storage) SetMatrixKey(k string, v MatrixUser) {
 
 // DeleteMatrixKey deletes value at key k.
 func (st *Storage) DeleteMatrixKey(k string) {
+	st.DebugWatch(StoredMatrix, k, "")
 	st.db.Delete(k, MatrixUser{})
 }
 
@@ -227,6 +318,7 @@ func (st *Storage) GetInvitesKey(k string) (Invite, bool) {
 
 // SetInvitesKey stores value v in key k.
 func (st *Storage) SetInvitesKey(k string, v Invite) {
+	st.DebugWatch(StoredInvites, k, "changed") // Not sure what the main data from this would be
 	v.Code = k
 	err := st.db.Upsert(k, v)
 	if err != nil {
@@ -236,6 +328,7 @@ func (st *Storage) SetInvitesKey(k string, v Invite) {
 
 // DeleteInvitesKey deletes value at key k.
 func (st *Storage) DeleteInvitesKey(k string) {
+	st.DebugWatch(StoredInvites, k, "")
 	st.db.Delete(k, Invite{})
 }
 
@@ -263,6 +356,7 @@ func (st *Storage) GetAnnouncementsKey(k string) (announcementTemplate, bool) {
 
 // SetAnnouncementsKey stores value v in key k.
 func (st *Storage) SetAnnouncementsKey(k string, v announcementTemplate) {
+	st.DebugWatch(StoredAnnouncements, k, v.Subject)
 	err := st.db.Upsert(k, v)
 	if err != nil {
 		// fmt.Printf("Failed to set announcement: %v\n", err)
@@ -271,6 +365,7 @@ func (st *Storage) SetAnnouncementsKey(k string, v announcementTemplate) {
 
 // DeleteAnnouncementsKey deletes value at key k.
 func (st *Storage) DeleteAnnouncementsKey(k string) {
+	st.DebugWatch(StoredAnnouncements, k, "")
 	st.db.Delete(k, announcementTemplate{})
 }
 
@@ -298,6 +393,7 @@ func (st *Storage) GetUserExpiryKey(k string) (UserExpiry, bool) {
 
 // SetUserExpiryKey stores value v in key k.
 func (st *Storage) SetUserExpiryKey(k string, v UserExpiry) {
+	st.DebugWatch(StoredExpiries, k, v.Expiry.String())
 	v.JellyfinID = k
 	err := st.db.Upsert(k, v)
 	if err != nil {
@@ -307,6 +403,7 @@ func (st *Storage) SetUserExpiryKey(k string, v UserExpiry) {
 
 // DeleteUserExpiryKey deletes value at key k.
 func (st *Storage) DeleteUserExpiryKey(k string) {
+	st.DebugWatch(StoredExpiries, k, "")
 	st.db.Delete(k, UserExpiry{})
 }
 
@@ -337,6 +434,7 @@ func (st *Storage) GetProfileKey(k string) (Profile, bool) {
 
 // SetProfileKey stores value v in key k.
 func (st *Storage) SetProfileKey(k string, v Profile) {
+	st.DebugWatch(StoredProfiles, k, "changed")
 	v.Name = k
 	v.Admin = v.Policy.IsAdministrator
 	if v.Policy.EnabledFolders != nil {
@@ -357,6 +455,7 @@ func (st *Storage) SetProfileKey(k string, v Profile) {
 
 // DeleteProfileKey deletes value at key k.
 func (st *Storage) DeleteProfileKey(k string) {
+	st.DebugWatch(StoredProfiles, k, "")
 	st.db.Delete(k, Profile{})
 }
 
@@ -401,6 +500,7 @@ func (st *Storage) MustGetCustomContentKey(k string) CustomContent {
 
 // SetCustomContentKey stores value v in key k.
 func (st *Storage) SetCustomContentKey(k string, v CustomContent) {
+	st.DebugWatch(StoredCustomContent, k, "changed")
 	v.Name = k
 	err := st.db.Upsert(k, v)
 	if err != nil {
@@ -410,6 +510,7 @@ func (st *Storage) SetCustomContentKey(k string, v CustomContent) {
 
 // DeleteCustomContentKey deletes value at key k.
 func (st *Storage) DeleteCustomContentKey(k string) {
+	st.DebugWatch(StoredCustomContent, k, "")
 	st.db.Delete(k, CustomContent{})
 }