Improve the log level filtering heuristics, but also discourage their use

backend/remote-state/azure/sender.go

@@ -21,7 +21,7 @@ func withRequestLogging() autorest.SendDecorator {
 	return func(s autorest.Sender) autorest.Sender {
 		return autorest.SenderFunc(func(r *http.Request) (*http.Response, error) {
 			// only log if logging's enabled
-			logLevel := logging.LogLevel()
+			logLevel := logging.CurrentLogLevel()
 			if logLevel == "" {
 				return s.Do(r)
 			}

go.mod

@@ -4,7 +4,6 @@ require (
 	cloud.google.com/go v0.45.1
 	github.com/Azure/azure-sdk-for-go v36.2.0+incompatible
 	github.com/Azure/go-autorest/autorest v0.9.2
-	github.com/Azure/go-autorest/autorest/adal v0.8.1-0.20191028180845-3492b2aff503
 	github.com/Unknwon/com v0.0.0-20151008135407-28b053d5a292 // indirect
 	github.com/abdullin/seq v0.0.0-20160510034733-d5467c17e7af // indirect
 	github.com/agext/levenshtein v1.2.2
@@ -86,7 +85,6 @@ require (
 	github.com/keybase/go-crypto v0.0.0-20161004153544-93f5b35093ba // indirect
 	github.com/lib/pq v1.0.0
 	github.com/lusis/go-artifactory v0.0.0-20160115162124-7e4ce345df82
-	github.com/marstr/guid v1.1.0 // indirect
 	github.com/masterzen/winrm v0.0.0-20190223112901-5e5c9a7fe54b
 	github.com/mattn/go-colorable v0.1.1
 	github.com/mattn/go-shellwords v1.0.4

go.sum

@@ -7,14 +7,9 @@ cloud.google.com/go v0.45.1 h1:lRi0CHyU+ytlvylOlFKKq0af6JncuyoRh1J+QJBqQx0=
 cloud.google.com/go v0.45.1/go.mod h1:RpBamKRgapWJb87xiFSdk4g1CME7QZg3uwTez+TSTjc=
 cloud.google.com/go/bigquery v1.0.1/go.mod h1:i/xbL2UlR5RvWAURpBYZTtm/cXjCha9lbfbpx4poX+o=
 cloud.google.com/go/datastore v1.0.0/go.mod h1:LXYbyblFSglQ5pkeyhO+Qmw7ukd3C+pD7TKLgZqpHYE=
-github.com/Azure/azure-sdk-for-go v21.3.0+incompatible h1:YFvAka2WKAl2xnJkYV1e1b7E2z88AgFszDzWU18ejMY=
-github.com/Azure/azure-sdk-for-go v21.3.0+incompatible/go.mod h1:9XXNKU+eRnpl9moKnB4QOLf1HestfXbmab5FXxiDBjc=
 github.com/Azure/azure-sdk-for-go v35.0.0+incompatible/go.mod h1:9XXNKU+eRnpl9moKnB4QOLf1HestfXbmab5FXxiDBjc=
 github.com/Azure/azure-sdk-for-go v36.2.0+incompatible h1:09cv2WoH0g6jl6m2iT+R9qcIPZKhXEL0sbmLhxP895s=
 github.com/Azure/azure-sdk-for-go v36.2.0+incompatible/go.mod h1:9XXNKU+eRnpl9moKnB4QOLf1HestfXbmab5FXxiDBjc=
-github.com/Azure/go-autorest v10.15.4+incompatible h1:q+DRrRdbCnkY7f2WxQBx58TwCGkEdMAK/hkZ10g0Pzk=
-github.com/Azure/go-autorest v10.15.4+incompatible/go.mod h1:r+4oMnoxhatjLLJ6zxSWATqVooLgysK6ZNox3g/xq24=
-github.com/Azure/go-autorest v13.3.0+incompatible h1:8Ix0VdeOllBx9jEcZ2Wb1uqWUpE1awmJiaHztwaJCPk=
 github.com/Azure/go-autorest/autorest v0.9.0/go.mod h1:xyHB1BMZT0cuDHU7I0+g046+BFDTQ8rEZB0s4Yfa6bI=
 github.com/Azure/go-autorest/autorest v0.9.2 h1:6AWuh3uWrsZJcNoCHrCF/+g4aKPCU39kaMO6/qrnK/4=
 github.com/Azure/go-autorest/autorest v0.9.2/go.mod h1:xyHB1BMZT0cuDHU7I0+g046+BFDTQ8rEZB0s4Yfa6bI=
@@ -30,6 +25,7 @@ github.com/Azure/go-autorest/autorest/date v0.2.0 h1:yW+Zlqf26583pE43KhfnhFcdmSW
 github.com/Azure/go-autorest/autorest/date v0.2.0/go.mod h1:vcORJHLJEh643/Ioh9+vPmf1Ij9AEBM5FuBIXLmIy0g=
 github.com/Azure/go-autorest/autorest/mocks v0.1.0/go.mod h1:OTyCOPRA2IgIlWxVYxBee2F5Gr4kF2zd2J5cFRaIDN0=
 github.com/Azure/go-autorest/autorest/mocks v0.2.0/go.mod h1:OTyCOPRA2IgIlWxVYxBee2F5Gr4kF2zd2J5cFRaIDN0=
+github.com/Azure/go-autorest/autorest/mocks v0.3.0 h1:qJumjCaCudz+OcqE9/XtEPfvtOjOmKaui4EOpFI6zZc=
 github.com/Azure/go-autorest/autorest/mocks v0.3.0/go.mod h1:a8FDP3DYzQ4RYfVAxAN3SVSiiO77gL2j2ronKKP0syM=
 github.com/Azure/go-autorest/autorest/to v0.3.0 h1:zebkZaadz7+wIQYgC7GXaz3Wb28yKYfVkkBKwc38VF8=
 github.com/Azure/go-autorest/autorest/to v0.3.0/go.mod h1:MgwOyqaIuKdG4TL/2ywSsIWKAfJfgHDo8ObuUk3t5sA=
@@ -121,8 +117,6 @@ github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c
 github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38=
 github.com/dgrijalva/jwt-go v3.2.0+incompatible h1:7qlOGliEKZXTDg6OTjfoBKDXWrumCAMpl/TFQ4/5kLM=
 github.com/dgrijalva/jwt-go v3.2.0+incompatible/go.mod h1:E3ru+11k8xSBh+hMPgOLZmtrrCbhqsmaPHjLKYnJCaQ=
-github.com/dimchansky/utfbom v1.0.0 h1:fGC2kkf4qOoKqZ4q7iIh+Vef4ubC1c38UDsEyZynZPc=
-github.com/dimchansky/utfbom v1.0.0/go.mod h1:rO41eb7gLfo8SF1jd9F8HplJm1Fewwi4mQvIirEdv+8=
 github.com/dimchansky/utfbom v1.1.0 h1:FcM3g+nofKgUteL8dm/UpdRXNC9KmADgTpLKsu0TRo4=
 github.com/dimchansky/utfbom v1.1.0/go.mod h1:rO41eb7gLfo8SF1jd9F8HplJm1Fewwi4mQvIirEdv+8=
 github.com/dnaeon/go-vcr v0.0.0-20180920040454-5637cf3d8a31 h1:Dzuw9GtbmllUqEcoHfScT9YpKFUssSiZ5PgZkIGf/YQ=
@@ -199,8 +193,6 @@ github.com/hashicorp/consul v0.0.0-20171026175957-610f3c86a089/go.mod h1:mFrjN1m
 github.com/hashicorp/errwrap v0.0.0-20180715044906-d6c0cd880357/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
 github.com/hashicorp/errwrap v1.0.0 h1:hLrqtEDnRye3+sgx6z4qVLNuviH3MR5aQ0ykNJa/UYA=
 github.com/hashicorp/errwrap v1.0.0/go.mod h1:YH+1FKiLXxHSkmPseP+kNlulaMuP3n2brvKWEqk/Jc4=
-github.com/hashicorp/go-azure-helpers v0.0.0-20190129193224-166dfd221bb2 h1:VBRx+yPYUZaobnn5ANBcOUf4hhWpTHSQgftG4TcDkhI=
-github.com/hashicorp/go-azure-helpers v0.0.0-20190129193224-166dfd221bb2/go.mod h1:lu62V//auUow6k0IykxLK2DCNW8qTmpm8KqhYVWattA=
 github.com/hashicorp/go-azure-helpers v0.10.0 h1:KhjDnQhCqEMKlt4yH00MCevJQPJ6LkHFdSveXINO6vE=
 github.com/hashicorp/go-azure-helpers v0.10.0/go.mod h1:YuAtHxm2v74s+IjQwUG88dHBJPd5jL+cXr5BGVzSKhE=
 github.com/hashicorp/go-checkpoint v0.5.0 h1:MFYpPZCnQqQTE18jFwSII6eUQrD/oxMFp3mlgcqk5mU=
@@ -301,8 +293,6 @@ github.com/lib/pq v1.0.0 h1:X5PMW56eZitiTeO7tKzZxFCSpbFZJtkMMooicw2us9A=
 github.com/lib/pq v1.0.0/go.mod h1:5WUZQaWbwv1U+lTReE5YruASi9Al49XbQIvNi/34Woo=
 github.com/lusis/go-artifactory v0.0.0-20160115162124-7e4ce345df82 h1:wnfcqULT+N2seWf6y4yHzmi7GD2kNx4Ute0qArktD48=
 github.com/lusis/go-artifactory v0.0.0-20160115162124-7e4ce345df82/go.mod h1:y54tfGmO3NKssKveTEFFzH8C/akrSOy/iW9qEAUDV84=
-github.com/marstr/guid v1.1.0 h1:/M4H/1G4avsieL6BbUwCOBzulmoeKVP5ux/3mQNnbyI=
-github.com/marstr/guid v1.1.0/go.mod h1:74gB1z2wpxxInTG6yaqA7KrtM0NZ+RbrcqDvYHefzho=
 github.com/masterzen/simplexml v0.0.0-20160608183007-4572e39b1ab9 h1:SmVbOZFWAlyQshuMfOkiAx1f5oUTsOGG5IXplAEYeeM=
 github.com/masterzen/simplexml v0.0.0-20160608183007-4572e39b1ab9/go.mod h1:kCEbxUJlNDEBNbdQMkPSp6yaKcRXVI6f4ddk8Riv4bc=
 github.com/masterzen/winrm v0.0.0-20190223112901-5e5c9a7fe54b h1:/1RFh2SLCJ+tEnT73+Fh5R2AO89sQqs8ba7o+hx1G0Y=
@@ -442,7 +432,6 @@ go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/
 go.uber.org/zap v1.9.1 h1:XCJQEf3W6eZaVwhRBof6ImoYGJSITeKWsyeh3HFu/5o=
 go.uber.org/zap v1.9.1/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
 golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
-golang.org/x/crypto v0.0.0-20181112202954-3d3f9f413869/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20190219172222-a4c6cb3142f2/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20190222235706-ffb98f73852f/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20190308221718-c2843e01d9a2/go.mod h1:djNgcEr1/C05ACkg1iLfiJU5Ep61QUkGW8qpdssI0+w=

helper/logging/indent.go

@@ -0,0 +1,23 @@
+package logging
+
+import (
+	"strings"
+)
+
+// Indent adds two spaces to the beginning of each line of the given string,
+// with the goal of making the log level filter understand it as a line
+// continuation rather than possibly as new log lines.
+func Indent(s string) string {
+	var b strings.Builder
+	for len(s) > 0 {
+		end := strings.IndexByte(s, '\n')
+		if end == -1 {
+			end = len(s) - 1
+		}
+		var l string
+		l, s = s[:end+1], s[end+1:]
+		b.WriteString("  ")
+		b.WriteString(l)
+	}
+	return b.String()
+}

helper/logging/indent_test.go

@@ -0,0 +1,15 @@
+package logging
+
+import (
+	"testing"
+)
+
+func TestIndent(t *testing.T) {
+	s := "hello\n  world\ngoodbye\n  moon"
+	got := Indent(s)
+	want := "  hello\n    world\n  goodbye\n    moon"
+
+	if got != want {
+		t.Errorf("wrong result\ngot:\n%s\n\nwant:\n%s", got, want)
+	}
+}

helper/logging/level.go

@@ -0,0 +1,159 @@
+package logging
+
+import (
+	"bytes"
+	"io"
+	"sync"
+)
+
+// LogLevel is a special string, conventionally written all in uppercase, that
+// can be used to mark a log line for filtering and to specify filtering
+// levels in the LevelFilter type.
+type LogLevel string
+
+// LevelFilter is an io.Writer that can be used with a logger that
+// will attempt to filter out log messages that aren't at least a certain
+// level.
+//
+// This filtering is HEURISTIC-BASED, and so will not be 100% reliable. The
+// assumptions it makes are:
+//
+//   - Individual log messages are never split across multiple calls to the
+//     Write method.
+//
+//   - Messages that carry levels are marked by a sequence starting with "[",
+//     then the level name string, and then "]". Any message without a sequence
+//     like this is an un-levelled message, and is not subject to filtering.
+//
+//   - Each \n-delimited line in a write is a separate log message, unless a
+//     line starts with at least one space in which case it is interpreted
+//     as a continuation of the previous line.
+//
+//   - If a log line starts with a non-whitespace character that isn't a digit
+//     then it's recognized as a degenerate continuation, because "real" log
+//     lines should start with a date/time and thus always have a leading
+//     digit. (This also cleans up after some situations where the assumptuion
+//     that messages arrive atomically aren't met, which is sadly sometimes
+//     true for longer messages that trip over some buffering behavior in
+//     panicwrap.)
+//
+// Because logging is a cross-cutting concern and not fully under the control
+// of Terraform itself, there will certainly be cases where the above
+// heuristics will fail. For example, it is likely that LevelFilter will
+// occasionally misinterpret a continuation line as a new message because the
+// code generating it doesn't know about our indentation convention.
+//
+// Our goal here is just to make a best effort to reduce the log volume,
+// accepting that the results will not be 100% correct.
+//
+// Logging calls within Terraform Core should follow the above conventions so
+// that the log output is broadly correct, however.
+//
+// Once the filter is in use somewhere, it is not safe to modify
+// the structure.
+type LevelFilter struct {
+	// Levels is the list of log levels, in increasing order of
+	// severity. Example might be: {"DEBUG", "WARN", "ERROR"}.
+	Levels []LogLevel
+
+	// MinLevel is the minimum level allowed through
+	MinLevel LogLevel
+
+	// The underlying io.Writer where log messages that pass the filter
+	// will be set.
+	Writer io.Writer
+
+	badLevels map[LogLevel]struct{}
+	show      bool
+	once      sync.Once
+}
+
+// Check will check a given line if it would be included in the level
+// filter.
+func (f *LevelFilter) Check(line []byte) bool {
+	f.once.Do(f.init)
+
+	// Check for a log level
+	var level LogLevel
+	x := bytes.IndexByte(line, '[')
+	if x >= 0 {
+		y := bytes.IndexByte(line[x:], ']')
+		if y >= 0 {
+			level = LogLevel(line[x+1 : x+y])
+		}
+	}
+
+	//return level == ""
+
+	_, ok := f.badLevels[level]
+	return !ok
+}
+
+// Write is a specialized implementation of io.Writer suitable for being
+// the output of a logger from the "log" package.
+//
+// This Writer implementation assumes that it will only recieve byte slices
+// containing one or more entire lines of log output, each one terminated by
+// a newline. This is compatible with the behavior of the "log" package
+// directly, and is also tolerant of intermediaries that might buffer multiple
+// separate writes together, as long as no individual log line is ever
+// split into multiple slices.
+//
+// Behavior is undefined if any log line is split across multiple writes or
+// written without a trailing '\n' delimiter.
+func (f *LevelFilter) Write(p []byte) (n int, err error) {
+	for len(p) > 0 {
+		// Split at the first \n, inclusive
+		idx := bytes.IndexByte(p, '\n')
+		if idx == -1 {
+			// Invalid, undelimited write. We'll tolerate it assuming that
+			// our assumptions are being violated, but the results may be
+			// non-ideal.
+			idx = len(p) - 1
+			break
+		}
+		var l []byte
+		l, p = p[:idx+1], p[idx+1:]
+		// Lines starting with characters other than decimal digits (including
+		// whitespace) are assumed to be continuations lines. This is an
+		// imprecise heuristic, but experimentally it seems to generate
+		// "good enough" results from Terraform Core's own logging. Its mileage
+		// may vary with output from other systems.
+		if l[0] >= '0' && l[0] <= '9' {
+			f.show = f.Check(l)
+		}
+		if f.show {
+			_, err = f.Writer.Write(l)
+			if err != nil {
+				// Technically it's not correct to say we've written the whole
+				// buffer, but for our purposes here it's good enough as we're
+				// only implementing io.Writer enough to satisfy logging
+				// use-cases.
+				return len(p), err
+			}
+		}
+	}
+
+	// We always behave as if we wrote the whole of the buffer, even if
+	// we actually skipped some lines. We're only implementiong io.Writer
+	// enough to satisfy logging use-cases.
+	return len(p), nil
+}
+
+// SetMinLevel is used to update the minimum log level
+func (f *LevelFilter) SetMinLevel(min LogLevel) {
+	f.MinLevel = min
+	f.init()
+}
+
+func (f *LevelFilter) init() {
+	badLevels := make(map[LogLevel]struct{})
+	for _, level := range f.Levels {
+		if level == f.MinLevel {
+			break
+		}
+		badLevels[level] = struct{}{}
+	}
+	f.badLevels = badLevels
+	f.show = true
+}

helper/logging/level_test.go

@@ -0,0 +1,93 @@
+package logging
+
+import (
+	"bytes"
+	"io"
+	"log"
+	"testing"
+)
+
+func TestLevelFilter_impl(t *testing.T) {
+	var _ io.Writer = new(LevelFilter)
+}
+
+func TestLevelFilter(t *testing.T) {
+	buf := new(bytes.Buffer)
+	filter := &LevelFilter{
+		Levels:   []LogLevel{"DEBUG", "WARN", "ERROR"},
+		MinLevel: "WARN",
+		Writer:   buf,
+	}
+
+	logger := log.New(filter, "", 0)
+	logger.Print("2019/01/01 00:00:00 [WARN] foo")
+	logger.Println("2019/01/01 00:00:00 [ERROR] bar\n2019/01/01 00:00:00 [DEBUG] buzz")
+	logger.Println("2019/01/01 00:00:00 [DEBUG] baz\n  continuation\n2019/01/01 00:00:00 [WARN] buzz\n  more\n2019/01/01 00:00:00 [DEBUG] fizz")
+
+	result := buf.String()
+	expected := "2019/01/01 00:00:00 [WARN] foo\n2019/01/01 00:00:00 [ERROR] bar\n2019/01/01 00:00:00 [WARN] buzz\n  more\n"
+	if result != expected {
+		t.Fatalf("wrong result\ngot:\n%s\nwant:\n%s", result, expected)
+	}
+}
+
+func TestLevelFilterCheck(t *testing.T) {
+	filter := &LevelFilter{
+		Levels:   []LogLevel{"DEBUG", "WARN", "ERROR"},
+		MinLevel: "WARN",
+		Writer:   nil,
+	}
+
+	testCases := []struct {
+		line  string
+		check bool
+	}{
+		{"[WARN] foo\n", true},
+		{"[ERROR] bar\n", true},
+		{"[DEBUG] baz\n", false},
+		{"[WARN] buzz\n", true},
+	}
+
+	for _, testCase := range testCases {
+		result := filter.Check([]byte(testCase.line))
+		if result != testCase.check {
+			t.Errorf("Fail: %s", testCase.line)
+		}
+	}
+}
+
+func TestLevelFilter_SetMinLevel(t *testing.T) {
+	filter := &LevelFilter{
+		Levels:   []LogLevel{"DEBUG", "WARN", "ERROR"},
+		MinLevel: "ERROR",
+		Writer:   nil,
+	}
+
+	testCases := []struct {
+		line        string
+		checkBefore bool
+		checkAfter  bool
+	}{
+		{"[WARN] foo\n", false, true},
+		{"[ERROR] bar\n", true, true},
+		{"[DEBUG] baz\n", false, false},
+		{"[WARN] buzz\n", false, true},
+	}
+
+	for _, testCase := range testCases {
+		result := filter.Check([]byte(testCase.line))
+		if result != testCase.checkBefore {
+			t.Errorf("Fail: %s", testCase.line)
+		}
+	}
+
+	// Update the minimum level to WARN
+	filter.SetMinLevel("WARN")
+
+	for _, testCase := range testCases {
+		result := filter.Check([]byte(testCase.line))
+		if result != testCase.checkAfter {
+			t.Errorf("Fail: %s", testCase.line)
+		}
+	}
+}