From 6017c23f579936342d7c978ccb08f33d40df5b00 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Roland=20Hu=C3=9F?= Date: Mon, 7 Oct 2019 20:54:08 +0200 Subject: [PATCH] chore(service): Improvements for waiting on service readiness * Increased default timeout to 600s. This timeout will be triggered only when the Ready condition stays in UNKNOWN for that long. If its True or False then the command will return anyway sooner. So it makes sense to go for a much longer timeout than 60s * Enhanced output to indicate the progress This change needs some updates to the API and introduces a 'MessageCallback' type which is calle for each intermediate event with the "Ready" condition message. --- CHANGELOG.adoc | 5 ++ docs/cmd/kn_service_create.md | 2 +- pkg/kn/commands/service/create.go | 88 +++++++++++---------- pkg/kn/commands/service/create_mock_test.go | 6 +- pkg/kn/commands/service/create_test.go | 10 +-- pkg/kn/commands/service/list_mock_test.go | 17 ++-- pkg/kn/commands/service/service.go | 28 +++++-- pkg/kn/commands/service/update.go | 12 ++- pkg/kn/commands/service/update_test.go | 2 +- pkg/kn/commands/testing_helper.go | 2 +- pkg/serving/v1alpha1/client.go | 17 +++- pkg/serving/v1alpha1/client_mock.go | 44 ++++++++--- pkg/serving/v1alpha1/client_mock_test.go | 6 +- pkg/serving/v1alpha1/client_test.go | 9 ++- pkg/wait/test_wait_helper.go | 4 +- pkg/wait/wait_for_ready.go | 42 ++++++++-- pkg/wait/wait_for_ready_test.go | 77 ++++++++++++------ test/e2e/basic_workflow_test.go | 5 +- test/e2e/service_options_test.go | 2 +- test/e2e/traffic_split_test.go | 4 +- 20 files changed, 252 insertions(+), 130 deletions(-) diff --git a/CHANGELOG.adoc b/CHANGELOG.adoc index feb98b9a04..fa21fe3ef5 100644 --- a/CHANGELOG.adoc +++ b/CHANGELOG.adoc @@ -73,6 +73,11 @@ | 🎁 | Update build.sh -w to add a message when compilation succeeded | https://github.com/knative/client/pull/432[#432] + +| 🧽 +| Add more progress information during service create/update +| https://github.com/knative/client/pull/431[#431] + |=== ## v0.2.0 (2019-07-10) diff --git a/docs/cmd/kn_service_create.md b/docs/cmd/kn_service_create.md index ee00c7a725..852144da28 100644 --- a/docs/cmd/kn_service_create.md +++ b/docs/cmd/kn_service_create.md @@ -63,7 +63,7 @@ kn service create NAME --image IMAGE [flags] --requests-memory string The requested memory (e.g., 64Mi). --revision-name string The revision name to set. Must start with the service name and a dash as a prefix. Empty revision name will result in the server generating a name for the revision. Accepts golang templates, allowing {{.Service}} for the service name, {{.Generation}} for the generation, and {{.Random [n]}} for n random consonants. (default "{{.Service}}-{{.Random 5}}-{{.Generation}}") --service-account string Service account name to set. Empty service account name will result to clear the service account. - --wait-timeout int Seconds to wait before giving up on waiting for service to be ready. (default 60) + --wait-timeout int Seconds to wait before giving up on waiting for service to be ready. (default 600) ``` ### Options inherited from parent commands diff --git a/pkg/kn/commands/service/create.go b/pkg/kn/commands/service/create.go index 2cc010a630..80d0822470 100644 --- a/pkg/kn/commands/service/create.go +++ b/pkg/kn/commands/service/create.go @@ -26,11 +26,11 @@ import ( "knative.dev/serving/pkg/apis/serving" "github.com/spf13/cobra" - serving_v1alpha1_api "knative.dev/serving/pkg/apis/serving/v1alpha1" - corev1 "k8s.io/api/core/v1" api_errors "k8s.io/apimachinery/pkg/api/errors" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + serving_kn_v1alpha1 "knative.dev/client/pkg/serving/v1alpha1" + serving_v1alpha1_api "knative.dev/serving/pkg/apis/serving/v1alpha1" ) var create_example = ` @@ -95,59 +95,57 @@ func NewServiceCreateCommand(p *commands.KnParams) *cobra.Command { return err } + out := cmd.OutOrStdout() if serviceExists { if !editFlags.ForceCreate { return fmt.Errorf( "cannot create service '%s' in namespace '%s' "+ "because the service already exists and no --force option was given", name, namespace) } - err = replaceService(client, service, namespace, cmd.OutOrStdout()) + err = replaceService(client, service, waitFlags, out) } else { - err = createService(client, service, namespace, cmd.OutOrStdout()) + err = createService(client, service, waitFlags, out) } if err != nil { return err } - - if !waitFlags.Async { - out := cmd.OutOrStdout() - err := waitForService(client, name, out, waitFlags.TimeoutInSeconds) - if err != nil { - return err - } - return showUrl(client, name, namespace, out) - } - return nil }, } commands.AddNamespaceFlags(serviceCreateCommand.Flags(), false) editFlags.AddCreateFlags(serviceCreateCommand) - waitFlags.AddConditionWaitFlags(serviceCreateCommand, 60, "Create", "service") + waitFlags.AddConditionWaitFlags(serviceCreateCommand, 600, "Create", "service") return serviceCreateCommand } -// Duck type for writers having a flush -type flusher interface { - Flush() error -} - -func flush(out io.Writer) { - if flusher, ok := out.(flusher); ok { - flusher.Flush() +func createService(client serving_kn_v1alpha1.KnServingClient, service *serving_v1alpha1_api.Service, waitFlags commands.WaitFlags, out io.Writer) error { + err := client.CreateService(service) + if err != nil { + return err } + + return waitIfRequested(client, service, waitFlags, "Creating", "created", out) } -func createService(client v1alpha1.KnServingClient, service *serving_v1alpha1_api.Service, namespace string, out io.Writer) error { - err := client.CreateService(service) +func replaceService(client serving_kn_v1alpha1.KnServingClient, service *serving_v1alpha1_api.Service, waitFlags commands.WaitFlags, out io.Writer) error { + err := prepareAndUpdateService(client, service) if err != nil { return err } - fmt.Fprintf(out, "Service '%s' successfully created in namespace '%s'.\n", service.Name, namespace) - return nil + return waitIfRequested(client, service, waitFlags, "Replacing", "replaced", out) +} + +func waitIfRequested(client serving_kn_v1alpha1.KnServingClient, service *serving_v1alpha1_api.Service, waitFlags commands.WaitFlags, verbDoing string, verbDone string, out io.Writer) error { + if waitFlags.Async { + fmt.Fprintf(out, "Service '%s' %s in namespace '%s'.\n", service.Name, verbDone, client.Namespace()) + return nil + } + + fmt.Fprintf(out, "%s service '%s' in namespace '%s':\n", verbDoing, service.Name, client.Namespace()) + return waitForServiceToGetReady(client, service.Name, waitFlags.TimeoutInSeconds, verbDone, out) } -func replaceService(client v1alpha1.KnServingClient, service *serving_v1alpha1_api.Service, namespace string, out io.Writer) error { +func prepareAndUpdateService(client serving_kn_v1alpha1.KnServingClient, service *serving_v1alpha1_api.Service) error { var retries = 0 for { existingService, err := client.GetService(service.Name) @@ -185,11 +183,29 @@ func replaceService(client v1alpha1.KnServingClient, service *serving_v1alpha1_a } return err } - fmt.Fprintf(out, "Service '%s' successfully replaced in namespace '%s'.\n", service.Name, namespace) return nil } } +func waitForServiceToGetReady(client serving_kn_v1alpha1.KnServingClient, name string, timeout int, verbDone string, out io.Writer) error { + err := waitForService(client, name, out, timeout) + if err != nil { + return err + } + return showUrl(client, name, "", verbDone, out) +} + +// Duck type for writers having a flush +type flusher interface { + Flush() error +} + +func flush(out io.Writer) { + if flusher, ok := out.(flusher); ok { + flusher.Flush() + } +} + func serviceExists(client v1alpha1.KnServingClient, name string) (bool, error) { _, err := client.GetService(name) if api_errors.IsNotFound(err) { @@ -228,17 +244,3 @@ func constructService(cmd *cobra.Command, editFlags ConfigurationEditFlags, name } return &service, nil } - -func showUrl(client v1alpha1.KnServingClient, serviceName string, namespace string, out io.Writer) error { - service, err := client.GetService(serviceName) - if err != nil { - return fmt.Errorf("cannot fetch service '%s' in namespace '%s' for extracting the URL: %v", serviceName, namespace, err) - } - url := service.Status.URL.String() - if url == "" { - url = service.Status.DeprecatedDomain - } - fmt.Fprintln(out, "\nService URL:") - fmt.Fprintf(out, "%s\n", url) - return nil -} diff --git a/pkg/kn/commands/service/create_mock_test.go b/pkg/kn/commands/service/create_mock_test.go index 105edd3d29..b8a95f1c9c 100644 --- a/pkg/kn/commands/service/create_mock_test.go +++ b/pkg/kn/commands/service/create_mock_test.go @@ -16,6 +16,7 @@ package service import ( "testing" + "time" "gotest.tools/assert" corev1 "k8s.io/api/core/v1" @@ -27,6 +28,7 @@ import ( servinglib "knative.dev/client/pkg/serving" knclient "knative.dev/client/pkg/serving/v1alpha1" + "knative.dev/client/pkg/wait" "knative.dev/client/pkg/util" ) @@ -43,14 +45,14 @@ func TestServiceCreateImageMock(t *testing.T) { // Create service (don't validate given service --> "Any()" arg is allowed) r.CreateService(knclient.Any(), nil) // Wait for service to become ready - r.WaitForService("foo", knclient.Any(), nil) + r.WaitForService("foo", knclient.Any(), wait.NoopMessageCallback(), nil, time.Second) // Get for showing the URL r.GetService("foo", getServiceWithUrl("foo", "http://foo.example.com"), nil) // Testing: output, err := executeServiceCommand(client, "create", "foo", "--image", "gcr.io/foo/bar:baz") assert.NilError(t, err) - assert.Assert(t, util.ContainsAll(output, "created", "foo", "http://foo.example.com", "Waiting")) + assert.Assert(t, util.ContainsAll(output, "Creating", "foo", "http://foo.example.com", "Ready")) // Validate that all recorded API methods have been called r.Validate() diff --git a/pkg/kn/commands/service/create_test.go b/pkg/kn/commands/service/create_test.go index 0917472aa2..3fa241638d 100644 --- a/pkg/kn/commands/service/create_test.go +++ b/pkg/kn/commands/service/create_test.go @@ -107,9 +107,9 @@ func fakeServiceCreate(args []string, withExistingService bool, sync bool) ( func getServiceEvents(name string) []watch.Event { return []watch.Event{ - {watch.Added, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "")}, - {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionTrue, "")}, - {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "")}, + {watch.Added, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "", "msg1")}, + {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionTrue, "", "msg2")}, + {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "", "")}, } } @@ -147,11 +147,11 @@ func TestServiceCreateImageSync(t *testing.T) { if template.Spec.Containers[0].Image != "gcr.io/foo/bar:baz" { t.Fatalf("wrong image set: %v", template.Spec.Containers[0].Image) } - if !strings.Contains(output, "foo") || !strings.Contains(output, "created") || + if !strings.Contains(output, "foo") || !strings.Contains(output, "Creating") || !strings.Contains(output, commands.FakeNamespace) { t.Fatalf("wrong stdout message: %v", output) } - if !strings.Contains(output, "OK") || !strings.Contains(output, "Waiting") { + if !strings.Contains(output, "Ready") { t.Fatalf("not running in sync mode") } } diff --git a/pkg/kn/commands/service/list_mock_test.go b/pkg/kn/commands/service/list_mock_test.go index ba6149446a..7049393773 100644 --- a/pkg/kn/commands/service/list_mock_test.go +++ b/pkg/kn/commands/service/list_mock_test.go @@ -17,11 +17,14 @@ package service import ( "strings" "testing" + "time" "gotest.tools/assert" "k8s.io/apimachinery/pkg/api/errors" knclient "knative.dev/client/pkg/serving/v1alpha1" "knative.dev/client/pkg/util" + "knative.dev/client/pkg/wait" + "knative.dev/serving/pkg/apis/serving/v1alpha1" ) @@ -32,17 +35,17 @@ func TestServiceListAllNamespaceMock(t *testing.T) { r.GetService("svc1", nil, errors.NewNotFound(v1alpha1.Resource("service"), "svc1")) r.CreateService(knclient.Any(), nil) - r.WaitForService("svc1", knclient.Any(), nil) + r.WaitForService("svc1", knclient.Any(), wait.NoopMessageCallback(), nil, time.Second) r.GetService("svc1", getServiceWithNamespace("svc1", "default"), nil) r.GetService("svc2", nil, errors.NewNotFound(v1alpha1.Resource("service"), "foo")) r.CreateService(knclient.Any(), nil) - r.WaitForService("svc2", knclient.Any(), nil) + r.WaitForService("svc2", knclient.Any(), wait.NoopMessageCallback(), nil, time.Second) r.GetService("svc2", getServiceWithNamespace("svc2", "foo"), nil) r.GetService("svc3", nil, errors.NewNotFound(v1alpha1.Resource("service"), "svc3")) r.CreateService(knclient.Any(), nil) - r.WaitForService("svc3", knclient.Any(), nil) + r.WaitForService("svc3", knclient.Any(), wait.NoopMessageCallback(), nil, time.Second) r.GetService("svc3", getServiceWithNamespace("svc3", "bar"), nil) r.ListServices(knclient.Any(), &v1alpha1.ServiceList{ @@ -55,15 +58,17 @@ func TestServiceListAllNamespaceMock(t *testing.T) { output, err := executeServiceCommand(client, "create", "svc1", "--image", "gcr.io/foo/bar:baz", "--namespace", "default") assert.NilError(t, err) - assert.Assert(t, util.ContainsAll(output, "created", "svc1", "default", "Waiting")) + assert.Assert(t, util.ContainsAll(output, "Creating", "svc1", "default", "Ready")) + r.Namespace("foo") output, err = executeServiceCommand(client, "create", "svc2", "--image", "gcr.io/foo/bar:baz", "--namespace", "foo") assert.NilError(t, err) - assert.Assert(t, util.ContainsAll(output, "created", "svc2", "foo", "Waiting")) + assert.Assert(t, util.ContainsAll(output, "Creating", "svc2", "foo", "Ready")) + r.Namespace("bar") output, err = executeServiceCommand(client, "create", "svc3", "--image", "gcr.io/foo/bar:baz", "--namespace", "bar") assert.NilError(t, err) - assert.Assert(t, util.ContainsAll(output, "created", "svc3", "bar", "Waiting")) + assert.Assert(t, util.ContainsAll(output, "Creating", "svc3", "bar", "Ready")) output, err = executeServiceCommand(client, "list", "--all-namespaces") assert.NilError(t, err) diff --git a/pkg/kn/commands/service/service.go b/pkg/kn/commands/service/service.go index 44dd9a3766..451ce07ee2 100644 --- a/pkg/kn/commands/service/service.go +++ b/pkg/kn/commands/service/service.go @@ -20,6 +20,7 @@ import ( "knative.dev/client/pkg/kn/commands" serving_kn_v1alpha1 "knative.dev/client/pkg/serving/v1alpha1" + "knative.dev/client/pkg/wait" "fmt" @@ -45,14 +46,29 @@ func NewServiceCommand(p *commands.KnParams) *cobra.Command { } func waitForService(client serving_kn_v1alpha1.KnServingClient, serviceName string, out io.Writer, timeout int) error { - fmt.Fprintf(out, "Waiting for service '%s' to become ready ... ", serviceName) - flush(out) - - err := client.WaitForService(serviceName, time.Duration(timeout)*time.Second) + fmt.Println("") + err, duration := client.WaitForService(serviceName, time.Duration(timeout)*time.Second, wait.SimpleMessageCallback(out)) if err != nil { - fmt.Fprintln(out) return err } - fmt.Fprintln(out, "OK") + fmt.Fprintf(out, "%7.3fs Ready to serve.\n", float64(duration.Round(time.Millisecond))/float64(time.Second)) + return nil +} + +func showUrl(client serving_kn_v1alpha1.KnServingClient, serviceName string, originalRevision string, what string, out io.Writer) error { + service, err := client.GetService(serviceName) + if err != nil { + return fmt.Errorf("cannot fetch service '%s' in namespace '%s' for extracting the URL: %v", serviceName, client.Namespace(), err) + } + url := service.Status.URL.String() + if url == "" { + url = service.Status.DeprecatedDomain + } + revisionUpdateStatus := "" + newRevision := service.Status.LatestReadyRevisionName + if originalRevision != "" && originalRevision == newRevision { + revisionUpdateStatus = " (unchanged)" + } + fmt.Fprintf(out, "\nService '%s' %s with latest revision '%s'%s and URL:\n%s\n", serviceName, what, newRevision, revisionUpdateStatus, url) return nil } diff --git a/pkg/kn/commands/service/update.go b/pkg/kn/commands/service/update.go index 090c4f18b1..3cb9f67658 100644 --- a/pkg/kn/commands/service/update.go +++ b/pkg/kn/commands/service/update.go @@ -80,12 +80,12 @@ func NewServiceUpdateCommand(p *commands.KnParams) *cobra.Command { return err } service = service.DeepCopy() - + latestRevisionBeforeUpdate := service.Status.LatestReadyRevisionName var baseRevision *v1alpha1.Revision if !cmd.Flags().Changed("image") && editFlags.LockToDigest { baseRevision, err = client.GetBaseRevision(service) if _, ok := err.(*serving.NoBaseRevisionError); ok { - fmt.Fprintf(cmd.OutOrStdout(), "Warning: No reivision found to update image digest") + fmt.Fprintf(cmd.OutOrStdout(), "Warning: No revision found to update image digest") } } err = editFlags.Apply(service, baseRevision, cmd) @@ -112,15 +112,19 @@ func NewServiceUpdateCommand(p *commands.KnParams) *cobra.Command { return err } + out := cmd.OutOrStdout() if !waitFlags.Async { - out := cmd.OutOrStdout() + fmt.Fprintf(cmd.OutOrStdout(), "Updating Service '%s' in namespace '%s':\n", args[0], namespace) err := waitForService(client, name, out, waitFlags.TimeoutInSeconds) if err != nil { return err } + return showUrl(client, name, latestRevisionBeforeUpdate, "updated", out) + } else { + fmt.Fprintf(out, "Service '%s' updated in namespace '%s'.\n", args[0], namespace) + } - fmt.Fprintf(cmd.OutOrStdout(), "Service '%s' updated in namespace '%s'.\n", args[0], namespace) return nil } }, diff --git a/pkg/kn/commands/service/update_test.go b/pkg/kn/commands/service/update_test.go index deb1774005..8f89c506a8 100644 --- a/pkg/kn/commands/service/update_test.go +++ b/pkg/kn/commands/service/update_test.go @@ -158,7 +158,7 @@ func TestServiceUpdateImageSync(t *testing.T) { assert.NilError(t, err) assert.Equal(t, template.Spec.Containers[0].Image, "gcr.io/foo/quux:xyzzy") - assert.Assert(t, util.ContainsAll(strings.ToLower(output), "update", "foo", "service", "namespace", "bar", "ok", "waiting")) + assert.Assert(t, util.ContainsAll(strings.ToLower(output), "updating", "foo", "service", "namespace", "bar", "ready")) } func TestServiceUpdateImage(t *testing.T) { diff --git a/pkg/kn/commands/testing_helper.go b/pkg/kn/commands/testing_helper.go index fd9c44aa98..470e353925 100644 --- a/pkg/kn/commands/testing_helper.go +++ b/pkg/kn/commands/testing_helper.go @@ -47,7 +47,7 @@ func CreateTestKnCommand(cmd *cobra.Command, knParams *KnParams) (*cobra.Command fakeServing := &fake.FakeServingV1alpha1{&client_testing.Fake{}} knParams.Output = buf knParams.NewClient = func(namespace string) (v1alpha1.KnServingClient, error) { - return v1alpha1.NewKnServingClient(fakeServing, namespace), nil + return v1alpha1.NewKnServingClient(fakeServing, FakeNamespace), nil } knParams.fixedCurrentNamespace = FakeNamespace knCommand := NewKnTestCommand(cmd, knParams) diff --git a/pkg/serving/v1alpha1/client.go b/pkg/serving/v1alpha1/client.go index d64fc8c69d..7dd62100ec 100644 --- a/pkg/serving/v1alpha1/client.go +++ b/pkg/serving/v1alpha1/client.go @@ -40,6 +40,9 @@ import ( // namespace specified during construction type KnServingClient interface { + // Namespace in which this client is operating for + Namespace() string + // Get a service by its unique name GetService(name string) (*v1alpha1.Service, error) @@ -55,8 +58,9 @@ type KnServingClient interface { // Delete a service by name DeleteService(name string) error - // Wait for a service to become ready, but not longer than provided timeout - WaitForService(name string, timeout time.Duration) error + // Wait for a service to become ready, but not longer than provided timeout. + // Return error and how long has been waited + WaitForService(name string, timeout time.Duration, msgCallback wait.MessageCallback) (error, time.Duration) // Get a configuration by name GetConfiguration(name string) (*v1alpha1.Configuration, error) @@ -137,6 +141,11 @@ func NewKnServingClient(client client_v1alpha1.ServingV1alpha1Interface, namespa } } +// Return the client's namespace +func (cl *knServingClient) Namespace() string { + return cl.namespace +} + // Get a service by its unique name func (cl *knServingClient) GetService(name string) (*v1alpha1.Service, error) { service, err := cl.client.Services(cl.namespace).Get(name, v1.GetOptions{}) @@ -206,9 +215,9 @@ func (cl *knServingClient) DeleteService(serviceName string) error { } // Wait for a service to become ready, but not longer than provided timeout -func (cl *knServingClient) WaitForService(name string, timeout time.Duration) error { +func (cl *knServingClient) WaitForService(name string, timeout time.Duration, msgCallback wait.MessageCallback) (error, time.Duration) { waitForReady := newServiceWaitForReady(cl.client.Services(cl.namespace).Watch) - return waitForReady.Wait(name, timeout) + return waitForReady.Wait(name, timeout, msgCallback) } // Get the configuration for a service diff --git a/pkg/serving/v1alpha1/client_mock.go b/pkg/serving/v1alpha1/client_mock.go index b8a2caa9f6..a7e40b8fd9 100644 --- a/pkg/serving/v1alpha1/client_mock.go +++ b/pkg/serving/v1alpha1/client_mock.go @@ -24,6 +24,8 @@ import ( "k8s.io/apimachinery/pkg/fields" "k8s.io/apimachinery/pkg/labels" "knative.dev/serving/pkg/apis/serving/v1alpha1" + + "knative.dev/client/pkg/wait" ) type Recorder struct { @@ -31,11 +33,15 @@ type Recorder struct { // List of recorded calls in order recordedCalls map[string][]apiMethodCall + + // Namespace for client + namespace string } type MockKnClient struct { - t *testing.T - recorder Recorder + t *testing.T + recorder Recorder + namespace string } // Recorded method call @@ -51,6 +57,7 @@ func NewMockKnClient(t *testing.T) *MockKnClient { recorder: Recorder{ t: t, recordedCalls: make(map[string][]apiMethodCall), + namespace: "default", }, } } @@ -65,6 +72,15 @@ func Any() func(t *testing.T, a interface{}) { return func(t *testing.T, a interface{}) {} } +func (r *Recorder) Namespace(namespace string) { + r.namespace = namespace +} + +// Namespace of this client +func (c *MockKnClient) Namespace() string { + return c.recorder.namespace +} + // Get Service func (r *Recorder) GetService(name interface{}, service *v1alpha1.Service, err error) { r.add("GetService", apiMethodCall{[]interface{}{name}, []interface{}{service, err}}) @@ -121,14 +137,14 @@ func (c *MockKnClient) DeleteService(name string) error { } // Wait for a service to become ready, but not longer than provided timeout -func (r *Recorder) WaitForService(name interface{}, timeout interface{}, err error) { - r.add("WaitForService", apiMethodCall{[]interface{}{name}, []interface{}{err}}) +func (r *Recorder) WaitForService(name interface{}, timeout interface{}, callback interface{}, err error, duration time.Duration) { + r.add("WaitForService", apiMethodCall{[]interface{}{name, timeout, callback}, []interface{}{err, duration}}) } -func (c *MockKnClient) WaitForService(name string, timeout time.Duration) error { +func (c *MockKnClient) WaitForService(name string, timeout time.Duration, msgCallback wait.MessageCallback) (error, time.Duration) { call := c.getCall("WaitForService") - c.verifyArgs(call, name) - return errorOrNil(call.result[0]) + c.verifyArgs(call, name, timeout, msgCallback) + return errorOrNil(call.result[0]), call.result[1].(time.Duration) } // Get a revision by name @@ -288,12 +304,18 @@ func (c *MockKnClient) verifyArgs(call *apiMethodCall, args ...interface{}) { callArgs := call.args for i, arg := range args { assert.Assert(c.t, len(callArgs) > i, "Internal: Invalid recording: Expected %d args, got %d", len(callArgs), len(args)) - fn := reflect.ValueOf(call.args[i]) + fn := reflect.ValueOf(callArgs[i]) fnType := fn.Type() - if fnType.Kind() == reflect.Func && fnType.NumIn() == 2 { - fn.Call([]reflect.Value{reflect.ValueOf(c.t), reflect.ValueOf(arg)}) + if fnType.Kind() == reflect.Func { + if fnType.NumIn() == 2 && + // It's an assertion function which takes a Testing as first parameter + fnType.In(0).AssignableTo(reflect.TypeOf(c.t)) { + fn.Call([]reflect.Value{reflect.ValueOf(c.t), reflect.ValueOf(arg)}) + } else { + assert.Assert(c.t, fnType.AssignableTo(reflect.TypeOf(arg))) + } } else { - assert.DeepEqual(c.t, call.args[i], arg) + assert.DeepEqual(c.t, callArgs[i], arg) } } } diff --git a/pkg/serving/v1alpha1/client_mock_test.go b/pkg/serving/v1alpha1/client_mock_test.go index cc2ab45076..7c2713def9 100644 --- a/pkg/serving/v1alpha1/client_mock_test.go +++ b/pkg/serving/v1alpha1/client_mock_test.go @@ -20,6 +20,8 @@ import ( api_serving "knative.dev/serving/pkg/apis/serving" "knative.dev/serving/pkg/apis/serving/v1alpha1" + + "knative.dev/client/pkg/wait" ) func TestMockKnClient(t *testing.T) { @@ -34,7 +36,7 @@ func TestMockKnClient(t *testing.T) { recorder.CreateService(&v1alpha1.Service{}, nil) recorder.UpdateService(&v1alpha1.Service{}, nil) recorder.DeleteService("hello", nil) - recorder.WaitForService("hello", time.Duration(10)*time.Second, nil) + recorder.WaitForService("hello", time.Duration(10)*time.Second, wait.NoopMessageCallback(), nil, 10*time.Second) recorder.GetRevision("hello", nil, nil) recorder.ListRevisions(Any(), nil, nil) recorder.DeleteRevision("hello", nil) @@ -48,7 +50,7 @@ func TestMockKnClient(t *testing.T) { client.CreateService(&v1alpha1.Service{}) client.UpdateService(&v1alpha1.Service{}) client.DeleteService("hello") - client.WaitForService("hello", time.Duration(10)*time.Second) + client.WaitForService("hello", time.Duration(10)*time.Second, wait.NoopMessageCallback()) client.GetRevision("hello") client.ListRevisions(WithName("blub")) client.DeleteRevision("hello") diff --git a/pkg/serving/v1alpha1/client_test.go b/pkg/serving/v1alpha1/client_test.go index 8129bb6e2e..5f549b3b90 100644 --- a/pkg/serving/v1alpha1/client_test.go +++ b/pkg/serving/v1alpha1/client_test.go @@ -390,8 +390,9 @@ func TestWaitForService(t *testing.T) { }) t.Run("wait on a service to become ready with success", func(t *testing.T) { - err := client.WaitForService(serviceName, 60*time.Second) + err, duration := client.WaitForService(serviceName, 60*time.Second, wait.NoopMessageCallback()) assert.NilError(t, err) + assert.Assert(t, duration > 0) }) } @@ -509,8 +510,8 @@ func newRoute(name string) *v1alpha1.Route { func getServiceEvents(name string) []watch.Event { return []watch.Event{ - {watch.Added, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "")}, - {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionTrue, "")}, - {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "")}, + {watch.Added, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "", "msg1")}, + {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionTrue, "", "msg2")}, + {watch.Modified, wait.CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "", "")}, } } diff --git a/pkg/wait/test_wait_helper.go b/pkg/wait/test_wait_helper.go index 82ebf85d36..050cc260ad 100644 --- a/pkg/wait/test_wait_helper.go +++ b/pkg/wait/test_wait_helper.go @@ -64,7 +64,7 @@ func (f *FakeWatch) fireEvents() { } // Create a service skeleton with a given ConditionReady status and all other statuses set to otherReadyStatus. Optionally a single generation can be added. -func CreateTestServiceWithConditions(name string, readyStatus corev1.ConditionStatus, otherReadyStatus corev1.ConditionStatus, reason string, generations ...int64) runtime.Object { +func CreateTestServiceWithConditions(name string, readyStatus corev1.ConditionStatus, otherReadyStatus corev1.ConditionStatus, reason string, message string, generations ...int64) runtime.Object { service := v1alpha1.Service{ObjectMeta: metav1.ObjectMeta{Name: name}} if len(generations) == 2 { service.Generation = generations[0] @@ -75,7 +75,7 @@ func CreateTestServiceWithConditions(name string, readyStatus corev1.ConditionSt } service.Status.Conditions = duck.Conditions([]apis.Condition{ {Type: "RoutesReady", Status: otherReadyStatus}, - {Type: apis.ConditionReady, Status: readyStatus, Reason: reason}, + {Type: apis.ConditionReady, Status: readyStatus, Reason: reason, Message: message}, {Type: "ConfigurationsReady", Status: otherReadyStatus}, }) return &service diff --git a/pkg/wait/wait_for_ready.go b/pkg/wait/wait_for_ready.go index 873e48854a..a4a67db421 100644 --- a/pkg/wait/wait_for_ready.go +++ b/pkg/wait/wait_for_ready.go @@ -16,6 +16,7 @@ package wait import ( "fmt" + "io" "time" corev1 "k8s.io/api/core/v1" @@ -38,8 +39,8 @@ type waitForReadyConfig struct { type WaitForReady interface { // Wait on resource the resource with this name until a given timeout - // and write status out on writer - Wait(name string, timeout time.Duration) error + // and write event messages for unknown event to the status writer + Wait(name string, timeout time.Duration, msgCallback MessageCallback) (error, time.Duration) } // Create watch which is used when waiting for Ready condition @@ -48,6 +49,9 @@ type WatchFunc func(opts v1.ListOptions) (watch.Interface, error) // Extract conditions from a runtime object type ConditionsExtractor func(obj runtime.Object) (apis.Conditions, error) +// Callback for event messages +type MessageCallback func(durationSinceState time.Duration, message string) + // Constructor with resource type specific configuration func NewWaitForReady(kind string, watchFunc WatchFunc, extractor ConditionsExtractor) WaitForReady { return &waitForReadyConfig{ @@ -57,11 +61,30 @@ func NewWaitForReady(kind string, watchFunc WatchFunc, extractor ConditionsExtra } } +// A simple message callback which prints out messages line by line +func SimpleMessageCallback(out io.Writer) MessageCallback { + oldMessage := "" + return func(duration time.Duration, message string) { + txt := message + if message == oldMessage { + txt = "..." + } + fmt.Fprintf(out, "%7.3fs %s\n", float64(duration.Round(time.Millisecond))/float64(time.Second), txt) + oldMessage = message + } +} + +// Noop-callback +func NoopMessageCallback() MessageCallback { + return func(durationSinceState time.Duration, message string) {} +} + // Wait until a resource enters condition of type "Ready" to "False" or "True". // `watchFunc` creates the actual watch, `kind` is the type what your are watching for // (e.g. "service"), `timeout` is a timeout after which the watch should be cancelled if no // target state has been entered yet and `out` is used for printing out status messages -func (w *waitForReadyConfig) Wait(name string, timeout time.Duration) error { +// msgCallback gets called for every event with an 'Ready' condition == UNKNOWN with the event's message. +func (w *waitForReadyConfig) Wait(name string, timeout time.Duration, msgCallback MessageCallback) (error, time.Duration) { opts := v1.ListOptions{ FieldSelector: fields.OneTermEqualSelector("metadata.name", name).String(), } @@ -70,20 +93,20 @@ func (w *waitForReadyConfig) Wait(name string, timeout time.Duration) error { floatingTimeout := timeout for { start := time.Now() - retry, timeoutReached, err := w.waitForReadyCondition(opts, name, floatingTimeout) + retry, timeoutReached, err := w.waitForReadyCondition(start, opts, name, floatingTimeout, msgCallback) if err != nil { - return err + return err, time.Since(start) } floatingTimeout = floatingTimeout - time.Since(start) if timeoutReached || floatingTimeout < 0 { - return fmt.Errorf("timeout: %s '%s' not ready after %d seconds", w.kind, name, int(timeout/time.Second)) + return fmt.Errorf("timeout: %s '%s' not ready after %d seconds", w.kind, name, int(timeout/time.Second)), time.Since(start) } if retry { // restart loop continue } - return nil + return nil, time.Since(start) } } @@ -98,7 +121,7 @@ func addWatchTimeout(opts *v1.ListOptions, timeout time.Duration) { opts.TimeoutSeconds = &timeOutWatchSeconds } -func (w *waitForReadyConfig) waitForReadyCondition(opts v1.ListOptions, name string, timeout time.Duration) (bool, bool, error) { +func (w *waitForReadyConfig) waitForReadyCondition(start time.Time, opts v1.ListOptions, name string, timeout time.Duration, msgCallback MessageCallback) (retry bool, timeoutReached bool, err error) { watcher, err := w.watchFunc(opts) if err != nil { @@ -136,6 +159,9 @@ func (w *waitForReadyConfig) waitForReadyCondition(opts v1.ListOptions, name str case corev1.ConditionFalse: return false, false, fmt.Errorf("%s: %s", cond.Reason, cond.Message) } + if cond.Message != "" { + msgCallback(time.Since(start), cond.Message) + } } } } diff --git a/pkg/wait/wait_for_ready_test.go b/pkg/wait/wait_for_ready_test.go index eb5e1f8961..242d7bae8a 100644 --- a/pkg/wait/wait_for_ready_test.go +++ b/pkg/wait/wait_for_ready_test.go @@ -18,6 +18,8 @@ import ( "testing" "time" + "gotest.tools/assert" + "gotest.tools/assert/cmp" corev1 "k8s.io/api/core/v1" v1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/runtime" @@ -27,9 +29,10 @@ import ( ) type waitForReadyTestCase struct { - events []watch.Event - timeout time.Duration - errorExpected bool + events []watch.Event + timeout time.Duration + errorExpected bool + messagesExpected []string } func TestAddWaitForReady(t *testing.T) { @@ -46,7 +49,10 @@ func TestAddWaitForReady(t *testing.T) { return apis.Conditions(obj.(*v1alpha1.Service).Status.Conditions), nil }) fakeWatchApi.Start() - err := waitForReady.Wait("foobar", tc.timeout) + var msgs []string + err, _ := waitForReady.Wait("foobar", tc.timeout, func(_ time.Duration, msg string) { + msgs = append(msgs, msg) + }) close(fakeWatchApi.eventChan) if !tc.errorExpected && err != nil { @@ -57,6 +63,9 @@ func TestAddWaitForReady(t *testing.T) { t.Errorf("%d: No error but expected one", i) } + // check messages + assert.Assert(t, cmp.DeepEqual(tc.messagesExpected, msgs), "%d: Messages expected to be equal", i) + if fakeWatchApi.StopCalled != 1 { t.Errorf("%d: Exactly one 'stop' should be called, but got %d", i, fakeWatchApi.StopCalled) } @@ -67,39 +76,59 @@ func TestAddWaitForReady(t *testing.T) { // Test cases which consists of a series of events to send and the expected behaviour. func prepareTestCases(name string) []waitForReadyTestCase { return []waitForReadyTestCase{ - {peNormal(name), time.Second, false}, - {peError(name), time.Second, true}, - {peTimeout(name), time.Second, true}, - {peWrongGeneration(name), time.Second, true}, + tc(peNormal, name, false), + tc(peError, name, true), + tc(peWrongGeneration, name, true), + tc(peTimeout, name, true), } } +func tc(f func(name string) (evts []watch.Event, nrMessages int), name string, isError bool) waitForReadyTestCase { + events, nrMsgs := f(name) + return waitForReadyTestCase{ + events, + time.Second, + isError, + pMessages(nrMsgs), + } +} + +func pMessages(max int) []string { + return []string{ + "msg1", "msg2", "msg3", "msg4", "msg5", "msg6", + }[:max] +} + // ============================================================================= -func peNormal(name string) []watch.Event { +func peNormal(name string) ([]watch.Event, int) { + messages := pMessages(2) return []watch.Event{ - {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "")}, - {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionTrue, "")}, - {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "")}, - } + {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "", messages[0])}, + {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionTrue, "", messages[1])}, + {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "", "")}, + }, len(messages) } -func peError(name string) []watch.Event { +func peError(name string) ([]watch.Event, int) { + messages := pMessages(1) return []watch.Event{ - {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "")}, - {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionFalse, corev1.ConditionTrue, "FakeError")}, - } + {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "", messages[0])}, + {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionFalse, corev1.ConditionTrue, "FakeError", "")}, + }, len(messages) } -func peTimeout(name string) []watch.Event { +func peTimeout(name string) ([]watch.Event, int) { + messages := pMessages(1) return []watch.Event{ - {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "")}, - } + {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "", messages[0])}, + }, len(messages) } -func peWrongGeneration(name string) []watch.Event { +func peWrongGeneration(name string) ([]watch.Event, int) { + messages := pMessages(1) return []watch.Event{ - {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "")}, - {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "", 1, 2)}, - } + {watch.Added, CreateTestServiceWithConditions(name, corev1.ConditionUnknown, corev1.ConditionUnknown, "", messages[0])}, + {watch.Modified, CreateTestServiceWithConditions(name, corev1.ConditionTrue, corev1.ConditionTrue, "", "", 1, 2)}, + }, len(messages) } diff --git a/test/e2e/basic_workflow_test.go b/test/e2e/basic_workflow_test.go index e18502392b..4410382fb8 100644 --- a/test/e2e/basic_workflow_test.go +++ b/test/e2e/basic_workflow_test.go @@ -83,7 +83,7 @@ func (test *e2eTest) serviceCreate(t *testing.T, serviceName string) { "--image", KnDefaultTestImage}, runOpts{NoNamespace: false}) assert.NilError(t, err) - assert.Check(t, util.ContainsAll(out, "Service", serviceName, "successfully created in namespace", test.kn.namespace, "OK")) + assert.Check(t, util.ContainsAllIgnoreCase(out, "service", serviceName, "creating", "namespace", test.kn.namespace, "ready")) } func (test *e2eTest) serviceList(t *testing.T, serviceName string) { @@ -106,8 +106,7 @@ func (test *e2eTest) serviceUpdate(t *testing.T, serviceName string, args []stri out, err := test.kn.RunWithOpts(append([]string{"service", "update", serviceName}, args...), runOpts{NoNamespace: false}) assert.NilError(t, err) - expectedOutput := fmt.Sprintf("Service '%s' updated", serviceName) - assert.Check(t, util.ContainsAll(out, expectedOutput)) + assert.Check(t, util.ContainsAllIgnoreCase(out, "updating", "service", serviceName, "ready")) } func (test *e2eTest) serviceDelete(t *testing.T, serviceName string) { diff --git a/test/e2e/service_options_test.go b/test/e2e/service_options_test.go index 2d3d813044..64881b4d40 100644 --- a/test/e2e/service_options_test.go +++ b/test/e2e/service_options_test.go @@ -85,7 +85,7 @@ func (test *e2eTest) serviceCreateWithOptions(t *testing.T, serviceName string, command = append(command, options...) out, err := test.kn.RunWithOpts(command, runOpts{NoNamespace: false}) assert.NilError(t, err) - assert.Check(t, util.ContainsAll(out, "Service", serviceName, "successfully created in namespace", test.kn.namespace, "OK")) + assert.Check(t, util.ContainsAll(out, "service", serviceName, "Creating", "namespace", test.kn.namespace, "Ready")) } func (test *e2eTest) validateServiceConcurrencyLimit(t *testing.T, serviceName, concurrencyLimit string) { diff --git a/test/e2e/traffic_split_test.go b/test/e2e/traffic_split_test.go index 162380f2aa..32f7bdb10b 100644 --- a/test/e2e/traffic_split_test.go +++ b/test/e2e/traffic_split_test.go @@ -37,7 +37,7 @@ var targetsJsonPath = "jsonpath={range .status.traffic[*]}{.tag}{','}{.revisionN // returns deployed service latest revision name var latestRevisionJsonPath = "jsonpath={.status.latestCreatedRevisionName}" -// TargetFileds are used in e2e to store expected fields per traffic target +// TargetFields are used in e2e to store expected fields per traffic target // and actual traffic targets fields of deployed service are converted into struct before comparing type TargetFields struct { Tag string @@ -385,5 +385,5 @@ func (test *e2eTest) serviceUpdateWithOptions(t *testing.T, serviceName string, command = append(command, options...) out, err := test.kn.RunWithOpts(command, runOpts{NoNamespace: false}) assert.NilError(t, err) - assert.Check(t, util.ContainsAll(out, "Service", serviceName, "update", "namespace", test.kn.namespace)) + assert.Check(t, util.ContainsAllIgnoreCase(out, "Service", serviceName, "updating", "namespace", test.kn.namespace)) }