Support scraper logging to specific log levels (#1648)

* init scrapper log levels
* Refactor plugin logging

Co-authored-by: WithoutPants <53250216+WithoutPants@users.noreply.github.com>

pkg/logger/plugin.go

@@ -0,0 +1,191 @@
+package logger
+
+import (
+	"bufio"
+	"fmt"
+	"io"
+	"os"
+	"strconv"
+	"strings"
+)
+
+type PluginLogLevel struct {
+	char byte
+	Name string
+}
+
+// Valid Level values.
+var (
+	TraceLevel = PluginLogLevel{
+		char: 't',
+		Name: "trace",
+	}
+	DebugLevel = PluginLogLevel{
+		char: 'd',
+		Name: "debug",
+	}
+	InfoLevel = PluginLogLevel{
+		char: 'i',
+		Name: "info",
+	}
+	WarningLevel = PluginLogLevel{
+		char: 'w',
+		Name: "warning",
+	}
+	ErrorLevel = PluginLogLevel{
+		char: 'e',
+		Name: "error",
+	}
+	ProgressLevel = PluginLogLevel{
+		char: 'p',
+		Name: "progress",
+	}
+	NoneLevel = PluginLogLevel{
+		Name: "none",
+	}
+)
+
+var validLevels = []PluginLogLevel{
+	TraceLevel,
+	DebugLevel,
+	InfoLevel,
+	WarningLevel,
+	ErrorLevel,
+	ProgressLevel,
+	NoneLevel,
+}
+
+const startLevelChar byte = 1
+const endLevelChar byte = 2
+
+func (l PluginLogLevel) prefix() string {
+	return string([]byte{
+		startLevelChar,
+		byte(l.char),
+		endLevelChar,
+	})
+}
+
+func (l PluginLogLevel) Log(args ...interface{}) {
+	if l.char == 0 {
+		return
+	}
+
+	argsToUse := []interface{}{
+		l.prefix(),
+	}
+	argsToUse = append(argsToUse, args...)
+	fmt.Fprintln(os.Stderr, argsToUse...)
+}
+
+func (l PluginLogLevel) Logf(format string, args ...interface{}) {
+	if l.char == 0 {
+		return
+	}
+
+	formatToUse := string(l.prefix()) + format + "\n"
+	fmt.Fprintf(os.Stderr, formatToUse, args...)
+}
+
+// PluginLogLevelFromName returns the Level that matches the provided name or nil if
+// the name does not match a valid value.
+func PluginLogLevelFromName(name string) *PluginLogLevel {
+	for _, l := range validLevels {
+		if l.Name == name {
+			return &l
+		}
+	}
+
+	return nil
+}
+
+// DetectLogLevel returns the Level and the logging string for a provided line
+// of plugin output. It parses the string for logging control characters and
+// determines the log level, if present. If not present, the plugin output
+// is returned unchanged with a nil Level.
+func DetectLogLevel(line string) (*PluginLogLevel, string) {
+	if len(line) < 4 || line[0] != startLevelChar || line[2] != endLevelChar {
+		return nil, line
+	}
+
+	char := line[1]
+	var level *PluginLogLevel
+	for _, l := range validLevels {
+		if l.char == char {
+			level = &l
+			break
+		}
+	}
+
+	if level == nil {
+		return nil, line
+	}
+
+	line = strings.TrimSpace(line[3:])
+
+	return level, line
+}
+
+type PluginLogger struct {
+	Prefix          string
+	DefaultLogLevel *PluginLogLevel
+	ProgressChan    chan float64
+}
+
+func (log *PluginLogger) HandleStderrLine(line string) {
+	level, ll := DetectLogLevel(line)
+
+	// if no log level, just output to info
+	if level == nil {
+		if log.DefaultLogLevel != nil {
+			level = log.DefaultLogLevel
+		} else {
+			level = &InfoLevel
+		}
+	}
+
+	switch *level {
+	case TraceLevel:
+		logger.Trace(log.Prefix, ll)
+	case DebugLevel:
+		logger.Debug(log.Prefix, ll)
+	case InfoLevel:
+		logger.Info(log.Prefix, ll)
+	case WarningLevel:
+		logger.Warn(log.Prefix, ll)
+	case ErrorLevel:
+		logger.Error(log.Prefix, ll)
+	case ProgressLevel:
+		p, err := strconv.ParseFloat(ll, 64)
+		if err != nil {
+			logger.Errorf("Error parsing progress value '%s': %s", ll, err.Error())
+		} else {
+			// only pass progress through if channel present
+			if log.ProgressChan != nil {
+				// don't block on this
+				select {
+				case log.ProgressChan <- p:
+				default:
+				}
+			}
+		}
+	}
+}
+
+func (log *PluginLogger) HandlePluginStdErr(pluginStdErr io.ReadCloser) {
+	// pipe plugin stderr to our logging
+	scanner := bufio.NewScanner(pluginStdErr)
+	for scanner.Scan() {
+		str := scanner.Text()
+		if str != "" {
+			log.HandleStderrLine(str)
+		}
+	}
+
+	str := scanner.Text()
+	if str != "" {
+		log.HandleStderrLine(str)
+	}
+
+	pluginStdErr.Close()
+}

pkg/plugin/common/log/log.go

@@ -16,144 +16,94 @@
 package log
 
 import (
-	"fmt"
 	"math"
-	"os"
-	"strings"
+
+	"github.com/stashapp/stash/pkg/logger"
 )
 
 // Level represents a logging level for plugin outputs.
 type Level struct {
-	char byte
-	Name string
+	*logger.PluginLogLevel
 }
 
 // Valid Level values.
 var (
 	TraceLevel = Level{
-		char: 't',
-		Name: "trace",
+		&logger.TraceLevel,
 	}
 	DebugLevel = Level{
-		char: 'd',
-		Name: "debug",
+		&logger.DebugLevel,
 	}
 	InfoLevel = Level{
-		char: 'i',
-		Name: "info",
+		&logger.InfoLevel,
 	}
 	WarningLevel = Level{
-		char: 'w',
-		Name: "warning",
+		&logger.WarningLevel,
 	}
 	ErrorLevel = Level{
-		char: 'e',
-		Name: "error",
+		&logger.ErrorLevel,
 	}
 	ProgressLevel = Level{
-		char: 'p',
-		Name: "progress",
+		&logger.ProgressLevel,
 	}
 	NoneLevel = Level{
-		Name: "none",
+		&logger.NoneLevel,
 	}
 )
 
-var validLevels = []Level{
-	TraceLevel,
-	DebugLevel,
-	InfoLevel,
-	WarningLevel,
-	ErrorLevel,
-	ProgressLevel,
-	NoneLevel,
-}
-
-const startLevelChar byte = 1
-const endLevelChar byte = 2
-
-func (l Level) prefix() string {
-	return string([]byte{
-		startLevelChar,
-		byte(l.char),
-		endLevelChar,
-	})
-}
-
-func (l Level) log(args ...interface{}) {
-	if l.char == 0 {
-		return
-	}
-
-	argsToUse := []interface{}{
-		l.prefix(),
-	}
-	argsToUse = append(argsToUse, args...)
-	fmt.Fprintln(os.Stderr, argsToUse...)
-}
-
-func (l Level) logf(format string, args ...interface{}) {
-	if l.char == 0 {
-		return
-	}
-
-	formatToUse := string(l.prefix()) + format + "\n"
-	fmt.Fprintf(os.Stderr, formatToUse, args...)
-}
-
 // Trace outputs a trace logging message to os.Stderr. Message is encoded with a
 // prefix that signifies to the server that it is a trace message.
 func Trace(args ...interface{}) {
-	TraceLevel.log(args...)
+	TraceLevel.Log(args...)
 }
 
 // Tracef is the equivalent of Printf outputting as a trace logging message.
 func Tracef(format string, args ...interface{}) {
-	TraceLevel.logf(format, args...)
+	TraceLevel.Logf(format, args...)
 }
 
 // Debug outputs a debug logging message to os.Stderr. Message is encoded with a
 // prefix that signifies to the server that it is a debug message.
 func Debug(args ...interface{}) {
-	DebugLevel.log(args...)
+	DebugLevel.Log(args...)
 }
 
 // Debugf is the equivalent of Printf outputting as a debug logging message.
 func Debugf(format string, args ...interface{}) {
-	DebugLevel.logf(format, args...)
+	DebugLevel.Logf(format, args...)
 }
 
 // Info outputs an info logging message to os.Stderr. Message is encoded with a
 // prefix that signifies to the server that it is an info message.
 func Info(args ...interface{}) {
-	InfoLevel.log(args...)
+	InfoLevel.Log(args...)
 }
 
 // Infof is the equivalent of Printf outputting as an info logging message.
 func Infof(format string, args ...interface{}) {
-	InfoLevel.logf(format, args...)
+	InfoLevel.Logf(format, args...)
 }
 
 // Warn outputs a warning logging message to os.Stderr. Message is encoded with a
 // prefix that signifies to the server that it is a warning message.
 func Warn(args ...interface{}) {
-	WarningLevel.log(args...)
+	WarningLevel.Log(args...)
 }
 
 // Warnf is the equivalent of Printf outputting as a warning logging message.
 func Warnf(format string, args ...interface{}) {
-	WarningLevel.logf(format, args...)
+	WarningLevel.Logf(format, args...)
 }
 
 // Error outputs an error logging message to os.Stderr. Message is encoded with a
 // prefix that signifies to the server that it is an error message.
 func Error(args ...interface{}) {
-	ErrorLevel.log(args...)
+	ErrorLevel.Log(args...)
 }
 
 // Errorf is the equivalent of Printf outputting as an error logging message.
 func Errorf(format string, args ...interface{}) {
-	ErrorLevel.logf(format, args...)
+	ErrorLevel.Logf(format, args...)
 }
 
 // Progress logs the current progress value. The progress value should be
@@ -161,15 +111,16 @@ func Errorf(format string, args ...interface{}) {
 // complete. Values outside of this range will be clamp to be within it.
 func Progress(progress float64) {
 	progress = math.Min(math.Max(0, progress), 1)
-	ProgressLevel.log(progress)
+	ProgressLevel.Log(progress)
 }
 
 // LevelFromName returns the Level that matches the provided name or nil if
 // the name does not match a valid value.
 func LevelFromName(name string) *Level {
-	for _, l := range validLevels {
-		if l.Name == name {
-			return &l
+	l := logger.PluginLogLevelFromName(name)
+	if l != nil {
+		return &Level{
+			l,
 		}
 	}
 
@@ -181,24 +132,14 @@ func LevelFromName(name string) *Level {
 // determines the log level, if present. If not present, the plugin output
 // is returned unchanged with a nil Level.
 func DetectLogLevel(line string) (*Level, string) {
-	if len(line) < 4 || line[0] != startLevelChar || line[2] != endLevelChar {
-		return nil, line
-	}
-
-	char := line[1]
-	var level *Level
-	for _, l := range validLevels {
-		if l.char == char {
-			level = &l
-			break
-		}
-	}
+	var level *logger.PluginLogLevel
+	level, line = logger.DetectLogLevel(line)
 
 	if level == nil {
 		return nil, line
 	}
 
-	line = strings.TrimSpace(line[3:])
-
-	return level, line
+	return &Level{
+		level,
+	}, line
 }

pkg/plugin/log.go

@@ -1,79 +1,25 @@
 package plugin
 
 import (
-	"bufio"
 	"io"
-	"strconv"
 
 	"github.com/stashapp/stash/pkg/logger"
-	"github.com/stashapp/stash/pkg/plugin/common/log"
 )
 
-func (t *pluginTask) handleStderrLine(line string, defaultLogLevel *log.Level) {
-	level, l := log.DetectLogLevel(line)
-
-	const pluginPrefix = "[Plugin] "
-	// if no log level, just output to info
-	if level == nil {
-		if defaultLogLevel != nil {
-			level = defaultLogLevel
-		} else {
-			level = &log.InfoLevel
-		}
-	}
-
-	switch *level {
-	case log.TraceLevel:
-		logger.Trace(pluginPrefix, l)
-	case log.DebugLevel:
-		logger.Debug(pluginPrefix, l)
-	case log.InfoLevel:
-		logger.Info(pluginPrefix, l)
-	case log.WarningLevel:
-		logger.Warn(pluginPrefix, l)
-	case log.ErrorLevel:
-		logger.Error(pluginPrefix, l)
-	case log.ProgressLevel:
-		progress, err := strconv.ParseFloat(l, 64)
-		if err != nil {
-			logger.Errorf("Error parsing progress value '%s': %s", l, err.Error())
-		} else {
-			// only pass progress through if channel present
-			if t.progress != nil {
-				// don't block on this
-				select {
-				case t.progress <- progress:
-				default:
-				}
-			}
-		}
-	}
-}
-
-func (t *pluginTask) handlePluginOutput(pluginOutputReader io.ReadCloser, defaultLogLevel *log.Level) {
-	// pipe plugin stderr to our logging
-	scanner := bufio.NewScanner(pluginOutputReader)
-	for scanner.Scan() {
-		str := scanner.Text()
-		if str != "" {
-			t.handleStderrLine(str, defaultLogLevel)
-		}
-	}
-
-	str := scanner.Text()
-	if str != "" {
-		t.handleStderrLine(str, defaultLogLevel)
-	}
-
-	pluginOutputReader.Close()
-}
-
 func (t *pluginTask) handlePluginStderr(pluginOutputReader io.ReadCloser) {
-	logLevel := log.LevelFromName(t.plugin.PluginErrLogLevel)
+	logLevel := logger.PluginLogLevelFromName(t.plugin.PluginErrLogLevel)
 	if logLevel == nil {
 		// default log level to error
-		logLevel = &log.ErrorLevel
+		logLevel = &logger.ErrorLevel
 	}
 
-	t.handlePluginOutput(pluginOutputReader, logLevel)
+	const pluginPrefix = "[Plugin] "
+
+	lgr := logger.PluginLogger{
+		Prefix:          pluginPrefix,
+		DefaultLogLevel: logLevel,
+		ProgressChan:    t.progress,
+	}
+
+	lgr.HandlePluginStdErr(pluginOutputReader)
 }

pkg/scraper/script.go

@@ -1,7 +1,6 @@
 package scraper
 
 import (
-	"bufio"
 	"encoding/json"
 	"errors"
 	"io"
@@ -66,12 +65,7 @@ func (s *scriptScraper) runScraperScript(inString string, out interface{}) error
 		return errors.New("error running scraper script")
 	}
 
-	scanner := bufio.NewScanner(stderr)
-	go func() { // log errors from stderr pipe
-		for scanner.Scan() {
-			logger.Errorf("scraper: %s", scanner.Text())
-		}
-	}()
+	go handleScraperStderr(stderr)
 
 	logger.Debugf("Scraper script <%s> started", strings.Join(cmd.Args, " "))
 
@@ -253,3 +247,13 @@ func findPythonExecutable() (string, error) {
 
 	return "python3", nil
 }
+
+func handleScraperStderr(scraperOutputReader io.ReadCloser) {
+	const scraperPrefix = "[Scrape] "
+
+	lgr := logger.PluginLogger{
+		Prefix:          scraperPrefix,
+		DefaultLogLevel: &logger.ErrorLevel,
+	}
+	lgr.HandlePluginStdErr(scraperOutputReader)
+}

ui/v2.5/src/components/Changelog/versions/v0100.md

@@ -10,6 +10,7 @@
 * Support filtering Movies by Performers. ([#1675](https://github.com/stashapp/stash/pull/1675))
 
 ### 🎨 Improvements
+* Support scraper script logging to specific log levels. ([#1648](https://github.com/stashapp/stash/pull/1648))
 * Added sv-SE language option. ([#1691](https://github.com/stashapp/stash/pull/1691))
 
 ### 🐛 Bug fixes