Improve logging in the phantomjs renderer (#10697)

* Add add adapter between io.Writer and log.Logger

* Add phantomjs output to grafana log

* Unexport LogWriterImpl

* Add test for LogWriter

* Make it possible to get phantomjs debug output

* Make it possible to get the configured log level

pkg/components/renderer/renderer.go

@@ -91,9 +91,15 @@ func RenderToPng(params *RenderOpts) (string, error) {
 		timeout = 15
 	}
 
+	phantomDebugArg := "--debug=false"
+	if log.GetLogLevelFor("png-renderer") >= log.LvlDebug {
+		phantomDebugArg = "--debug=true"
+	}
+
 	cmdArgs := []string{
 		"--ignore-ssl-errors=true",
 		"--web-security=false",
+		phantomDebugArg,
 		scriptPath,
 		"url=" + url,
 		"width=" + params.Width,
@@ -109,15 +115,13 @@ func RenderToPng(params *RenderOpts) (string, error) {
 	}
 
 	cmd := exec.Command(binPath, cmdArgs...)
-	stdout, err := cmd.StdoutPipe()
+	output, err := cmd.StdoutPipe()
 
 	if err != nil {
+		rendererLog.Error("Could not acquire stdout pipe", err)
 		return "", err
 	}
-	stderr, err := cmd.StderrPipe()
+	cmd.Stderr = cmd.Stdout
-	if err != nil {
-		return "", err
-	}
 
 	if params.Timezone != "" {
 		baseEnviron := os.Environ()
@@ -126,11 +130,12 @@ func RenderToPng(params *RenderOpts) (string, error) {
 
 	err = cmd.Start()
 	if err != nil {
+		rendererLog.Error("Could not start command", err)
 		return "", err
 	}
 
-	go io.Copy(os.Stdout, stdout)
+	logWriter := log.NewLogWriter(rendererLog, log.LvlDebug, "[phantom] ")
-	go io.Copy(os.Stdout, stderr)
+	go io.Copy(logWriter, output)
 
 	done := make(chan error)
 	go func() {

pkg/log/log.go

@@ -21,6 +21,7 @@ import (
 
 var Root log15.Logger
 var loggersToClose []DisposableHandler
+var filters map[string]log15.Lvl
 
 func init() {
 	loggersToClose = make([]DisposableHandler, 0)
@@ -114,6 +115,25 @@ func Close() {
 	loggersToClose = make([]DisposableHandler, 0)
 }
 
+func GetLogLevelFor(name string) Lvl {
+	if level, ok := filters[name]; ok {
+		switch level {
+		case log15.LvlWarn:
+			return LvlWarn
+		case log15.LvlInfo:
+			return LvlInfo
+		case log15.LvlError:
+			return LvlError
+		case log15.LvlCrit:
+			return LvlCrit
+		default:
+			return LvlDebug
+		}
+	}
+
+	return LvlInfo
+}
+
 var logLevels = map[string]log15.Lvl{
 	"trace":    log15.LvlDebug,
 	"debug":    log15.LvlDebug,
@@ -187,7 +207,7 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) {
 
 		// Log level.
 		_, level := getLogLevelFromConfig("log."+mode, defaultLevelName, cfg)
-		modeFilters := getFilters(util.SplitString(sec.Key("filters").String()))
+		filters := getFilters(util.SplitString(sec.Key("filters").String()))
 		format := getLogFormat(sec.Key("format").MustString(""))
 
 		var handler log15.Handler
@@ -219,12 +239,12 @@ func ReadLoggingConfig(modes []string, logsPath string, cfg *ini.File) {
 		}
 
 		for key, value := range defaultFilters {
-			if _, exist := modeFilters[key]; !exist {
+			if _, exist := filters[key]; !exist {
-				modeFilters[key] = value
+				filters[key] = value
 			}
 		}
 
-		handler = LogFilterHandler(level, modeFilters, handler)
+		handler = LogFilterHandler(level, filters, handler)
 		handlers = append(handlers, handler)
 	}
 

pkg/log/log_writer.go

@@ -0,0 +1,39 @@
+package log
+
+import (
+	"io"
+	"strings"
+)
+
+type logWriterImpl struct {
+	log    Logger
+	level  Lvl
+	prefix string
+}
+
+func NewLogWriter(log Logger, level Lvl, prefix string) io.Writer {
+	return &logWriterImpl{
+		log:    log,
+		level:  level,
+		prefix: prefix,
+	}
+}
+
+func (l *logWriterImpl) Write(p []byte) (n int, err error) {
+	message := l.prefix + strings.TrimSpace(string(p))
+
+	switch l.level {
+	case LvlCrit:
+		l.log.Crit(message)
+	case LvlError:
+		l.log.Error(message)
+	case LvlWarn:
+		l.log.Warn(message)
+	case LvlInfo:
+		l.log.Info(message)
+	default:
+		l.log.Debug(message)
+	}
+
+	return len(p), nil
+}

pkg/log/log_writer_test.go

@@ -0,0 +1,116 @@
+package log
+
+import (
+	"testing"
+
+	"github.com/inconshreveable/log15"
+	. "github.com/smartystreets/goconvey/convey"
+)
+
+type FakeLogger struct {
+	debug string
+	info  string
+	warn  string
+	err   string
+	crit  string
+}
+
+func (f *FakeLogger) New(ctx ...interface{}) log15.Logger {
+	return nil
+}
+
+func (f *FakeLogger) Debug(msg string, ctx ...interface{}) {
+	f.debug = msg
+}
+
+func (f *FakeLogger) Info(msg string, ctx ...interface{}) {
+	f.info = msg
+}
+
+func (f *FakeLogger) Warn(msg string, ctx ...interface{}) {
+	f.warn = msg
+}
+
+func (f *FakeLogger) Error(msg string, ctx ...interface{}) {
+	f.err = msg
+}
+
+func (f *FakeLogger) Crit(msg string, ctx ...interface{}) {
+	f.crit = msg
+}
+
+func (f *FakeLogger) GetHandler() log15.Handler {
+	return nil
+}
+
+func (f *FakeLogger) SetHandler(l log15.Handler) {}
+
+func TestLogWriter(t *testing.T) {
+	Convey("When writing to a LogWriter", t, func() {
+		Convey("Should write using the correct level [crit]", func() {
+			fake := &FakeLogger{}
+
+			crit := NewLogWriter(fake, LvlCrit, "")
+			n, err := crit.Write([]byte("crit"))
+
+			So(n, ShouldEqual, 4)
+			So(err, ShouldBeNil)
+			So(fake.crit, ShouldEqual, "crit")
+		})
+
+		Convey("Should write using the correct level [error]", func() {
+			fake := &FakeLogger{}
+
+			crit := NewLogWriter(fake, LvlError, "")
+			n, err := crit.Write([]byte("error"))
+
+			So(n, ShouldEqual, 5)
+			So(err, ShouldBeNil)
+			So(fake.err, ShouldEqual, "error")
+		})
+
+		Convey("Should write using the correct level [warn]", func() {
+			fake := &FakeLogger{}
+
+			crit := NewLogWriter(fake, LvlWarn, "")
+			n, err := crit.Write([]byte("warn"))
+
+			So(n, ShouldEqual, 4)
+			So(err, ShouldBeNil)
+			So(fake.warn, ShouldEqual, "warn")
+		})
+
+		Convey("Should write using the correct level [info]", func() {
+			fake := &FakeLogger{}
+
+			crit := NewLogWriter(fake, LvlInfo, "")
+			n, err := crit.Write([]byte("info"))
+
+			So(n, ShouldEqual, 4)
+			So(err, ShouldBeNil)
+			So(fake.info, ShouldEqual, "info")
+		})
+
+		Convey("Should write using the correct level [debug]", func() {
+			fake := &FakeLogger{}
+
+			crit := NewLogWriter(fake, LvlDebug, "")
+			n, err := crit.Write([]byte("debug"))
+
+			So(n, ShouldEqual, 5)
+			So(err, ShouldBeNil)
+			So(fake.debug, ShouldEqual, "debug")
+		})
+
+		Convey("Should prefix the output with the prefix", func() {
+			fake := &FakeLogger{}
+
+			crit := NewLogWriter(fake, LvlDebug, "prefix")
+			n, err := crit.Write([]byte("debug"))
+
+			So(n, ShouldEqual, 5) // n is how much of input consumed
+			So(err, ShouldBeNil)
+			So(fake.debug, ShouldEqual, "prefixdebug")
+		})
+	})
+}