Backend for improving test logging (#1022)

* Create TLogger, bringing leveled logging to tests

Inspired heavily by go-logr, brings leveled logging to tests while
using the highly reliable zap logger backend to fulfill writing to
multiple log files.

Now that metrics logger has been removed, SetupLoggingFlags() is redundant. Moved to test/logging

* Cleanup TLogger and document

Add TLogger.Collect() to support collecting outcomes (either positive
strings or error types) which will be processed in a subtest upon
completion of the currently-running (sub-)test.

StructuredError prints its output in a more-readable form now.

Call-site should now work for .Log/.Logf-using functions.

Use cancel from NewTLogger instead of t.CleanUp()

Use a zapcore SpewEncoder when writing to testing.T

Means even non-json-encodable structs will get printed to the test log
output, while preserving encodable structured output for other log files.

Removed timestamp from printing to t.Log

* Fix the automatically-detected issues

Spelling, codegen, some coverage (coverage of memory_encoder.go should
not be necessary but the coverage tool is broken and needs to be fixed).

* Increase unit test coverage slightly and fix tiny comment

* Set attribute the way the coverage program wants

* Cleanup based on notes

* Comment cleanup and privitize var

* Mistake; left purposely-failing tests enabled

* Reduce long lines

* Consolidate cleanup code; make variable expressive

* Cleanup and bugfix

Failing functions now tested by having an internal constructor
option to skip calls to t.Fail()/t.FailNow().

Fixed some bugs with internal method errorWithRuntimeCheck and added
tests for it.

Address minor typos from comments.

* Tiny name/optimization fixes

Gopkg.toml

@@ -13,6 +13,8 @@ required = [
   "knative.dev/test-infra/scripts",
   "knative.dev/test-infra/tools/dep-collector",
   "github.com/gogo/protobuf/proto",
+  "github.com/go-logr/logr",
+  "github.com/go-logr/zapr",
 ]
 
 [[constraint]]

test/e2e_flags.go

@@ -22,15 +22,12 @@ package test
 import (
 	"bytes"
 	"flag"
-	"fmt"
 	"os"
 	"os/user"
 	"path"
 	"sync"
 	"text/template"
 
-	_ "github.com/golang/glog" // Needed if glog and klog are to coexist
-	"k8s.io/klog"
 	"knative.dev/pkg/test/logging"
 )
 
@@ -53,7 +50,6 @@ type EnvironmentFlags struct {
 	Kubeconfig      string // Path to kubeconfig (defaults to ./kube/config)
 	Namespace       string // K8s namespace (blank by default, to be overwritten by test suite)
 	IngressEndpoint string // Host to use for ingress endpoint
-	LogVerbose      bool   // Enable verbose logging
 	ImageTemplate   string // Template to build the image reference (defaults to {{.Repository}}/{{.Name}}:{{.Tag}})
 	DockerRepo      string // Docker repo (defaults to $KO_DOCKER_REPO)
 	Tag             string // Tag for test images
@@ -83,9 +79,6 @@ func initializeFlags() *EnvironmentFlags {
 
 	flag.StringVar(&f.IngressEndpoint, "ingressendpoint", "", "Provide a static endpoint url to the ingress server used during tests.")
 
-	flag.BoolVar(&f.LogVerbose, "logverbose", false,
-		"Set this flag to true if you would like to see verbose logging.")
-
 	flag.StringVar(&f.ImageTemplate, "imagetemplate", "{{.Repository}}/{{.Name}}:{{.Tag}}",
 		"Provide a template to generate the reference to an image from the test. Defaults to `{{.Repository}}/{{.Name}}:{{.Tag}}`.")
 
@@ -95,45 +88,12 @@ func initializeFlags() *EnvironmentFlags {
 
 	flag.StringVar(&f.Tag, "tag", "latest", "Provide the version tag for the test images.")
 
-	klog.InitFlags(klogFlags)
-	flag.Set("v", klogDefaultLogLevel)
-	flag.Set("alsologtostderr", "true")
-
 	return &f
 }
 
-func printFlags() {
-	fmt.Print("Test Flags: {")
-	flag.CommandLine.VisitAll(func(f *flag.Flag) {
-		fmt.Printf("'%s': '%s', ", f.Name, f.Value.String())
-	})
-	fmt.Println("}")
-}
-
-// SetupLoggingFlags initializes the logging libraries at runtime
+// TODO(coryrc): Remove once other repos are moved to call logging.InitializeLogger() directly
 func SetupLoggingFlags() {
-	flagsSetupOnce.Do(func() {
-		// Sync the glog flags to klog
-		flag.CommandLine.VisitAll(func(f1 *flag.Flag) {
-			f2 := klogFlags.Lookup(f1.Name)
-			if f2 != nil {
-				value := f1.Value.String()
-				f2.Value.Set(value)
-			}
-		})
-		if Flags.LogVerbose {
-			// If klog verbosity is not set to a non-default value (via "-args -v=X"),
-			if flag.CommandLine.Lookup("v").Value.String() == klogDefaultLogLevel {
-				// set up verbosity for klog so round_trippers.go prints:
-				//   URL, request headers, response headers, and partial response body
-				// See levels in vendor/k8s.io/client-go/transport/round_trippers.go:DebugWrappers for other options
-				klogFlags.Set("v", "8")
-				flag.Set("v", "8") // This is for glog, since glog=>klog sync is one-time
-			}
-			printFlags()
-		}
-		logging.InitializeLogger(Flags.LogVerbose)
-	})
+	logging.InitializeLogger()
 }
 
 // ImagePath is a helper function to transform an image name into an image reference that can be pulled.

test/logging/.gitattributes

@@ -0,0 +1 @@
+memory_encoder.go coverage-excluded=true

test/logging/doc.go

@@ -0,0 +1,49 @@
+/*
+Copyright 2020 The Knative Authors
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+/*
+Package logging assists setting up test logging and using leveled logging in tests.
+
+The TLogger is designed to assist the test writer in creating more useful tests and
+collecting log data in multiple streams, optimizing for human readability in one and
+machine readability in another. It's designed to mimic the testing.T object rather closely and
+use Zap logging semantics, both things already in use in Knative, to minimize the time developers
+need to spend learning the tool.
+
+Inspired by and uses go-logr.
+
+Advantages
+
+The TLogger enhances test design through subtle nudges and affordances:
+
+* It encourages only logging with .V(), giving the writer a nudge to think about how important it is,
+but without requiring them to fit it in a narrowly-defined category.
+
+* Reduces boilerplate of carrying around context for errors in several different variables,
+using .WithValues(), which results in more consistent and reusable code across the tests.
+
+Porting
+
+To port code from using testing.T to logging.TLogger, the interfaces knative.dev/pkg/test.T and
+knative.dev/pkg/test.TLegacy have been created. All library functions should be refactored to use
+one interface and all .Log() calls rewritten to use structured format, which works with testing and
+TLogger. If a library function needs test functions not available even in test.TLegacy,
+it's probably badly written.
+
+Then any test can be incrementally rewritten to use TLogger, as it coexists with testing.T without issue.
+
+*/
+package logging

test/logging/error.go

@@ -0,0 +1,91 @@
+/*
+Copyright 2020 The Knative Authors
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package logging
+
+import (
+	"fmt"
+
+	"github.com/davecgh/go-spew/spew"
+)
+
+// StructuredError is an error which can hold arbitrary key-value arguments.
+//
+// TODO(coryrc): The Structured Error is experimental and likely to be removed, but is currently in use in a refactored test.
+type StructuredError interface {
+	error
+	GetValues() []interface{}
+	WithValues(...interface{}) StructuredError
+	DisableValuePrinting()
+	EnableValuePrinting()
+}
+
+type structuredError struct {
+	msg           string
+	keysAndValues []interface{}
+	print         bool
+}
+
+func keysAndValuesToSpewedMap(args ...interface{}) map[string]string {
+	m := make(map[string]string, len(args)/2)
+	for i := 0; i < len(args); i += 2 {
+		key, val := args[i], args[i+1]
+		if keyStr, ok := key.(string); ok {
+			m[keyStr] = spew.Sdump(val)
+		}
+	}
+	return m
+}
+
+// Implement `error` interface
+func (e structuredError) Error() string {
+	// TODO(coryrc): accept zap.Field entries?
+	if e.print {
+		// %v for fmt.Sprintf does print keys sorted
+		return fmt.Sprintf("Error: %s\nContext:\n%v", e.msg, keysAndValuesToSpewedMap(e.keysAndValues...))
+	} else {
+		return e.msg
+	}
+}
+
+// GetValues gives you the structured key values in a plist
+func (e structuredError) GetValues() []interface{} {
+	return e.keysAndValues
+}
+
+// DisableValuePrinting disables printing out the keys and values from the Error() method
+func (e *structuredError) DisableValuePrinting() {
+	e.print = false
+}
+
+// EnableValuePrinting enables printing out the keys and values from the Error() method
+func (e *structuredError) EnableValuePrinting() {
+	e.print = true
+}
+
+// Create a StructuredError. Gives a little better logging when given to a TLogger.
+// This may prove to not be useful if users use the logger's WithValues() better.
+func Error(msg string, keysAndValues ...interface{}) *structuredError {
+	return &structuredError{msg, keysAndValues, true}
+}
+
+// WithValues operates just like TLogger's WithValues but stores them in the error object.
+func (e *structuredError) WithValues(keysAndValues ...interface{}) StructuredError {
+	newKAV := make([]interface{}, 0, len(keysAndValues)+len(e.keysAndValues))
+	newKAV = append(newKAV, e.keysAndValues...)
+	newKAV = append(newKAV, keysAndValues...)
+	return &structuredError{e.msg, newKAV, e.print}
+}