Repository: flant/shell-operator
Pull request #125 (2020-02-19 15:09:59)

fix: errors from klog was also written to stderr
- add test of sdterr output


Patch:
diff --git a/pkg/utils/klogtologrus/adapter.go b/pkg/utils/klogtologrus/adapter.go
index 98b5c9d..1d98511 100644
--- a/pkg/utils/klogtologrus/adapter.go
+++ b/pkg/utils/klogtologrus/adapter.go
@@ -15,10 +15,12 @@ import (
 //     _ "github.com/flant/shell-operator/pkg/utils/klogtologrus"
 //   )
 func init() {
-	// turn off logging to stderr and set Info writer to catch all messages.
+	// - turn off logging to stderr
+	// - default stderr threshold is ERROR and it outputs errors to stderr, set it to FATAL
+	// - set writer for INFO severity to catch all messages
 	klogFlagSet := flag.NewFlagSet("klog", flag.ContinueOnError)
 	klog.InitFlags(klogFlagSet)
-	_ = klogFlagSet.Parse([]string{"-logtostderr=false"})
+	_ = klogFlagSet.Parse([]string{"-logtostderr=false", "-stderrthreshold=FATAL"})
 	klog.SetOutputBySeverity("INFO", &klogToLogrusWriter{})
 }
 


Test patch:
diff --git a/pkg/utils/klogtologrus/adapter_test.go b/pkg/utils/klogtologrus/adapter_test.go
deleted file mode 100644
index 87c85d2..0000000
--- a/pkg/utils/klogtologrus/adapter_test.go
+++ /dev/null
@@ -1,32 +0,0 @@
-package klogtologrus
-
-import (
-	"encoding/json"
-	"testing"
-
-	. "github.com/onsi/gomega"
-	"github.com/onsi/gomega/gbytes"
-
-	log "github.com/sirupsen/logrus"
-	"k8s.io/klog"
-)
-
-func Test_basic(t *testing.T) {
-	g := NewWithT(t)
-
-	buf := gbytes.NewBuffer()
-
-	log.SetOutput(buf)
-	log.SetFormatter(&log.JSONFormatter{DisableTimestamp: true})
-
-	klog.Warning("test warning")
-
-	var record map[string]string
-	err := json.Unmarshal(buf.Contents(), &record)
-	g.Expect(err).ShouldNot(HaveOccurred(), string(buf.Contents()))
-
-	g.Expect(record).Should(HaveKey("level"))
-	g.Expect(record["level"]).Should(Equal("warning"))
-	g.Expect(record).Should(HaveKey("msg"))
-	g.Expect(record["msg"]).Should(ContainSubstring("test warning"))
-}
diff --git a/pkg/utils/klogtologrus/test/adapter_test.go b/pkg/utils/klogtologrus/test/adapter_test.go
new file mode 100644
index 0000000..47ef0d1
--- /dev/null
+++ b/pkg/utils/klogtologrus/test/adapter_test.go
@@ -0,0 +1,116 @@
+package test
+
+import (
+	"bufio"
+	"bytes"
+	"encoding/json"
+	"io"
+	"io/ioutil"
+	"os"
+	"sync"
+	"testing"
+
+	log "github.com/sirupsen/logrus"
+
+	"github.com/flant/shell-operator/pkg/utils/klogtologrus/test/service"
+	. "github.com/onsi/gomega"
+	"github.com/onsi/gomega/gbytes"
+)
+
+// Test that adapter is working through default import in another package
+func Test_adapter_catches_klog_WarnInfoError(t *testing.T) {
+	g := NewWithT(t)
+
+	buf := gbytes.NewBuffer()
+
+	log.SetOutput(buf)
+	log.SetFormatter(&log.JSONFormatter{DisableTimestamp: true})
+
+	tests := []struct {
+		level string
+		msg   string
+	}{
+		{
+			"warning",
+			"Warning from klog powered lib",
+		},
+		{
+			"info",
+			"Info from klog powered lib",
+		},
+		{
+			"error",
+			"Error from klog powered lib",
+		},
+	}
+
+	service.DoWithCallToKlogPoweredLib()
+
+	// Catch log lines
+	lines := []string{}
+	scanner := bufio.NewScanner(buf)
+	for scanner.Scan() {
+		lines = append(lines, scanner.Text())
+	}
+
+	g.Expect(lines).To(HaveLen(len(tests)))
+
+	for i, line := range lines {
+		tt := tests[i]
+
+		var record map[string]string
+		err := json.Unmarshal([]byte(line), &record)
+		g.Expect(err).ShouldNot(HaveOccurred(), line, "log line should be a valid JSON")
+
+		g.Expect(record).Should(HaveKey("level"))
+		g.Expect(record["level"]).Should(Equal(tt.level))
+		g.Expect(record).Should(HaveKey("msg"))
+		g.Expect(record["msg"]).Should(ContainSubstring(tt.msg))
+	}
+
+}
+
+// Test that klog do not print to stderr
+func Test_klog_should_not_output_to_Stderr(t *testing.T) {
+	g := NewWithT(t)
+
+	log.SetOutput(ioutil.Discard)
+
+	stderr := captureStderr(func() {
+		service.DoWithCallToKlogPoweredLib()
+	})
+
+	g.Expect(stderr).ShouldNot(ContainSubstring("klog powered lib"))
+}
+
+func captureStderr(f func()) string {
+	// save and defer restore of original stderr
+	origStderr := os.Stderr
+	defer func() {
+		os.Stderr = origStderr
+	}()
+
+	// Create a pipe to catch stderr
+	reader, writer, err := os.Pipe()
+	if err != nil {
+		panic(err)
+	}
+	os.Stderr = writer
+
+	var out string
+	wg := new(sync.WaitGroup)
+	wg.Add(1)
+	go func() {
+		var buf bytes.Buffer
+		go func() {
+			f()
+			wg.Done()
+		}()
+		io.Copy(&buf, reader)
+		out = buf.String()
+		wg.Done()
+	}()
+	wg.Wait()
+	writer.Close()
+	return out
+}
diff --git a/pkg/utils/klogtologrus/test/klog-powered-lib/lib_methods.go b/pkg/utils/klogtologrus/test/klog-powered-lib/lib_methods.go
new file mode 100644
index 0000000..5e8aefe
--- /dev/null
+++ b/pkg/utils/klogtologrus/test/klog-powered-lib/lib_methods.go
@@ -0,0 +1,17 @@
+package klog_powered_lib
+
+import (
+	"k8s.io/klog"
+)
+
+func ActionWithKlogWarn() {
+	klog.Warning("Warning from klog powered lib")
+}
+
+func ActionWithKlogInfo() {
+	klog.V(0).Info("Info from klog powered lib")
+}
+
+func ActionWithKlogError() {
+	klog.ErrorDepth(2, "Error from klog powered lib")
+}
diff --git a/pkg/utils/klogtologrus/test/service/some_service.go b/pkg/utils/klogtologrus/test/service/some_service.go
new file mode 100644
index 0000000..4fadd36
--- /dev/null
+++ b/pkg/utils/klogtologrus/test/service/some_service.go
@@ -0,0 +1,16 @@
+package service
+
+import (
+	log "github.com/sirupsen/logrus"
+
+	_ "github.com/flant/shell-operator/pkg/utils/klogtologrus"
+	"github.com/flant/shell-operator/pkg/utils/klogtologrus/test/klog-powered-lib"
+)
+
+func DoWithCallToKlogPoweredLib() {
+	log.Trace("service action")
+
+	klog_powered_lib.ActionWithKlogWarn()
+	klog_powered_lib.ActionWithKlogInfo()
+	klog_powered_lib.ActionWithKlogError()
+}