From 4f91d1138e64727732efff6ca54d76e6993dd7db Mon Sep 17 00:00:00 2001 From: Martin Atkins Date: Thu, 5 Dec 2019 11:13:37 -0800 Subject: [PATCH 1/3] helper/logging: Bring the LevelFilter into our own codebase In order to make this work reasonably we can't avoid using some funny heuristics, which are somewhat reasonable to apply within the context of Terraform itself but would not be good to add to the general "logutils". Specifically, this is adding the additional heuristic that lines starting with spaces are continuation lines and so should inherit the log level of the most recent non-continuation line. --- backend/remote-state/azure/sender.go | 2 +- go.mod | 2 - go.sum | 13 +-- helper/logging/indent.go | 23 +++++ helper/logging/indent_test.go | 15 +++ helper/logging/level.go | 144 +++++++++++++++++++++++++++ helper/logging/level_test.go | 93 +++++++++++++++++ helper/logging/logging.go | 17 ++-- helper/resource/testing.go | 7 +- terraform/graph_builder.go | 6 +- terraform/transform.go | 3 +- 11 files changed, 293 insertions(+), 32 deletions(-) create mode 100644 helper/logging/indent.go create mode 100644 helper/logging/indent_test.go create mode 100644 helper/logging/level.go create mode 100644 helper/logging/level_test.go diff --git a/backend/remote-state/azure/sender.go b/backend/remote-state/azure/sender.go index 90a2fb5bd8f7..d2b432a65a0f 100644 --- a/backend/remote-state/azure/sender.go +++ b/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) } diff --git a/go.mod b/go.mod index aa7d2056aa1d..e3eb4beadc4e 100644 --- a/go.mod +++ b/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 diff --git a/go.sum b/go.sum index 4508c7352887..57054a77c3c6 100644 --- a/go.sum +++ b/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= diff --git a/helper/logging/indent.go b/helper/logging/indent.go new file mode 100644 index 000000000000..e0da0d7c7356 --- /dev/null +++ b/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() +} diff --git a/helper/logging/indent_test.go b/helper/logging/indent_test.go new file mode 100644 index 000000000000..46b12a42caf5 --- /dev/null +++ b/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) + } +} diff --git a/helper/logging/level.go b/helper/logging/level.go new file mode 100644 index 000000000000..2c173a626ae5 --- /dev/null +++ b/helper/logging/level.go @@ -0,0 +1,144 @@ +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. +// +// 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{} + 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) { + show := true + for len(p) > 0 { + // Split at the first \n, inclusive + idx := bytes.IndexByte(p, '\n') + if idx == -1 { + // Invalid, undelimited write + break + } + var l []byte + l, p = p[:idx+1], p[idx+1:] + // Lines starting with whitespace are continuations, so they inherit + // the result of the check of the previous line. + if !(l[0] == ' ' || l[0] == '\t' || l[0] == '\n') { + show = f.Check(l) + } + if 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 +} diff --git a/helper/logging/level_test.go b/helper/logging/level_test.go new file mode 100644 index 000000000000..12cade314025 --- /dev/null +++ b/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("[WARN] foo") + logger.Println("[ERROR] bar\n[DEBUG] buzz") + logger.Println("[DEBUG] baz\n continuation\n[WARN] buzz\n more\n[DEBUG] fizz") + + result := buf.String() + expected := "[WARN] foo\n[ERROR] bar\n[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) + } + } +} diff --git a/helper/logging/logging.go b/helper/logging/logging.go index 6bd92f777846..e2913fa2be75 100644 --- a/helper/logging/logging.go +++ b/helper/logging/logging.go @@ -7,8 +7,6 @@ import ( "os" "strings" "syscall" - - "github.com/hashicorp/logutils" ) // These are the environmental variables that determine if we log, and if @@ -18,13 +16,14 @@ const ( EnvLogFile = "TF_LOG_PATH" // Set to a file ) -var ValidLevels = []logutils.LogLevel{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} +// ValidLevels are the log level names that Terraform recognizes. +var ValidLevels = []LogLevel{"TRACE", "DEBUG", "INFO", "WARN", "ERROR"} // LogOutput determines where we should send logs (if anywhere) and the log level. func LogOutput() (logOutput io.Writer, err error) { logOutput = ioutil.Discard - logLevel := LogLevel() + logLevel := CurrentLogLevel() if logLevel == "" { return } @@ -39,9 +38,9 @@ func LogOutput() (logOutput io.Writer, err error) { } // This was the default since the beginning - logOutput = &logutils.LevelFilter{ + logOutput = &LevelFilter{ Levels: ValidLevels, - MinLevel: logutils.LogLevel(logLevel), + MinLevel: LogLevel(logLevel), Writer: logOutput, } @@ -64,8 +63,8 @@ func SetOutput() { log.SetOutput(out) } -// LogLevel returns the current log level string based the environment vars -func LogLevel() string { +// CurrentLogLevel returns the current log level string based the environment vars +func CurrentLogLevel() string { envLevel := os.Getenv(EnvLog) if envLevel == "" { return "" @@ -85,7 +84,7 @@ func LogLevel() string { // IsDebugOrHigher returns whether or not the current log level is debug or trace func IsDebugOrHigher() bool { - level := string(LogLevel()) + level := string(CurrentLogLevel()) return level == "DEBUG" || level == "TRACE" } diff --git a/helper/resource/testing.go b/helper/resource/testing.go index 26ea72a8df23..0e5af093346c 100644 --- a/helper/resource/testing.go +++ b/helper/resource/testing.go @@ -18,7 +18,6 @@ import ( "github.com/davecgh/go-spew/spew" "github.com/hashicorp/errwrap" "github.com/hashicorp/go-multierror" - "github.com/hashicorp/logutils" "github.com/mitchellh/colorstring" "github.com/hashicorp/terraform/addrs" @@ -396,7 +395,7 @@ const EnvLogPathMask = "TF_LOG_PATH_MASK" func LogOutput(t TestT) (logOutput io.Writer, err error) { logOutput = ioutil.Discard - logLevel := logging.LogLevel() + logLevel := logging.CurrentLogLevel() if logLevel == "" { return } @@ -424,9 +423,9 @@ func LogOutput(t TestT) (logOutput io.Writer, err error) { } // This was the default since the beginning - logOutput = &logutils.LevelFilter{ + logOutput = &logging.LevelFilter{ Levels: logging.ValidLevels, - MinLevel: logutils.LogLevel(logLevel), + MinLevel: logging.LogLevel(logLevel), Writer: logOutput, } diff --git a/terraform/graph_builder.go b/terraform/graph_builder.go index 66b21f300dc7..71b71b75284d 100644 --- a/terraform/graph_builder.go +++ b/terraform/graph_builder.go @@ -5,9 +5,9 @@ import ( "log" "strings" - "github.com/hashicorp/terraform/tfdiags" - "github.com/hashicorp/terraform/addrs" + "github.com/hashicorp/terraform/helper/logging" + "github.com/hashicorp/terraform/tfdiags" ) // GraphBuilder is an interface that can be implemented and used with @@ -56,7 +56,7 @@ func (b *BasicGraphBuilder) Build(path addrs.ModuleInstance) (*Graph, tfdiags.Di debugOp.End(errMsg) if thisStepStr := g.StringWithNodeTypes(); thisStepStr != lastStepStr { - log.Printf("[TRACE] Completed graph transform %T with new graph:\n%s------", step, thisStepStr) + log.Printf("[TRACE] Completed graph transform %T with new graph:\n%s ------", step, logging.Indent(thisStepStr)) lastStepStr = thisStepStr } else { log.Printf("[TRACE] Completed graph transform %T (no changes)", step) diff --git a/terraform/transform.go b/terraform/transform.go index fd3f5c7daa36..d587c89e49a0 100644 --- a/terraform/transform.go +++ b/terraform/transform.go @@ -4,6 +4,7 @@ import ( "log" "github.com/hashicorp/terraform/dag" + "github.com/hashicorp/terraform/helper/logging" ) // GraphTransformer is the interface that transformers implement. This @@ -45,7 +46,7 @@ func (t *graphTransformerMulti) Transform(g *Graph) error { return err } if thisStepStr := g.StringWithNodeTypes(); thisStepStr != lastStepStr { - log.Printf("[TRACE] (graphTransformerMulti) Completed graph transform %T with new graph:\n%s------", t, thisStepStr) + log.Printf("[TRACE] (graphTransformerMulti) Completed graph transform %T with new graph:\n%s ------", t, logging.Indent(thisStepStr)) lastStepStr = thisStepStr } else { log.Printf("[TRACE] (graphTransformerMulti) Completed graph transform %T (no changes)", t) From d33256aa8a995d0f37b82d355a85e735d17d9d8b Mon Sep 17 00:00:00 2001 From: Martin Atkins Date: Thu, 5 Dec 2019 11:49:11 -0800 Subject: [PATCH 2/3] helper/logging: Warn about levels other than TRACE The filtering for other log levels is unreliable and glitchy because it's trying to infer information from the log stream that isn't reliably represented. Although the previous commit has improved the situation somewhat, it is still a tricky and unreliable heuristic, so worth a warning to anyone who is reading such a log that if they see something confusing it could be a result of the heuristic not working fully. --- helper/logging/logging.go | 3 +++ 1 file changed, 3 insertions(+) diff --git a/helper/logging/logging.go b/helper/logging/logging.go index e2913fa2be75..f5a0ba47feee 100644 --- a/helper/logging/logging.go +++ b/helper/logging/logging.go @@ -78,6 +78,9 @@ func CurrentLogLevel() string { log.Printf("[WARN] Invalid log level: %q. Defaulting to level: TRACE. Valid levels are: %+v", envLevel, ValidLevels) } + if logLevel != "TRACE" { + log.Printf("[WARN] Log levels other than TRACE are currently unreliable, and are supported only for backward compatibility.\n Use TF_LOG=TRACE to see Terraform's internal logs.\n ----") + } return logLevel } From fa302f7846cf4e10069274c101ac11c87fe59036 Mon Sep 17 00:00:00 2001 From: Martin Atkins Date: Thu, 5 Dec 2019 12:19:22 -0800 Subject: [PATCH 3/3] helper/logging: Loosen the filtering heuristic even more Now we'll consider any message that doesn't start with a digit as a continuation. This is _definitely_ in loose, best-effort territory now since a continuation line could very well start with a digit, but ultimately this is still better than the totally broken behavior that preceded it. Just to make sure that none of these heuristics interfere with producing complete, accurate logs for TRACE, we'll skip the LevelFilter altogether in that case. --- helper/logging/level.go | 29 ++++++++++++++++++++++------- helper/logging/level_test.go | 8 ++++---- helper/logging/logging.go | 11 +++++++++-- 3 files changed, 35 insertions(+), 13 deletions(-) diff --git a/helper/logging/level.go b/helper/logging/level.go index 2c173a626ae5..0dc4dfe8d544 100644 --- a/helper/logging/level.go +++ b/helper/logging/level.go @@ -29,6 +29,14 @@ type LogLevel string // 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 @@ -56,6 +64,7 @@ type LevelFilter struct { Writer io.Writer badLevels map[LogLevel]struct{} + show bool once sync.Once } @@ -93,22 +102,27 @@ func (f *LevelFilter) Check(line []byte) bool { // 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) { - show := true for len(p) > 0 { // Split at the first \n, inclusive idx := bytes.IndexByte(p, '\n') if idx == -1 { - // Invalid, undelimited write + // 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 whitespace are continuations, so they inherit - // the result of the check of the previous line. - if !(l[0] == ' ' || l[0] == '\t' || l[0] == '\n') { - show = f.Check(l) + // 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 show { + if f.show { _, err = f.Writer.Write(l) if err != nil { // Technically it's not correct to say we've written the whole @@ -141,4 +155,5 @@ func (f *LevelFilter) init() { badLevels[level] = struct{}{} } f.badLevels = badLevels + f.show = true } diff --git a/helper/logging/level_test.go b/helper/logging/level_test.go index 12cade314025..baa94748e41c 100644 --- a/helper/logging/level_test.go +++ b/helper/logging/level_test.go @@ -20,12 +20,12 @@ func TestLevelFilter(t *testing.T) { } logger := log.New(filter, "", 0) - logger.Print("[WARN] foo") - logger.Println("[ERROR] bar\n[DEBUG] buzz") - logger.Println("[DEBUG] baz\n continuation\n[WARN] buzz\n more\n[DEBUG] fizz") + 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 := "[WARN] foo\n[ERROR] bar\n[WARN] buzz\n more\n" + 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) } diff --git a/helper/logging/logging.go b/helper/logging/logging.go index f5a0ba47feee..75627cf02e8c 100644 --- a/helper/logging/logging.go +++ b/helper/logging/logging.go @@ -37,14 +37,21 @@ func LogOutput() (logOutput io.Writer, err error) { } } - // This was the default since the beginning + if logLevel == "TRACE" { + // Just pass through logs directly then, without any level filtering at all. + return logOutput, nil + } + + // Otherwise we'll use our level filter, which is a heuristic-based + // best effort thing that is not totally reliable but helps to reduce + // the volume of logs in some cases. logOutput = &LevelFilter{ Levels: ValidLevels, MinLevel: LogLevel(logLevel), Writer: logOutput, } - return + return logOutput, nil } // SetOutput checks for a log destination with LogOutput, and calls