From e1b3aaef5c041677fe3862aa13cb4274fe4616dc Mon Sep 17 00:00:00 2001 From: jessiezcc <37942702+jessiezcc@users.noreply.github.com> Date: Sun, 10 Jun 2018 22:16:14 -0700 Subject: [PATCH] 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 | 10 ++++++++++ test/adding_tests.md | 8 ++++++++ test/cleanup.go | 4 ++-- test/conformance/README.md | 12 ++++-------- test/conformance/route_test.go | 20 ++++++++++---------- test/crd.go | 4 ++-- test/e2e/README.md | 6 ++---- test/e2e/autoscale_test.go | 28 ++++++++++++++-------------- test/e2e/errorcondition_test.go | 10 +++++----- test/e2e/helloworld_test.go | 6 +++--- test/e2e_flags.go | 2 +- test/request.go | 6 +++--- 12 files changed, 64 insertions(+), 52 deletions(-) diff --git a/test/README.md b/test/README.md index 79782bf27f8d..dee1610db741 100644 --- a/test/README.md +++ b/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 +``` diff --git a/test/adding_tests.md b/test/adding_tests.md index 27724ecf9791..e01c941cd1b7 100644 --- a/test/adding_tests.md +++ b/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) diff --git a/test/cleanup.go b/test/cleanup.go index 336892096d84..b7463e6b349f 100644 --- a/test/cleanup.go +++ b/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) } diff --git a/test/conformance/README.md b/test/conformance/README.md index a6448fd18196..1e0f2d8f691e 100644 --- a/test/conformance/README.md +++ b/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. diff --git a/test/conformance/route_test.go b/test/conformance/route_test.go index 8928579904e6..79f20f156d9c 100644 --- a/test/conformance/route_test.go +++ b/test/conformance/route_test.go @@ -19,7 +19,7 @@ package conformance import ( "fmt" - "log" + "github.com/golang/glog" "strings" "testing" @@ -82,13 +82,13 @@ 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 }) @@ -96,13 +96,13 @@ func assertResourcesUpdatedWhenRevisionIsReady(t *testing.T, clients *test.Clien 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 }) @@ -110,7 +110,7 @@ func assertResourcesUpdatedWhenRevisionIsReady(t *testing.T, clients *test.Clien 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) diff --git a/test/crd.go b/test/crd.go index 79a49f7423d3..fbee7b72ad93 100644 --- a/test/crd.go +++ b/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)) } diff --git a/test/e2e/README.md b/test/e2e/README.md index 492067181392..9cf03b1697ca 100644 --- a/test/e2e/README.md +++ b/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. diff --git a/test/e2e/autoscale_test.go b/test/e2e/autoscale_test.go index 8e29dc455a19..18b38821aad8 100644 --- a/test/e2e/autoscale_test.go +++ b/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,7 +82,7 @@ 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) @@ -90,7 +90,7 @@ func TestAutoscaleUpDownUp(t *testing.T) { 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,7 +130,7 @@ 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( @@ -138,28 +138,28 @@ func TestAutoscaleUpDownUp(t *testing.T) { 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,7 +170,7 @@ 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( @@ -178,7 +178,7 @@ func TestAutoscaleUpDownUp(t *testing.T) { 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) } } diff --git a/test/e2e/errorcondition_test.go b/test/e2e/errorcondition_test.go index 156c69700620..7b6a77ae93b4 100644 --- a/test/e2e/errorcondition_test.go +++ b/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) diff --git a/test/e2e/helloworld_test.go b/test/e2e/helloworld_test.go index 589196a95a6c..4c88e5b94612 100644 --- a/test/e2e/helloworld_test.go +++ b/test/e2e/helloworld_test.go @@ -18,7 +18,7 @@ limitations under the License. package e2e import ( - "log" + "github.com/golang/glog" "strings" "testing" @@ -43,7 +43,7 @@ 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) @@ -51,7 +51,7 @@ func TestHelloWorld(t *testing.T) { 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 }) diff --git a/test/e2e_flags.go b/test/e2e_flags.go index aec9a3c24d3c..476f39dda2e8 100644 --- a/test/e2e_flags.go +++ b/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) diff --git a/test/request.go b/test/request.go index 6bb4c23812f3..fe8c88bc02bb 100644 --- a/test/request.go +++ b/test/request.go @@ -20,8 +20,8 @@ package test import ( "errors" "fmt" + "github.com/golang/glog" "io/ioutil" - "log" "net/http" "time" @@ -56,7 +56,7 @@ func waitForRequestToDomainState(address string, spoofDomain string, retryableCo if resp.StatusCode != 200 { for _, code := range retryableCodes { if resp.StatusCode == code { - log.Printf("Retrying for code %v\n", resp.StatusCode) + glog.Infof("Retrying for code %v\n", resp.StatusCode) return false, nil } } @@ -94,7 +94,7 @@ func WaitForEndpointState(kubeClientset *kubernetes.Clientset, resolvableDomain endpoint = domain } - log.Println("Wait for the endpoint to be up and handling requests") + glog.Infof("Wait for the endpoint to be up and handling requests") // TODO(#348): The ingress endpoint tends to return 503's and 404's return waitForRequestToDomainState(endpoint, spoofDomain, []int{503, 404}, inState) }