From b83ce29ac41fce290ac543f9f41436214537a78e Mon Sep 17 00:00:00 2001
From: gitgiggety <79809426+gitgiggety@users.noreply.github.com>
Date: Sun, 19 Sep 2021 02:06:34 +0200
Subject: [PATCH] Scraper log improvements (#1741)

* Fix logs from scraper and plugins not being shown in UI

Using `logger.` in the logger package to write logs is "incorrect". This
as the package contains a variable named `logger` which contains the
logrus instance. So instead of the log line being handled by the custom
log implementation / wrapper which makes sure the lines are shown in the
UI as well, it's written to logrus directly meaning the wrapper is
skipped.

This "issue" is obviously triggered because in any other place
`logger.X` can be used and it will used the custom logger package /
wrapper which works fine.

* Add plugin / scraper name to logging output

Indicate which plugin / scraper wrote a log message by including its
name to the `[Scrape]` prefix.

* Add missing addLogItem call
---
 pkg/logger/logger.go  |  5 +++++
 pkg/logger/plugin.go  | 12 ++++++------
 pkg/plugin/log.go     |  7 ++++---
 pkg/plugin/raw.go     |  2 +-
 pkg/plugin/rpc.go     |  2 +-
 pkg/scraper/script.go |  9 +++++----
 6 files changed, 22 insertions(+), 15 deletions(-)

diff --git a/pkg/logger/logger.go b/pkg/logger/logger.go
index fde7e09c2..0e2a3db0b 100644
--- a/pkg/logger/logger.go
+++ b/pkg/logger/logger.go
@@ -182,6 +182,11 @@ func Progressf(format string, args ...interface{}) {
 
 func Trace(args ...interface{}) {
 	logger.Trace(args...)
+	l := &LogItem{
+		Type:    "trace",
+		Message: fmt.Sprint(args...),
+	}
+	addLogItem(l)
 }
 
 func Tracef(format string, args ...interface{}) {
diff --git a/pkg/logger/plugin.go b/pkg/logger/plugin.go
index 9882ebf72..b2e266ea9 100644
--- a/pkg/logger/plugin.go
+++ b/pkg/logger/plugin.go
@@ -146,19 +146,19 @@ func (log *PluginLogger) HandleStderrLine(line string) {
 
 	switch *level {
 	case TraceLevel:
-		logger.Trace(log.Prefix, ll)
+		Trace(log.Prefix, ll)
 	case DebugLevel:
-		logger.Debug(log.Prefix, ll)
+		Debug(log.Prefix, ll)
 	case InfoLevel:
-		logger.Info(log.Prefix, ll)
+		Info(log.Prefix, ll)
 	case WarningLevel:
-		logger.Warn(log.Prefix, ll)
+		Warn(log.Prefix, ll)
 	case ErrorLevel:
-		logger.Error(log.Prefix, ll)
+		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())
+			Errorf("Error parsing progress value '%s': %s", ll, err.Error())
 		} else {
 			// only pass progress through if channel present
 			if log.ProgressChan != nil {
diff --git a/pkg/plugin/log.go b/pkg/plugin/log.go
index 3eadb9a5b..0b8511521 100644
--- a/pkg/plugin/log.go
+++ b/pkg/plugin/log.go
@@ -1,22 +1,23 @@
 package plugin
 
 import (
+	"fmt"
 	"io"
 
 	"github.com/stashapp/stash/pkg/logger"
 )
 
-func (t *pluginTask) handlePluginStderr(pluginOutputReader io.ReadCloser) {
+func (t *pluginTask) handlePluginStderr(name string, pluginOutputReader io.ReadCloser) {
 	logLevel := logger.PluginLogLevelFromName(t.plugin.PluginErrLogLevel)
 	if logLevel == nil {
 		// default log level to error
 		logLevel = &logger.ErrorLevel
 	}
 
-	const pluginPrefix = "[Plugin] "
+	const pluginPrefix = "[Plugin / %s] "
 
 	lgr := logger.PluginLogger{
-		Prefix:          pluginPrefix,
+		Prefix:          fmt.Sprintf(pluginPrefix, name),
 		DefaultLogLevel: logLevel,
 		ProgressChan:    t.progress,
 	}
diff --git a/pkg/plugin/raw.go b/pkg/plugin/raw.go
index 3ebe29600..5d5ce417c 100644
--- a/pkg/plugin/raw.go
+++ b/pkg/plugin/raw.go
@@ -70,7 +70,7 @@ func (t *rawPluginTask) Start() error {
 		return fmt.Errorf("error running plugin: %s", err.Error())
 	}
 
-	go t.handlePluginStderr(stderr)
+	go t.handlePluginStderr(t.plugin.Name, stderr)
 	t.cmd = cmd
 
 	// send the stdout to the plugin output
diff --git a/pkg/plugin/rpc.go b/pkg/plugin/rpc.go
index dff9774c0..49955a55b 100644
--- a/pkg/plugin/rpc.go
+++ b/pkg/plugin/rpc.go
@@ -64,7 +64,7 @@ func (t *rpcPluginTask) Start() error {
 		return err
 	}
 
-	go t.handlePluginStderr(pluginErrReader)
+	go t.handlePluginStderr(t.plugin.Name, pluginErrReader)
 
 	iface := rpcPluginClient{
 		Client: t.client,
diff --git a/pkg/scraper/script.go b/pkg/scraper/script.go
index e8fee8cfc..ad86517aa 100644
--- a/pkg/scraper/script.go
+++ b/pkg/scraper/script.go
@@ -3,6 +3,7 @@ package scraper
 import (
 	"encoding/json"
 	"errors"
+	"fmt"
 	"io"
 	"os/exec"
 	"path/filepath"
@@ -65,7 +66,7 @@ func (s *scriptScraper) runScraperScript(inString string, out interface{}) error
 		return errors.New("error running scraper script")
 	}
 
-	go handleScraperStderr(stderr)
+	go handleScraperStderr(s.config.Name, stderr)
 
 	logger.Debugf("Scraper script <%s> started", strings.Join(cmd.Args, " "))
 
@@ -248,11 +249,11 @@ func findPythonExecutable() (string, error) {
 	return "python3", nil
 }
 
-func handleScraperStderr(scraperOutputReader io.ReadCloser) {
-	const scraperPrefix = "[Scrape] "
+func handleScraperStderr(name string, scraperOutputReader io.ReadCloser) {
+	const scraperPrefix = "[Scrape / %s] "
 
 	lgr := logger.PluginLogger{
-		Prefix:          scraperPrefix,
+		Prefix:          fmt.Sprintf(scraperPrefix, name),
 		DefaultLogLevel: &logger.ErrorLevel,
 	}
 	lgr.HandlePluginStdErr(scraperOutputReader)