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.
This commit is contained in:
Martin Atkins 2019-12-05 11:13:37 -08:00
parent ebc075226a
commit 30bf83cdeb
11 changed files with 293 additions and 32 deletions

View File

@ -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)
}

2
go.mod
View File

@ -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

13
go.sum
View File

@ -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=

23
helper/logging/indent.go Normal file
View File

@ -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()
}

View File

@ -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)
}
}

144
helper/logging/level.go Normal file
View File

@ -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
}

View File

@ -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)
}
}
}

View File

@ -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"
}

View File

@ -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,
}

View File

@ -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)

View File

@ -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)