replace log with glog for all tests (#1104)

* replace log iwth glog for all tests

* update README

* update more comments

* s/pls/please

* s/Pls/Please/ again

test/README.md

@@ -42,6 +42,7 @@ go test -v -tags=e2e -count=1 ./test/e2e -run ^TestAutoscaleUpDownUp$
   using the environment specified in [your environment variables](/DEVELOPMENT.md#environment-setup).
 * Since these tests are fairly slow, running them with logging
   enabled is recommended (`-v`).
+* Using [`--logverbose`](#output-verbose-log) to see the verbose log output from test as well as from k8s libraries.
 * Using `-count=1` is [the idiomatic way to disable test caching](https://golang.org/doc/go1.10#test)
 
 You can [use test flags](#flags) to control the environment
@@ -111,6 +112,7 @@ Tests importing [`github.com/knative/serving/test`](adding_tests.md#test-library
 * [`--cluster`](#specifying-cluster)
 * [`--dockerrepo`](#overriding-docker-repo)
 * [`--resolvabledomain`](#using-a-resolvable-domain)
+* [`--logverbose`](#output-verbose-log)
 
 ### Specifying kubeconfig
 
@@ -169,3 +171,11 @@ and spoof the `Host` in the header.
 If you have configured your cluster to use a resolvable domain, you can use the
 `--resolvabledomain` flag to indicate that the test should make requests directly against
 `Route.Status.Domain` and does not need to spoof the `Host`.
+
+#### Output verbose log
+
+The `--logverbose` argument lets you see verbose test logs and k8s logs.
+
+```bash
+go test -v -tags=e2e -count=1 ./test/e2e --logverbose
+```

test/adding_tests.md

@@ -34,6 +34,7 @@ you can use in your tests.
 You can:
 
 * [Use common test flags](#use-common-test-flags)
+* [Output log](#output-log)
 * [Get access to client objects](#get-access-to-client-objects)
 * [Make requests against deployed services](#make-requests-against-deployed-services)
 * [Poll Knative Serving resources](#poll-knative-serving-resources)
@@ -55,6 +56,13 @@ imagePath := strings.Join([]string{test.Flags.DockerRepo, image}, "/"))
 
 _See [e2e_flags.go](./e2e_flags.go)._
 
+### Output log
+
+Log output should be provided exclusively using [the glog library](https://godoc.org/github.com/golang/glog).
+Package "github.com/knative/serving/test" contains a `Verbose` function to be used for all verbose logging.
+Internally, it defines `glog.Level` 10 as log level. _See [e2e_flags.go](./e2e_flags.go)._
+Also _see [errorcondition_test.go](./e2e/errorcondition_test.go)._ for an example of `test.Verbose()` call.
+
 ### Get access to client objects
 
 To initialize client objects that you can use [the command line flags](#use-flags)

test/cleanup.go

@@ -19,7 +19,7 @@ limitations under the License.
 package test
 
 import (
-	"log"
+	"github.com/golang/glog"
 	"os"
 	"os/signal"
 )
@@ -30,7 +30,7 @@ func CleanupOnInterrupt(cleanup func()) {
 	signal.Notify(c, os.Interrupt)
 	go func() {
 		for _ = range c {
-			log.Println("Test interrupted, cleaning up.")
+			glog.Infof("Test interrupted, cleaning up.")
 			cleanup()
 			os.Exit(1)
 		}

test/conformance/README.md

@@ -17,13 +17,9 @@ These tests use [the test library](../adding_tests.md#test-library).
 
 The conformance tests should **ONLY** cover functionality that applies to any implementation of the API.
 
-The conformance tests **MUST**: 
+The conformance tests **MUST**:
 
-1. Provide frequent output describing what actions they are undertaking, especially before performing long running operations.
-    1. Log output should be provided exclusively using [the log library](https://golang.org/pkg/log/)
-       (vs. [the testing log functions](https://golang.org/pkg/testing/#B.Log), which buffer output until the test has completed).
+1. Provide frequent output describing what actions they are undertaking, especially before performing long running operations. Please see the [Log section](../adding_tests.md#output-log) for detailed instructions.
 2. Follow Golang best practices.
-3. Not require any specific file system permissions to run or require any additional binaries to be installed in the target environment before
-   the tests run.
-4. Not depend on any k8s resources outside of those added by Knative Serving OR
-   they should provide flags that allow the test to run without access to those resources.
+3. Not require any specific file system permissions to run or require any additional binaries to be installed in the target environment before the tests run.
+4. Not depend on any k8s resources outside of those added by Knative Serving OR they should provide flags that allow the test to run without access to those resources.

test/conformance/route_test.go

@@ -19,7 +19,7 @@ package conformance
 
 import (
 	"fmt"
-	"log"
+	"github.com/golang/glog"
 	"strings"
 	"testing"
 
@@ -82,35 +82,35 @@ func updateConfigWithImage(clients *test.Clients, names test.ResourceNames, imag
 }
 
 func assertResourcesUpdatedWhenRevisionIsReady(t *testing.T, clients *test.Clients, names test.ResourceNames, expectedText string) {
-	log.Println("The Revision will be marked as Ready when it can serve traffic")
+	glog.Infof("The Revision will be marked as Ready when it can serve traffic")
 	err := test.WaitForRevisionState(clients.Revisions, names.Revision, test.IsRevisionReady(names.Revision))
 	if err != nil {
 		t.Fatalf("Revision %s did not become ready to serve traffic: %v", names.Revision, err)
 	}
 
-	log.Println("Updates the Configuration that the Revision is ready")
+	glog.Infof("Updates the Configuration that the Revision is ready")
 	err = test.WaitForConfigurationState(clients.Configs, names.Config, func(c *v1alpha1.Configuration) (bool, error) {
 		return c.Status.LatestReadyRevisionName == names.Revision, nil
 	})
 	if err != nil {
 		t.Fatalf("The Configuration %s was not updated indicating that the Revision %s was ready: %v", names.Config, names.Revision, err)
 	}
 
-	log.Println("Updates the Route to route traffic to the Revision")
+	glog.Infof("Updates the Route to route traffic to the Revision")
 	err = test.WaitForRouteState(clients.Routes, names.Route, test.AllRouteTrafficAtRevision(names.Route, names.Revision))
 	if err != nil {
 		t.Fatalf("The Route %s was not updated to route traffic to the Revision %s: %v", names.Route, names.Revision, err)
 	}
 
-	log.Println("When the Revision can have traffic routed to it, the Route is marked as Ready")
+	glog.Infof("When the Revision can have traffic routed to it, the Route is marked as Ready")
 	err = test.WaitForRouteState(clients.Routes, names.Route, func(r *v1alpha1.Route) (bool, error) {
 		return r.Status.IsReady(), nil
 	})
 	if err != nil {
 		t.Fatalf("The Route %s was not marked as Ready to serve traffic to Revision %s: %v", names.Route, names.Revision, err)
 	}
 
-	log.Println("Serves the expected data at the endpoint")
+	glog.Infof("Serves the expected data at the endpoint")
 	updatedRoute, err := clients.Routes.Get(names.Route, metav1.GetOptions{})
 	if err != nil {
 		t.Fatalf("Error fetching Route %s: %v", names.Route, err)
@@ -163,13 +163,13 @@ func TestRouteCreation(t *testing.T) {
 	test.CleanupOnInterrupt(func() { tearDown(clients, names) })
 	defer tearDown(clients, names)
 
-	log.Println("Creating a new Route and Configuration")
+	glog.Infof("Creating a new Route and Configuration")
 	err := createRouteAndConfig(clients, names, imagePaths)
 	if err != nil {
 		t.Fatalf("Failed to create Route and Configuration: %v", err)
 	}
 
-	log.Println("The Configuration will be updated with the name of the Revision once it is created")
+	glog.Infof("The Configuration will be updated with the name of the Revision once it is created")
 	revisionName, err := getFirstRevisionName(clients, names)
 	if err != nil {
 		t.Fatalf("Configuration %s was not updated with the new revision: %v", names.Config, err)
@@ -178,13 +178,13 @@ func TestRouteCreation(t *testing.T) {
 
 	assertResourcesUpdatedWhenRevisionIsReady(t, clients, names, "What a spaceport!")
 
-	log.Println("Updating the Configuration to use a different image")
+	glog.Infof("Updating the Configuration to use a different image")
 	err = updateConfigWithImage(clients, names, imagePaths)
 	if err != nil {
 		t.Fatalf("Patch update for Configuration %s with new image %s failed: %v", names.Config, imagePaths[1], err)
 	}
 
-	log.Println("Since the Configuration was updated a new Revision will be created and the Configuration will be updated")
+	glog.Infof("Since the Configuration was updated a new Revision will be created and the Configuration will be updated")
 	revisionName, err = getNextRevisionName(clients, names)
 	if err != nil {
 		t.Fatalf("Configuration %s was not updated with the Revision for image %s: %v", names.Config, image2, err)

test/crd.go

@@ -18,7 +18,7 @@ package test
 // crd contains functions that construct boilerplate CRD definitions.
 
 import (
-	"log"
+	"github.com/golang/glog"
 	"math/rand"
 	"sync"
 	"time"
@@ -89,7 +89,7 @@ var once sync.Once
 
 func initSeed() {
 	seed := time.Now().UTC().UnixNano()
-	log.Printf("Seeding rand.Rand with %v\n", seed)
+	glog.Infof("Seeding rand.Rand with %v\n", seed)
 	r = rand.New(rand.NewSource(seed))
 }
 

test/e2e/README.md

@@ -12,9 +12,7 @@ These tests use [the test library](../adding_tests.md#test-library).
 
 The e2e tests are used to test whether the flow of Knative Serving is performing as designed from start to finish.
 
-The e2e tests **MUST**: 
+The e2e tests **MUST**:
 
-1. Provide frequent output describing what actions they are undertaking, especially before performing long running operations.
-    1. Log output should be provided exclusively using [the log library](https://golang.org/pkg/log/)
-       (vs. [the testing log functions](https://golang.org/pkg/testing/#B.Log), which buffer output until the test has completed).
+1. Provide frequent output describing what actions they are undertaking, especially before performing long running operations. Plese see the [Log section](../adding_tests.md#output-log) for detailed instructions.
 2. Follow Golang best practices.

test/e2e/autoscale_test.go

@@ -18,7 +18,7 @@ limitations under the License.
 package e2e
 
 import (
-	"log"
+	"github.com/golang/glog"
 	"strings"
 	"testing"
 
@@ -54,7 +54,7 @@ func isDeploymentScaledDown() func(d *v1beta1.Deployment) (bool, error) {
 func generateTrafficBurst(clients *test.Clients, names test.ResourceNames, num int, domain string) {
 	concurrentRequests := make(chan bool, num)
 
-	log.Printf("Performing %d concurrent requests.", num)
+	glog.Infof("Performing %d concurrent requests.", num)
 	for i := 0; i < num; i++ {
 		go func() {
 			test.WaitForEndpointState(clients.Kube,
@@ -67,7 +67,7 @@ func generateTrafficBurst(clients *test.Clients, names test.ResourceNames, num i
 		}()
 	}
 
-	log.Println("Waiting for all requests to complete.")
+	glog.Infof("Waiting for all requests to complete.")
 	for i := 0; i < num; i++ {
 		<-concurrentRequests
 	}
@@ -82,15 +82,15 @@ func TestAutoscaleUpDownUp(t *testing.T) {
 			"autoscale"},
 		"/")
 
-	log.Println("Creating a new Route and Configuration")
+	glog.Infof("Creating a new Route and Configuration")
 	names, err := CreateRouteAndConfig(clients, imagePath)
 	if err != nil {
 		t.Fatalf("Failed to create Route and Configuration: %v", err)
 	}
 	test.CleanupOnInterrupt(func() { TearDown(clients, names) })
 	defer TearDown(clients, names)
 
-	log.Println(`When the Revision can have traffic routed to it,
+	glog.Infof(`When the Revision can have traffic routed to it,
 	            the Route is marked as Ready.`)
 	err = test.WaitForRouteState(
 		clients.Routes,
@@ -103,7 +103,7 @@ func TestAutoscaleUpDownUp(t *testing.T) {
 			 %v`, names.Route, err)
 	}
 
-	log.Println("Serves the expected data at the endpoint")
+	glog.Infof("Serves the expected data at the endpoint")
 	config, err := clients.Configs.Get(names.Config, metav1.GetOptions{})
 	if err != nil {
 		t.Fatalf(`Configuration %s was not updated with the new
@@ -130,36 +130,36 @@ func TestAutoscaleUpDownUp(t *testing.T) {
 			names.Route, domain, autoscaleExpectedOutput, err)
 	}
 
-	log.Println(`The autoscaler spins up additional replicas when traffic
+	glog.Infof(`The autoscaler spins up additional replicas when traffic
 		    increases.`)
 	generateTrafficBurst(clients, names, 5, domain)
 	err = test.WaitForDeploymentState(
 		clients.Kube.ExtensionsV1beta1().Deployments(NamespaceName),
 		deploymentName,
 		isDeploymentScaledUp())
 	if err != nil {
-		log.Fatalf(`Unable to observe the Deployment named %s scaling
+		glog.Fatalf(`Unable to observe the Deployment named %s scaling
 			   up. %s`, deploymentName, err)
 	}
 
-	log.Println(`The autoscaler successfully scales down when devoid of
+	glog.Infof(`The autoscaler successfully scales down when devoid of
 		    traffic.`)
 	err = test.WaitForDeploymentState(
 		clients.Kube.ExtensionsV1beta1().Deployments(NamespaceName),
 		deploymentName,
 		isDeploymentScaledDown())
 	if err != nil {
-		log.Fatalf(`Unable to observe the Deployment named %s scaling
+		glog.Fatalf(`Unable to observe the Deployment named %s scaling
 		           down. %s`, deploymentName, err)
 	}
 
 	// Account for the case where scaling up uses all available pods.
-	log.Println("Wait until there are pods available to scale into.")
+	glog.Infof("Wait until there are pods available to scale into.")
 	pc := clients.Kube.CoreV1().Pods(NamespaceName)
 	pods, err := pc.List(metav1.ListOptions{})
 	podCount := 0
 	if err != nil {
-		log.Printf("Unable to get pod count. Defaulting to 1.")
+		glog.Infof("Unable to get pod count. Defaulting to 1.")
 		podCount = 1
 	} else {
 		podCount = len(pods.Items)
@@ -170,15 +170,15 @@ func TestAutoscaleUpDownUp(t *testing.T) {
 			return len(p.Items) < podCount, nil
 		})
 
-	log.Println(`The autoscaler spins up additional replicas once again when
+	glog.Infof(`The autoscaler spins up additional replicas once again when
 	            traffic increases.`)
 	generateTrafficBurst(clients, names, 8, domain)
 	err = test.WaitForDeploymentState(
 		clients.Kube.ExtensionsV1beta1().Deployments(NamespaceName),
 		deploymentName,
 		isDeploymentScaledUp())
 	if err != nil {
-		log.Fatalf(`Unable to observe the Deployment named %s scaling
+		glog.Fatalf(`Unable to observe the Deployment named %s scaling
 			   up. %s`, deploymentName, err)
 	}
 }

test/e2e/errorcondition_test.go

@@ -20,11 +20,11 @@ package e2e
 import (
 	"errors"
 	"fmt"
+	"github.com/golang/glog"
 	"github.com/google/go-containerregistry/v1/remote"
 	"github.com/knative/serving/pkg/apis/serving/v1alpha1"
 	"github.com/knative/serving/test"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
-	"log"
 	"strings"
 	"testing"
 )
@@ -43,7 +43,7 @@ func TestContainerErrorMsg(t *testing.T) {
 	// A valid DockerRepo is still needed, otherwise will get UNAUTHORIZED instead of container missing error
 	imagePath := strings.Join([]string{test.Flags.DockerRepo, "invalidhelloworld"}, "/")
 
-	log.Printf("Creating a new Route and Configuration %s", imagePath)
+	glog.Infof("Creating a new Route and Configuration %s", imagePath)
 	names, err := CreateRouteAndConfig(clients, imagePath)
 	if err != nil {
 		t.Fatalf("Failed to create Route and Configuration: %v", err)
@@ -52,7 +52,7 @@ func TestContainerErrorMsg(t *testing.T) {
 	test.CleanupOnInterrupt(func() { TearDown(clients, names) })
 
 	manifestUnknown := string(remote.ManifestUnknownErrorCode)
-	log.Println("When the imagepath is invalid, the Configuration should have error status.")
+	glog.Infof("When the imagepath is invalid, the Configuration should have error status.")
 
 	// Checking for "Container image not present in repository" scenario defined in error condition spec
 	err = test.WaitForConfigurationState(clients.Configs, names.Config, func(r *v1alpha1.Configuration) (bool, error) {
@@ -76,7 +76,7 @@ func TestContainerErrorMsg(t *testing.T) {
 		t.Fatalf("Failed to get revision from configuration %s: %v", names.Config, err)
 	}
 
-	log.Println("When the imagepath is invalid, the revision should have error status.")
+	glog.Infof("When the imagepath is invalid, the revision should have error status.")
 	err = test.WaitForRevisionState(clients.Revisions, revisionName, func(r *v1alpha1.Revision) (bool, error) {
 		cond := r.Status.GetCondition(v1alpha1.RevisionConditionReady)
 		if cond != nil {
@@ -93,7 +93,7 @@ func TestContainerErrorMsg(t *testing.T) {
 		t.Fatalf("Failed to validate revision state: %s", err)
 	}
 
-	log.Println("When the revision has error condition, logUrl should be populated.")
+	glog.Infof("When the revision has error condition, logUrl should be populated.")
 	logURL, err := getLogURLFromRevision(clients, revisionName)
 	if err != nil {
 		t.Fatalf("Failed to get logUrl from revision %s: %v", revisionName, err)

test/e2e/helloworld_test.go

@@ -18,7 +18,7 @@ limitations under the License.
 package e2e
 
 import (
-	"log"
+	"github.com/golang/glog"
 	"strings"
 	"testing"
 
@@ -43,15 +43,15 @@ func TestHelloWorld(t *testing.T) {
 	var imagePath string
 	imagePath = strings.Join([]string{test.Flags.DockerRepo, "helloworld"}, "/")
 
-	log.Println("Creating a new Route and Configuration")
+	glog.Infof("Creating a new Route and Configuration")
 	names, err := CreateRouteAndConfig(clients, imagePath)
 	if err != nil {
 		t.Fatalf("Failed to create Route and Configuration: %v", err)
 	}
 	test.CleanupOnInterrupt(func() { TearDown(clients, names) })
 	defer TearDown(clients, names)
 
-	log.Println("When the Revision can have traffic routed to it, the Route is marked as Ready.")
+	glog.Infof("When the Revision can have traffic routed to it, the Route is marked as Ready.")
 	err = test.WaitForRouteState(clients.Routes, names.Route, func(r *v1alpha1.Route) (bool, error) {
 		return r.Status.IsReady(), nil
 	})

test/e2e_flags.go

@@ -66,9 +66,9 @@ func initializeFlags() *EnvironmentFlags {
 		"Set this flag to true if you would like to see verbose logging.")
 
 	flag.Parse()
+	flag.Set("alsologtostderr", "true")
 	if f.LogVerbose {
 		// Both gLog and "go test" use -v flag. The code below is a work around so that we can still set v value for gLog
-		flag.Set("alsologtostderr", "true")
 		var logLevel string
 		flag.StringVar(&logLevel, "logLevel", fmt.Sprint(VerboseLogLevel), "verbose log level")
 		flag.Lookup("v").Value.Set(logLevel)