Log errors returned from graphql (#3562)

* Add func methods to logger
* Log errors returned from the graphql interface
* Log authentication
* Log when credentials changed

internal/api/error.go

@@ -0,0 +1,39 @@
+package api
+
+import (
+	"context"
+	"encoding/json"
+
+	"github.com/99designs/gqlgen/graphql"
+	"github.com/stashapp/stash/pkg/logger"
+	"github.com/vektah/gqlparser/v2/gqlerror"
+)
+
+func gqlErrorHandler(ctx context.Context, e error) *gqlerror.Error {
+	// log all errors - for now just log the error message
+	// we can potentially add more context later
+	fc := graphql.GetFieldContext(ctx)
+	if fc != nil {
+		logger.Errorf("%s: %v", fc.Path(), e)
+
+		// log the args in debug level
+		logger.DebugFunc(func() (string, []interface{}) {
+			var args interface{}
+			args = fc.Args
+
+			s, _ := json.Marshal(args)
+			if len(s) > 0 {
+				args = string(s)
+			}
+
+			return "%s: %v", []interface{}{
+				fc.Path(),
+				args,
+			}
+		})
+	}
+
+	// we may also want to transform the error message for the response
+	// for now just return the original error
+	return graphql.DefaultErrorPresenter(ctx, e)
+}

internal/api/resolver_mutation_configure.go

@@ -228,8 +228,13 @@ func (r *mutationResolver) ConfigureGeneral(ctx context.Context, input ConfigGen
 		c.Set(config.GalleryCoverRegex, *input.GalleryCoverRegex)
 	}
 
-	if input.Username != nil {
+	if input.Username != nil && *input.Username != c.GetUsername() {
 		c.Set(config.Username, input.Username)
+		if *input.Password == "" {
+			logger.Info("Username cleared")
+		} else {
+			logger.Info("Username changed")
+		}
 	}
 
 	if input.Password != nil {
@@ -238,6 +243,11 @@ func (r *mutationResolver) ConfigureGeneral(ctx context.Context, input ConfigGen
 		currentPWHash := c.GetPasswordHash()
 
 		if *input.Password != currentPWHash {
+			if *input.Password == "" {
+				logger.Info("Password cleared")
+			} else {
+				logger.Info("Password changed")
+			}
 			c.SetPassword(*input.Password)
 		}
 	}

internal/api/server.go

@@ -120,6 +120,8 @@ func Start() error {
 	gqlSrv.SetQueryCache(gqlLru.New(1000))
 	gqlSrv.Use(gqlExtension.Introspection{})
 
+	gqlSrv.SetErrorPresenter(gqlErrorHandler)
+
 	gqlHandlerFunc := func(w http.ResponseWriter, r *http.Request) {
 		gqlSrv.ServeHTTP(w, r)
 	}

internal/api/session.go

@@ -9,6 +9,7 @@ import (
 
 	"github.com/stashapp/stash/internal/manager"
 	"github.com/stashapp/stash/internal/manager/config"
+	"github.com/stashapp/stash/pkg/logger"
 	"github.com/stashapp/stash/pkg/session"
 )
 
@@ -61,7 +62,14 @@ func handleLogin(loginUIBox embed.FS) http.HandlerFunc {
 		}
 
 		err := manager.GetInstance().SessionStore.Login(w, r)
-		if errors.Is(err, session.ErrInvalidCredentials) {
+		if err != nil {
+			// always log the error
+			logger.Errorf("Error logging in: %v", err)
+		}
+
+		var invalidCredentialsError *session.InvalidCredentialsError
+
+		if errors.As(err, &invalidCredentialsError) {
 			// redirect back to the login page with an error
 			redirectToLogin(loginUIBox, w, url, "Username or password is invalid")
 			return

internal/log/logger.go

@@ -235,6 +235,13 @@ func (log *Logger) Tracef(format string, args ...interface{}) {
 	log.addLogItem(l)
 }
 
+func (log *Logger) TraceFunc(fn func() (string, []interface{})) {
+	if log.logger.Level >= logrus.TraceLevel {
+		msg, args := fn()
+		log.Tracef(msg, args...)
+	}
+}
+
 func (log *Logger) Debug(args ...interface{}) {
 	log.logger.Debug(args...)
 	l := &LogItem{
@@ -253,6 +260,17 @@ func (log *Logger) Debugf(format string, args ...interface{}) {
 	log.addLogItem(l)
 }
 
+func (log *Logger) logFunc(level logrus.Level, logFn func(format string, args ...interface{}), fn func() (string, []interface{})) {
+	if log.logger.Level >= level {
+		msg, args := fn()
+		logFn(msg, args...)
+	}
+}
+
+func (log *Logger) DebugFunc(fn func() (string, []interface{})) {
+	log.logFunc(logrus.DebugLevel, log.logger.Debugf, fn)
+}
+
 func (log *Logger) Info(args ...interface{}) {
 	log.logger.Info(args...)
 	l := &LogItem{
@@ -271,6 +289,10 @@ func (log *Logger) Infof(format string, args ...interface{}) {
 	log.addLogItem(l)
 }
 
+func (log *Logger) InfoFunc(fn func() (string, []interface{})) {
+	log.logFunc(logrus.InfoLevel, log.logger.Infof, fn)
+}
+
 func (log *Logger) Warn(args ...interface{}) {
 	log.logger.Warn(args...)
 	l := &LogItem{
@@ -289,6 +311,10 @@ func (log *Logger) Warnf(format string, args ...interface{}) {
 	log.addLogItem(l)
 }
 
+func (log *Logger) WarnFunc(fn func() (string, []interface{})) {
+	log.logFunc(logrus.WarnLevel, log.logger.Warnf, fn)
+}
+
 func (log *Logger) Error(args ...interface{}) {
 	log.logger.Error(args...)
 	l := &LogItem{
@@ -307,6 +333,10 @@ func (log *Logger) Errorf(format string, args ...interface{}) {
 	log.addLogItem(l)
 }
 
+func (log *Logger) ErrorFunc(fn func() (string, []interface{})) {
+	log.logFunc(logrus.ErrorLevel, log.logger.Errorf, fn)
+}
+
 func (log *Logger) Fatal(args ...interface{}) {
 	log.logger.Fatal(args...)
 }

pkg/logger/basic.go

@@ -31,6 +31,11 @@ func (log *BasicLogger) Tracef(format string, args ...interface{}) {
 	log.printf("Trace", format, args...)
 }
 
+func (log *BasicLogger) TraceFunc(fn func() (string, []interface{})) {
+	format, args := fn()
+	log.printf("Trace", format, args...)
+}
+
 func (log *BasicLogger) Debug(args ...interface{}) {
 	log.print("Debug", args...)
 }
@@ -39,6 +44,11 @@ func (log *BasicLogger) Debugf(format string, args ...interface{}) {
 	log.printf("Debug", format, args...)
 }
 
+func (log *BasicLogger) DebugFunc(fn func() (string, []interface{})) {
+	format, args := fn()
+	log.printf("Debug", format, args...)
+}
+
 func (log *BasicLogger) Info(args ...interface{}) {
 	log.print("Info", args...)
 }
@@ -47,6 +57,11 @@ func (log *BasicLogger) Infof(format string, args ...interface{}) {
 	log.printf("Info", format, args...)
 }
 
+func (log *BasicLogger) InfoFunc(fn func() (string, []interface{})) {
+	format, args := fn()
+	log.printf("Info", format, args...)
+}
+
 func (log *BasicLogger) Warn(args ...interface{}) {
 	log.print("Warn", args...)
 }
@@ -55,6 +70,11 @@ func (log *BasicLogger) Warnf(format string, args ...interface{}) {
 	log.printf("Warn", format, args...)
 }
 
+func (log *BasicLogger) WarnFunc(fn func() (string, []interface{})) {
+	format, args := fn()
+	log.printf("Warn", format, args...)
+}
+
 func (log *BasicLogger) Error(args ...interface{}) {
 	log.print("Error", args...)
 }
@@ -63,6 +83,11 @@ func (log *BasicLogger) Errorf(format string, args ...interface{}) {
 	log.printf("Error", format, args...)
 }
 
+func (log *BasicLogger) ErrorFunc(fn func() (string, []interface{})) {
+	format, args := fn()
+	log.printf("Error", format, args...)
+}
+
 func (log *BasicLogger) Fatal(args ...interface{}) {
 	log.print("Fatal", args...)
 	os.Exit(1)

pkg/logger/logger.go

@@ -16,18 +16,23 @@ type LoggerImpl interface {
 
 	Trace(args ...interface{})
 	Tracef(format string, args ...interface{})
+	TraceFunc(fn func() (string, []interface{}))
 
 	Debug(args ...interface{})
 	Debugf(format string, args ...interface{})
+	DebugFunc(fn func() (string, []interface{}))
 
 	Info(args ...interface{})
 	Infof(format string, args ...interface{})
+	InfoFunc(fn func() (string, []interface{}))
 
 	Warn(args ...interface{})
 	Warnf(format string, args ...interface{})
+	WarnFunc(fn func() (string, []interface{}))
 
 	Error(args ...interface{})
 	Errorf(format string, args ...interface{})
+	ErrorFunc(fn func() (string, []interface{}))
 
 	Fatal(args ...interface{})
 	Fatalf(format string, args ...interface{})
@@ -61,6 +66,14 @@ func Tracef(format string, args ...interface{}) {
 	}
 }
 
+// TraceFunc calls TraceFunc with the Logger registered using RegisterLogger.
+// If no logger has been registered, then this function is a no-op.
+func TraceFunc(fn func() (string, []interface{})) {
+	if Logger != nil {
+		Logger.TraceFunc(fn)
+	}
+}
+
 // Debug calls Debug with the Logger registered using RegisterLogger.
 // If no logger has been registered, then this function is a no-op.
 func Debug(args ...interface{}) {
@@ -77,6 +90,14 @@ func Debugf(format string, args ...interface{}) {
 	}
 }
 
+// DebugFunc calls DebugFunc with the Logger registered using RegisterLogger.
+// If no logger has been registered, then this function is a no-op.
+func DebugFunc(fn func() (string, []interface{})) {
+	if Logger != nil {
+		Logger.DebugFunc(fn)
+	}
+}
+
 // Info calls Info with the Logger registered using RegisterLogger.
 // If no logger has been registered, then this function is a no-op.
 func Info(args ...interface{}) {
@@ -93,6 +114,14 @@ func Infof(format string, args ...interface{}) {
 	}
 }
 
+// InfoFunc calls InfoFunc with the Logger registered using RegisterLogger.
+// If no logger has been registered, then this function is a no-op.
+func InfoFunc(fn func() (string, []interface{})) {
+	if Logger != nil {
+		Logger.InfoFunc(fn)
+	}
+}
+
 // Warn calls Warn with the Logger registered using RegisterLogger.
 // If no logger has been registered, then this function is a no-op.
 func Warn(args ...interface{}) {
@@ -109,6 +138,14 @@ func Warnf(format string, args ...interface{}) {
 	}
 }
 
+// WarnFunc calls WarnFunc with the Logger registered using RegisterLogger.
+// If no logger has been registered, then this function is a no-op.
+func WarnFunc(fn func() (string, []interface{})) {
+	if Logger != nil {
+		Logger.WarnFunc(fn)
+	}
+}
+
 // Error calls Error with the Logger registered using RegisterLogger.
 // If no logger has been registered, then this function is a no-op.
 func Error(args ...interface{}) {
@@ -125,6 +162,14 @@ func Errorf(format string, args ...interface{}) {
 	}
 }
 
+// ErrorFunc calls ErrorFunc with the Logger registered using RegisterLogger.
+// If no logger has been registered, then this function is a no-op.
+func ErrorFunc(fn func() (string, []interface{})) {
+	if Logger != nil {
+		Logger.ErrorFunc(fn)
+	}
+}
+
 // Fatal calls Fatal with the Logger registered using RegisterLogger.
 // If no logger has been registered, then this function is a no-op.
 func Fatal(args ...interface{}) {

pkg/session/session.go

@@ -34,7 +34,15 @@ const (
 	passwordFormKey = "password"
 )
 
-var ErrInvalidCredentials = errors.New("invalid username or password")
+type InvalidCredentialsError struct {
+	Username string
+}
+
+func (e InvalidCredentialsError) Error() string {
+	// don't leak the username
+	return "invalid credentials"
+}
+
 var ErrUnauthorized = errors.New("unauthorized")
 
 type Store struct {
@@ -63,9 +71,12 @@ func (s *Store) Login(w http.ResponseWriter, r *http.Request) error {
 
 	// authenticate the user
 	if !s.config.ValidateCredentials(username, password) {
-		return ErrInvalidCredentials
+		return &InvalidCredentialsError{Username: username}
 	}
 
+	// since we only have one user, don't leak the name
+	logger.Info("User logged in")
+
 	newSession.Values[userIDKey] = username
 
 	err := newSession.Save(r, w)
@@ -90,6 +101,9 @@ func (s *Store) Logout(w http.ResponseWriter, r *http.Request) error {
 		return err
 	}
 
+	// since we only have one user, don't leak the name
+	logger.Infof("User logged out")
+
 	return nil
 }