Lions, tigers, and services being enabled with "precondition failed",…

… oh my! (#1565)

* Use errwrap to retain original error

* Use built-in Page function, only return names when listing services

This removes the custom logic on pagination and uses the built-in Page function in the SDK to make things a bit simpler. Additionally, I added a field filter to only return service names, which drastically reduces the size of the API call (important for slow connections, given how frequently this function is executed).

Also added errwrap to better trace where errors originate.

* Add helper function for diffing string slices

This just looked really nasty inline

* Batch 20 services at a time, handle precondition failed, better errwrap

This commit does three things:

1. It batches services to be enabled 20 at a time. The API fails if you try to enable more than 20 services, and this is documented in the SDK and API. I learned this the hard way. I think Terraform should "do the right thing" here and batch them in series' of twenty, which is what this does. Each batch is tried in serial, but I think making it parallelized is not worth the complexity tradeoffs.

2. Handle the precondition failed error that occurs randomly. This just started happened, but it affects at least two APIs consistently, and a rudimentary test showed that it failed 78% of the time (78/100 times in an hour). We should fix this upstream, but that failure rate also necessitates (in my opinion) some mitigation on the Terraform side until a fix is in place at the API level.

3. Use errwrap on errors for better tracing. It was really difficult to trace exactly which error was being throw. That's fixed.

* Updates from code review

google/resource_google_project_service.go

@@ -5,6 +5,7 @@ import (
 	"log"
 	"strings"
 
+	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/terraform/helper/schema"
 )
 
@@ -51,7 +52,7 @@ func resourceGoogleProjectServiceCreate(d *schema.ResourceData, meta interface{}
 	srv := d.Get("service").(string)
 
 	if err = enableService(srv, project, config); err != nil {
-		return fmt.Errorf("Error enabling service: %s", err)
+		return errwrap.Wrapf("Error enabling service: {{err}}", err)
 	}
 
 	d.SetId(projectServiceId{project, srv}.terraformId())

google/resource_google_project_services.go

@@ -5,7 +5,9 @@ import (
 	"log"
 	"strings"
 
+	"github.com/hashicorp/errwrap"
 	"github.com/hashicorp/terraform/helper/schema"
+	"golang.org/x/net/context"
 	"google.golang.org/api/googleapi"
 	"google.golang.org/api/serviceusage/v1beta1"
 )
@@ -185,25 +187,34 @@ func getConfigServices(d *schema.ResourceData) (services []string) {
 
 // Retrieve a project's services from the API
 func getApiServices(pid string, config *Config, ignore map[string]struct{}) ([]string, error) {
-	apiServices := make([]string, 0)
-	// Get services from the API
-	token := ""
-	for paginate := true; paginate; {
-		svcResp, err := config.clientServiceUsage.Services.List("projects/" + pid).PageToken(token).Filter("state:ENABLED").Do()
-		if err != nil {
-			return apiServices, err
-		}
-		for _, v := range svcResp.Services {
-			// names are returned as projects/{project-number}/services/{service-name}
-			nameParts := strings.Split(v.Name, "/")
-			name := nameParts[len(nameParts)-1]
-			if _, ok := ignore[name]; !ok {
-				apiServices = append(apiServices, name)
+	var apiServices []string
+
+	if ignore == nil {
+		ignore = make(map[string]struct{})
+	}
+
+	ctx := context.Background()
+	if err := config.clientServiceUsage.Services.
+		List("projects/"+pid).
+		Fields("services/name").
+		Filter("state:ENABLED").
+		Pages(ctx, func(r *serviceusage.ListServicesResponse) error {
+			for _, v := range r.Services {
+				// services are returned as "projects/PROJECT/services/NAME"
+				parts := strings.Split(v.Name, "/")
+				if len(parts) > 0 {
+					name := parts[len(parts)-1]
+					if _, ok := ignore[name]; !ok {
+						apiServices = append(apiServices, name)
+					}
+				}
 			}
-		}
-		token = svcResp.NextPageToken
-		paginate = token != ""
+
+			return nil
+		}); err != nil {
+		return nil, errwrap.Wrapf("failed to list services: {{err}}", err)
 	}
+
 	return apiServices, nil
 }
 
@@ -212,58 +223,110 @@ func enableService(s, pid string, config *Config) error {
 }
 
 func enableServices(s []string, pid string, config *Config) error {
-	err := retryTime(func() error {
-		var sop *serviceusage.Operation
-		var err error
-		if len(s) > 1 {
-			req := &serviceusage.BatchEnableServicesRequest{ServiceIds: s}
-			sop, err = config.clientServiceUsage.Services.BatchEnable("projects/"+pid, req).Do()
-		} else if len(s) == 1 {
-			name := fmt.Sprintf("projects/%s/services/%s", pid, s[0])
-			sop, err = config.clientServiceUsage.Services.Enable(name, &serviceusage.EnableServiceRequest{}).Do()
-		} else {
-			// No services to enable
-			return nil
+	// It's not permitted to enable more than 20 services in one API call (even
+	// for batch).
+	//
+	// https://godoc.org/google.golang.org/api/serviceusage/v1beta1#BatchEnableServicesRequest
+	batchSize := 20
+
+	for i := 0; i < len(s); i += batchSize {
+		j := i + batchSize
+		if j > len(s) {
+			j = len(s)
 		}
-		if err != nil {
-			return err
-		}
-		_, waitErr := serviceUsageOperationWait(config, sop, "api to enable")
-		if waitErr != nil {
-			return waitErr
-		}
-		services, err := getApiServices(pid, config, map[string]struct{}{})
-		if err != nil {
-			return err
-		}
-		var missing []string
-		for _, toEnable := range s {
-			var found bool
-			for _, service := range services {
-				if service == toEnable {
-					found = true
-					break
+
+		services := s[i:j]
+
+		if err := retryTime(func() error {
+			var sop *serviceusage.Operation
+			var err error
+
+			if len(services) < 1 {
+				// No more services to enable
+				return nil
+			} else if len(services) == 1 {
+				// Use the singular enable - can't use batch for a single item
+				name := fmt.Sprintf("projects/%s/services/%s", pid, services[0])
+				req := &serviceusage.EnableServiceRequest{}
+				sop, err = config.clientServiceUsage.Services.Enable(name, req).Do()
+			} else {
+				// Batch enable 2+ services
+				name := fmt.Sprintf("projects/%s", pid)
+				req := &serviceusage.BatchEnableServicesRequest{ServiceIds: services}
+				sop, err = config.clientServiceUsage.Services.BatchEnable(name, req).Do()
+			}
+			if err != nil {
+				// Check for a "precondition failed" error. The API seems to randomly
+				// (although more than 50%) return this error when enabling certain
+				// APIs. It's transient, so we catch it and re-raise it as an error that
+				// is retryable instead.
+				if gerr, ok := err.(*googleapi.Error); ok {
+					if (gerr.Code == 400 || gerr.Code == 412) && gerr.Message == "Precondition check failed." {
+						return &googleapi.Error{
+							Code:    503,
+							Message: "api returned \"precondition failed\" while enabling service",
+						}
+					}
 				}
+				return errwrap.Wrapf("failed to issue request: {{err}}", err)
 			}
-			if !found {
-				missing = append(missing, toEnable)
+
+			// Poll for the API to return
+			activity := fmt.Sprintf("apis %q to be enabled for %s", services, pid)
+			_, waitErr := serviceUsageOperationWait(config, sop, activity)
+			if waitErr != nil {
+				return waitErr
 			}
-		}
-		if len(missing) > 0 {
-			// spoof a googleapi Error so retryTime will try again
-			return &googleapi.Error{
-				Code:    503, // haha, get it, service unavailable
-				Message: fmt.Sprintf("The services %s are still being enabled for project %q. This isn't a real API error, this is just eventual consistency.", strings.Join(missing, ", "), pid),
+
+			// Accumulate the list of services that are enabled on the project
+			enabledServices, err := getApiServices(pid, config, nil)
+			if err != nil {
+				return err
 			}
+
+			// Diff the list of requested services to enable against the list of
+			// services on the project.
+			missing := diffStringSlice(services, enabledServices)
+
+			// If there are any missing, force a retry
+			if len(missing) > 0 {
+				// Spoof a googleapi Error so retryTime will try again
+				return &googleapi.Error{
+					Code:    503,
+					Message: fmt.Sprintf("The service(s) %q are still being enabled for project %s. This isn't a real API error, this is just eventual consistency.", missing, pid),
+				}
+			}
+
+			return nil
+		}, 10); err != nil {
+			return errwrap.Wrap(err, fmt.Errorf("failed to enable service(s) %q for project %s", services, pid))
 		}
-		return nil
-	}, 10)
-	if err != nil {
-		return fmt.Errorf("Error enabling service %q for project %q: %v", s, pid, err)
 	}
+
 	return nil
 }
 
+func diffStringSlice(wanted, actual []string) []string {
+	var missing []string
+
+	for _, want := range wanted {
+		found := false
+
+		for _, act := range actual {
+			if want == act {
+				found = true
+				break
+			}
+		}
+
+		if !found {
+			missing = append(missing, want)
+		}
+	}
+
+	return missing
+}
+
 func disableService(s, pid string, config *Config) error {
 	err := retryTime(func() error {
 		name := fmt.Sprintf("projects/%s/services/%s", pid, s)