From 10a030330160072b005cb64cdbf33b1739131c95 Mon Sep 17 00:00:00 2001 From: George Blue Date: Fri, 12 Mar 2021 12:01:35 +0000 Subject: [PATCH] chore: log concurrent ID when running examples (#200) - this makes it easier to work out which log line relates to which example - also logs a summary at the end [#177317568](https://www.pivotaltracker.com/story/show/177317568) --- cmd/client.go | 15 +-- cmd/pak.go | 6 +- pkg/brokerpak/cmd.go | 11 +- pkg/client/example-runner.go | 243 +++++++++++++++++++---------------- pkg/client/example_logger.go | 30 +++++ 5 files changed, 175 insertions(+), 130 deletions(-) create mode 100644 pkg/client/example_logger.go diff --git a/cmd/client.go b/cmd/client.go index 596713745..7094fca69 100644 --- a/cmd/client.go +++ b/cmd/client.go @@ -137,17 +137,14 @@ user-defined plans. log.Fatalf("Error creating client: %v", err) } - if exampleName != "" && serviceName == "" { + switch { + case exampleName != "" && serviceName == "": log.Fatalf("If an example name is specified, you must provide an accompanying service name.") - } else if fileName != "" { - if err := client.RunExamplesFromFile(apiClient, fileName, serviceName, exampleName); err != nil { - log.Fatalf("Error executing examples from file: %v", err) - } - } else if err := client.RunExamplesForService(server.GetExamplesFromServer(), apiClient, serviceName, exampleName, exampleJobCount); err != nil { - log.Fatalf("Error executing examples: %v", err) + case fileName != "": + client.RunExamplesFromFile(apiClient, fileName, serviceName, exampleName) + default: + client.RunExamplesForService(server.GetExamplesFromServer(), apiClient, serviceName, exampleName, exampleJobCount) } - - log.Println("Success") }, } diff --git a/cmd/pak.go b/cmd/pak.go index 837979aef..07b47f3cb 100644 --- a/cmd/pak.go +++ b/cmd/pak.go @@ -141,11 +141,7 @@ dependencies, services it provides, and the contents. Short: "run the examples from a brokerpak", Args: cobra.ExactArgs(1), Run: func(cmd *cobra.Command, args []string) { - if err := brokerpak.RunExamples(args[0]); err != nil { - log.Fatalf("Error executing examples: %v", err) - } - - log.Println("Success") + brokerpak.RunExamples(args[0]) }, }) diff --git a/pkg/brokerpak/cmd.go b/pkg/brokerpak/cmd.go index c53c912f6..727562c48 100644 --- a/pkg/brokerpak/cmd.go +++ b/pkg/brokerpak/cmd.go @@ -17,6 +17,7 @@ package brokerpak import ( "fmt" "io" + "log" "os" "path/filepath" "text/tabwriter" @@ -173,23 +174,23 @@ func RegisterAll(registry broker.BrokerRegistry) error { } // RunExamples executes the examples from a brokerpak. -func RunExamples(pack string) error { +func RunExamples(pack string) { registry, err := registryFromLocalBrokerpak(pack) if err != nil { - return err + log.Fatalf("Error executing examples (registry): %v", err) } apiClient, err := client.NewClientFromEnv() if err != nil { - return err + log.Fatalf("Error executing examples (client): %v", err) } allExamples, err := server.GetAllCompleteServiceExamples(registry) if err != nil { - return err + log.Fatalf("Error executing examples (getting): %v", err) } - return client.RunExamplesForService(allExamples, apiClient, "", "", 1) + client.RunExamplesForService(allExamples, apiClient, "", "", 1) } // Docs generates the markdown usage docs for the given pack and writes them to stdout. diff --git a/pkg/client/example-runner.go b/pkg/client/example-runner.go index cbe51a7aa..ad478558e 100644 --- a/pkg/client/example-runner.go +++ b/pkg/client/example-runner.go @@ -34,73 +34,98 @@ import ( // the service broker pointed to by client. All examples in the registry get run // if serviceName is blank. If exampleName is non-blank then only the example // with the given name is run. -func RunExamplesForService(allExamples []CompleteServiceExample, client *Client, serviceName, exampleName string, jobCount int) error { - - rand.Seed(time.Now().UTC().UnixNano()) - - examples := make(chan CompleteServiceExample) - errors := make(chan error) - wg := &sync.WaitGroup{} - - go func() { - defer close(examples) - for _, completeServiceExample := range FilterMatchingServiceExamples(allExamples, serviceName, exampleName) { - examples <- completeServiceExample - } - }() - - for i := 0; i < jobCount; i++ { - wg.Add(1) - go func() { - defer wg.Done() - for example := range examples { - if err := RunExample(client, example); err != nil { - errors <- err - } - } - }() - } - - go func() { - wg.Wait() - close(errors) - }() - - var err error - for err = range errors { - } - - return err +func RunExamplesForService(allExamples []CompleteServiceExample, client *Client, serviceName, exampleName string, jobCount int) { + runExamples(jobCount, client, FilterMatchingServiceExamples(allExamples, serviceName, exampleName)) } // RunExamplesFromFile reads a json-encoded list of CompleteServiceExamples. // All examples in the list get run if serviceName is blank. If exampleName // is non-blank then only the example with the given name is run. -func RunExamplesFromFile(client *Client, fileName, serviceName, exampleName string) error { - - rand.Seed(time.Now().UTC().UnixNano()) - - jsonFile, err := os.Open(fileName) - +func RunExamplesFromFile(client *Client, fileName, serviceName, exampleName string) { + // ioutil is deprecated in Go 1.16, but the replacement os.ReadFile is not available in Go 1.14 + data, err := ioutil.ReadFile(fileName) if err != nil { log.Fatalf("Error opening file: %v", err) } - defer jsonFile.Close() - var allExamples []CompleteServiceExample + json.Unmarshal(data, &allExamples) - byteValue, _ := ioutil.ReadAll(jsonFile) - json.Unmarshal(byteValue, &allExamples) + runExamples(1, client, FilterMatchingServiceExamples(allExamples, serviceName, exampleName)) +} - for _, completeServiceExample := range FilterMatchingServiceExamples(allExamples, serviceName, exampleName) { - if err := RunExample(client, completeServiceExample); err != nil { - return err - } +func runExamples(workers int, client *Client, examples []CompleteServiceExample) { + rand.Seed(time.Now().UTC().UnixNano()) + + type result struct { + id string + name string + duration time.Duration + err error + } + var results []result + var resultsLock sync.Mutex + addResult := func(r result) { + resultsLock.Lock() + defer resultsLock.Unlock() + results = append(results, r) } - return nil + type work struct { + id string + example CompleteServiceExample + } + queue := make(chan work) + var wg sync.WaitGroup + wg.Add(workers) + for i := 0; i < workers; i++ { + go func() { + for w := range queue { + start := time.Now() + err := runExample(client, w.id, w.example) + addResult(result{ + id: w.id, + name: w.example.Name, + duration: time.Since(start), + err: err, + }) + } + wg.Done() + }() + } + for i, e := range examples { + queue <- work{ + id: fmt.Sprintf("%03d", i), + example: e, + } + } + close(queue) + wg.Wait() + + failed := 0 + log.Println() + log.Println("RESULTS:") + log.Println() + log.Println("id | name | duration | result") + log.Println("-- | ---- | -------- | ------") + for _, r := range results { + switch r.err { + case nil: + log.Printf("%s | %s | %s | PASS\n", r.id, r.name, r.duration) + default: + failed++ + log.Printf("%s | %s | %s | FAILED %s\n", r.id, r.name, r.duration, r.err) + } + } + log.Println() + + switch failed { + case 0: + log.Println("Success") + default: + log.Fatalf("FAILED %d examples", failed) + } } type CompleteServiceExample struct { @@ -154,24 +179,24 @@ func FilterMatchingServiceExamples(allExamples []CompleteServiceExample, service // RunExample runs a single example against the given service on the broker // pointed to by client. -func RunExample(client *Client, serviceExample CompleteServiceExample) error { - - executor, err := newExampleExecutor(client, serviceExample) +func runExample(client *Client, id string, serviceExample CompleteServiceExample) error { + logger := newExampleLogger(id) + executor, err := newExampleExecutor(logger, id, client, serviceExample) if err != nil { return err } - executor.LogTestInfo() + executor.LogTestInfo(logger) // Cleanup the test if it fails partway through defer func() { - log.Println("Cleaning up the environment") + logger.Println("Cleaning up the environment") executor.Unbind() executor.Deprovision() }() if err := executor.Provision(); err != nil { - log.Printf("Failed to provision %v: %v", serviceExample.ServiceName, err) + logger.Printf("Failed to provision %v: %v", serviceExample.ServiceName, err) return err } @@ -236,40 +261,7 @@ func retry(timeout, period time.Duration, function func() (tryAgain bool, err er } } -func pollUntilFinished(client *Client, instanceId string) error { - return retry(45*time.Minute, 30*time.Second, func() (bool, error) { - log.Println("Polling for async job") - - resp := client.LastOperation(instanceId) - if resp.InError() { - return false, resp.Error - } - - if resp.StatusCode != 200 { - log.Printf("Bad status code %d, needed 200", resp.StatusCode) - return false, fmt.Errorf("broker responded with statuscode %v", resp.StatusCode) - } - - var responseBody map[string]string - err := json.Unmarshal(resp.ResponseBody, &responseBody) - if err != nil { - return false, err - } - - state := responseBody["state"] - eq := state == string(brokerapi.Succeeded) - - if state == string(brokerapi.Failed) { - log.Printf("Last operation for %q was %q: %s\n", instanceId, state, responseBody["description"]) - return false, fmt.Errorf(responseBody["description"]) - } - - log.Printf("Last operation for %q was %q\n", instanceId, state) - return !eq, nil - }) -} - -func newExampleExecutor(client *Client, serviceExample CompleteServiceExample) (*exampleExecutor, error) { +func newExampleExecutor(logger *exampleLogger, id string, client *Client, serviceExample CompleteServiceExample) (*exampleExecutor, error) { provisionParams, err := json.Marshal(serviceExample.ServiceExample.ProvisionParams) if err != nil { return nil, err @@ -280,18 +272,17 @@ func newExampleExecutor(client *Client, serviceExample CompleteServiceExample) ( return nil, err } - testid := rand.Uint32() - return &exampleExecutor{ Name: fmt.Sprintf("%s/%s", serviceExample.ServiceName, serviceExample.ServiceExample.Name), ServiceId: serviceExample.ServiceId, PlanId: serviceExample.ServiceExample.PlanId, - InstanceId: fmt.Sprintf("ex%d-%s", testid, os.ExpandEnv("${USER}")), - BindingId: fmt.Sprintf("ex%d", testid), + InstanceId: fmt.Sprintf("ex%s-%s", id, os.ExpandEnv("${USER}")), + BindingId: fmt.Sprintf("ex%s", id), ProvisionParams: provisionParams, BindParams: bindParams, + logger: logger, client: client, }, nil } @@ -307,6 +298,7 @@ type exampleExecutor struct { ProvisionParams json.RawMessage BindParams json.RawMessage + logger *exampleLogger client *Client } @@ -316,11 +308,11 @@ type exampleExecutor struct { // If the response is an async result, Provision will attempt to wait until // the Provision is complete. func (ee *exampleExecutor) Provision() error { - log.Printf("Provisioning %s\n", ee.Name) + ee.logger.Printf("Provisioning %s\n", ee.Name) resp := ee.client.Provision(ee.InstanceId, ee.ServiceId, ee.PlanId, ee.ProvisionParams) - log.Println(resp.String()) + ee.logger.Println(resp.String()) if resp.InError() { return resp.Error } @@ -336,15 +328,44 @@ func (ee *exampleExecutor) Provision() error { } func (ee *exampleExecutor) pollUntilFinished() error { - return pollUntilFinished(ee.client, ee.InstanceId) + return retry(45*time.Minute, 30*time.Second, func() (bool, error) { + ee.logger.Println("Polling for async job") + + resp := ee.client.LastOperation(ee.InstanceId) + if resp.InError() { + return false, resp.Error + } + + if resp.StatusCode != 200 { + ee.logger.Printf("Bad status code %d, needed 200", resp.StatusCode) + return false, fmt.Errorf("broker responded with statuscode %v", resp.StatusCode) + } + + var responseBody map[string]string + err := json.Unmarshal(resp.ResponseBody, &responseBody) + if err != nil { + return false, err + } + + state := responseBody["state"] + eq := state == string(brokerapi.Succeeded) + + if state == string(brokerapi.Failed) { + ee.logger.Printf("Last operation for %q was %q: %s\n", ee.InstanceId, state, responseBody["description"]) + return false, fmt.Errorf(responseBody["description"]) + } + + ee.logger.Printf("Last operation for %q was %q\n", ee.InstanceId, state) + return !eq, nil + }) } // Deprovision destroys the instance created by a call to Provision. func (ee *exampleExecutor) Deprovision() error { - log.Printf("Deprovisioning %s\n", ee.Name) + ee.logger.Printf("Deprovisioning %s\n", ee.Name) resp := ee.client.Deprovision(ee.InstanceId, ee.ServiceId, ee.PlanId) - log.Println(resp.String()) + ee.logger.Println(resp.String()) if resp.InError() { return resp.Error } @@ -362,10 +383,10 @@ func (ee *exampleExecutor) Deprovision() error { // Unbind unbinds the exact binding created by a call to Bind. func (ee *exampleExecutor) Unbind() error { return retry(15*time.Minute, 15*time.Second, func() (bool, error) { - log.Printf("Unbinding %s\n", ee.Name) + ee.logger.Printf("Unbinding %s\n", ee.Name) resp := ee.client.Unbind(ee.InstanceId, ee.BindingId, ee.ServiceId, ee.PlanId) - log.Println(resp.String()) + ee.logger.Println(resp.String()) if resp.InError() { return false, resp.Error } @@ -382,10 +403,10 @@ func (ee *exampleExecutor) Unbind() error { // once successfully as subsequent binds will attempt to create bindings with // the same ID. func (ee *exampleExecutor) Bind() (json.RawMessage, error) { - log.Printf("Binding %s\n", ee.Name) + ee.logger.Printf("Binding %s\n", ee.Name) resp := ee.client.Bind(ee.InstanceId, ee.BindingId, ee.ServiceId, ee.PlanId, ee.BindParams) - log.Println(resp.String()) + ee.logger.Println(resp.String()) if resp.InError() { return nil, resp.Error } @@ -399,12 +420,12 @@ func (ee *exampleExecutor) Bind() (json.RawMessage, error) { // LogTestInfo writes information about the running example and a manual backout // strategy if the test dies part of the way through. -func (ee *exampleExecutor) LogTestInfo() { - log.Printf("Running Example: %s\n", ee.Name) +func (ee *exampleExecutor) LogTestInfo(logger *exampleLogger) { + logger.Printf("Running Example: %s\n", ee.Name) ips := fmt.Sprintf("--instanceid %q --planid %q --serviceid %q", ee.InstanceId, ee.PlanId, ee.ServiceId) - log.Printf("cloud-service-broker client provision %s --params %q\n", ips, ee.ProvisionParams) - log.Printf("cloud-service-broker client bind %s --bindingid %q --params %q\n", ips, ee.BindingId, ee.BindParams) - log.Printf("cloud-service-broker client unbind %s --bindingid %q\n", ips, ee.BindingId) - log.Printf("cloud-service-broker client deprovision %s\n", ips) + logger.Printf("cloud-service-broker client provision %s --params %q\n", ips, ee.ProvisionParams) + logger.Printf("cloud-service-broker client bind %s --bindingid %q --params %q\n", ips, ee.BindingId, ee.BindParams) + logger.Printf("cloud-service-broker client unbind %s --bindingid %q\n", ips, ee.BindingId) + logger.Printf("cloud-service-broker client deprovision %s\n", ips) } diff --git a/pkg/client/example_logger.go b/pkg/client/example_logger.go new file mode 100644 index 000000000..966bea8ef --- /dev/null +++ b/pkg/client/example_logger.go @@ -0,0 +1,30 @@ +package client + +import ( + "fmt" + "log" +) + +type exampleLogger struct { + id string +} + +func newExampleLogger(id string) *exampleLogger { + return &exampleLogger{id: id} +} + +func (l *exampleLogger) Println(s string) { + log.Println(l.format(s)) +} + +func (l *exampleLogger) Printf(format string, v ...interface{}) { + log.Printf(l.format(format), v...) +} + +func (l *exampleLogger) Fatalf(format string, v ...interface{}) { + log.Fatalf(l.format(format), v...) +} + +func (l *exampleLogger) format(format string) string { + return fmt.Sprintf("(id=%s): %s", l.id, format) +}