feat(tiller): Adds more logging

This builds on previous work and adds more logging to follow
the full process of installing, updating, deleting, and rolling back.
This also standardizes capitalization of logs and small formatting
fixes

pkg/kube/client.go

@@ -22,7 +22,6 @@ import (
 	goerrors "errors"
 	"fmt"
 	"io"
-	"log"
 	"strings"
 	"time"
 
@@ -86,10 +85,12 @@ func (c *Client) Create(namespace string, reader io.Reader, timeout int64, shoul
 	if err := ensureNamespace(client, namespace); err != nil {
 		return err
 	}
+	c.Log("building resources from manifest")
 	infos, buildErr := c.BuildUnstructured(namespace, reader)
 	if buildErr != nil {
 		return buildErr
 	}
+	c.Log("creating %d resource(s)", len(infos))
 	if err := perform(infos, createResource); err != nil {
 		return err
 	}
@@ -217,6 +218,7 @@ func (c *Client) Update(namespace string, originalReader, targetReader io.Reader
 		return fmt.Errorf("failed decoding reader into objects: %s", err)
 	}
 
+	c.Log("building resources from updated manifest")
 	target, err := c.BuildUnstructured(namespace, targetReader)
 	if err != nil {
 		return fmt.Errorf("failed decoding reader into objects: %s", err)
@@ -224,6 +226,7 @@ func (c *Client) Update(namespace string, originalReader, targetReader io.Reader
 
 	updateErrors := []string{}
 
+	c.Log("checking %d resources for changes", len(target))
 	err = target.Visit(func(info *resource.Info, err error) error {
 		if err != nil {
 			return err
@@ -232,7 +235,7 @@ func (c *Client) Update(namespace string, originalReader, targetReader io.Reader
 		helper := resource.NewHelper(info.Client, info.Mapping)
 		if _, err := helper.Get(info.Namespace, info.Name, info.Export); err != nil {
 			if !errors.IsNotFound(err) {
-				return fmt.Errorf("Could not get information about the resource: err: %s", err)
+				return fmt.Errorf("Could not get information about the resource: %s", err)
 			}
 
 			// Since the resource does not exist, create it.
@@ -386,7 +389,6 @@ func createPatch(mapping *meta.RESTMapping, target, current runtime.Object) ([]b
 	case err != nil:
 		return nil, types.StrategicMergePatchType, fmt.Errorf("failed to get versionedObject: %s", err)
 	default:
-		log.Printf("generating strategic merge patch for %T", target)
 		patch, err := strategicpatch.CreateTwoWayMergePatch(oldData, newData, versionedObject)
 		return patch, types.StrategicMergePatchType, err
 	}

pkg/kube/wait.go

@@ -17,7 +17,6 @@ limitations under the License.
 package kube // import "k8s.io/helm/pkg/kube"
 
 import (
-	"log"
 	"time"
 
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -44,7 +43,7 @@ type deployment struct {
 // waitForResources polls to get the current status of all pods, PVCs, and Services
 // until all are ready or a timeout is reached
 func (c *Client) waitForResources(timeout time.Duration, created Result) error {
-	log.Printf("beginning wait for resources with timeout of %v", timeout)
+	c.Log("beginning wait for %d resources with timeout of %v", len(created), timeout)
 
 	cs, err := c.ClientSet()
 	if err != nil {
@@ -121,7 +120,9 @@ func (c *Client) waitForResources(timeout time.Duration, created Result) error {
 				services = append(services, *svc)
 			}
 		}
-		return podsReady(pods) && servicesReady(services) && volumesReady(pvc) && deploymentsReady(deployments), nil
+		isReady := podsReady(pods) && servicesReady(services) && volumesReady(pvc) && deploymentsReady(deployments)
+		c.Log("resources ready: %v", isReady)
+		return isReady, nil
 	})
 }
 

pkg/storage/storage.go

@@ -41,7 +41,7 @@ type Storage struct {
 // if the storage driver failed to fetch the release, or the
 // release identified by the key, version pair does not exist.
 func (s *Storage) Get(name string, version int32) (*rspb.Release, error) {
-	s.Log("Getting release %q", makeKey(name, version))
+	s.Log("getting release %q", makeKey(name, version))
 	return s.Driver.Get(makeKey(name, version))
 }
 
@@ -49,7 +49,7 @@ func (s *Storage) Get(name string, version int32) (*rspb.Release, error) {
 // error is returned if the storage driver failed to store the
 // release, or a release with identical an key already exists.
 func (s *Storage) Create(rls *rspb.Release) error {
-	s.Log("Creating release %q", makeKey(rls.Name, rls.Version))
+	s.Log("creating release %q", makeKey(rls.Name, rls.Version))
 	return s.Driver.Create(makeKey(rls.Name, rls.Version), rls)
 }
 
@@ -57,7 +57,7 @@ func (s *Storage) Create(rls *rspb.Release) error {
 // storage backend fails to update the release or if the release
 // does not exist.
 func (s *Storage) Update(rls *rspb.Release) error {
-	s.Log("Updating release %q", makeKey(rls.Name, rls.Version))
+	s.Log("updating release %q", makeKey(rls.Name, rls.Version))
 	return s.Driver.Update(makeKey(rls.Name, rls.Version), rls)
 }
 
@@ -65,21 +65,21 @@ func (s *Storage) Update(rls *rspb.Release) error {
 // the storage backend fails to delete the release or if the release
 // does not exist.
 func (s *Storage) Delete(name string, version int32) (*rspb.Release, error) {
-	s.Log("Deleting release %q", makeKey(name, version))
+	s.Log("deleting release %q", makeKey(name, version))
 	return s.Driver.Delete(makeKey(name, version))
 }
 
 // ListReleases returns all releases from storage. An error is returned if the
 // storage backend fails to retrieve the releases.
 func (s *Storage) ListReleases() ([]*rspb.Release, error) {
-	s.Log("Listing all releases in storage")
+	s.Log("listing all releases in storage")
 	return s.Driver.List(func(_ *rspb.Release) bool { return true })
 }
 
 // ListDeleted returns all releases with Status == DELETED. An error is returned
 // if the storage backend fails to retrieve the releases.
 func (s *Storage) ListDeleted() ([]*rspb.Release, error) {
-	s.Log("Listing deleted releases in storage")
+	s.Log("listing deleted releases in storage")
 	return s.Driver.List(func(rls *rspb.Release) bool {
 		return relutil.StatusFilter(rspb.Status_DELETED).Check(rls)
 	})
@@ -88,7 +88,7 @@ func (s *Storage) ListDeleted() ([]*rspb.Release, error) {
 // ListDeployed returns all releases with Status == DEPLOYED. An error is returned
 // if the storage backend fails to retrieve the releases.
 func (s *Storage) ListDeployed() ([]*rspb.Release, error) {
-	s.Log("Listing all deployed releases in storage")
+	s.Log("listing all deployed releases in storage")
 	return s.Driver.List(func(rls *rspb.Release) bool {
 		return relutil.StatusFilter(rspb.Status_DEPLOYED).Check(rls)
 	})
@@ -98,7 +98,7 @@ func (s *Storage) ListDeployed() ([]*rspb.Release, error) {
 // (filter0 && filter1 && ... && filterN), i.e. a Release is included in the results
 // if and only if all filters return true.
 func (s *Storage) ListFilterAll(fns ...relutil.FilterFunc) ([]*rspb.Release, error) {
-	s.Log("Listing all releases with filter")
+	s.Log("listing all releases with filter")
 	return s.Driver.List(func(rls *rspb.Release) bool {
 		return relutil.All(fns...).Check(rls)
 	})
@@ -108,7 +108,7 @@ func (s *Storage) ListFilterAll(fns ...relutil.FilterFunc) ([]*rspb.Release, err
 // (filter0 || filter1 || ... || filterN), i.e. a Release is included in the results
 // if at least one of the filters returns true.
 func (s *Storage) ListFilterAny(fns ...relutil.FilterFunc) ([]*rspb.Release, error) {
-	s.Log("Listing any releases with filter")
+	s.Log("listing any releases with filter")
 	return s.Driver.List(func(rls *rspb.Release) bool {
 		return relutil.Any(fns...).Check(rls)
 	})
@@ -117,7 +117,7 @@ func (s *Storage) ListFilterAny(fns ...relutil.FilterFunc) ([]*rspb.Release, err
 // Deployed returns the deployed release with the provided release name, or
 // returns ErrReleaseNotFound if not found.
 func (s *Storage) Deployed(name string) (*rspb.Release, error) {
-	s.Log("Getting deployed release from %q history", name)
+	s.Log("getting deployed release from %q history", name)
 
 	ls, err := s.Driver.Query(map[string]string{
 		"NAME":   name,
@@ -137,14 +137,14 @@ func (s *Storage) Deployed(name string) (*rspb.Release, error) {
 // History returns the revision history for the release with the provided name, or
 // returns ErrReleaseNotFound if no such release name exists.
 func (s *Storage) History(name string) ([]*rspb.Release, error) {
-	s.Log("Getting release history for %q", name)
+	s.Log("getting release history for %q", name)
 
 	return s.Driver.Query(map[string]string{"NAME": name, "OWNER": "TILLER"})
 }
 
 // Last fetches the last revision of the named release.
 func (s *Storage) Last(name string) (*rspb.Release, error) {
-	s.Log("Getting last revision of %q", name)
+	s.Log("getting last revision of %q", name)
 	h, err := s.History(name)
 	if err != nil {
 		return nil, err
@@ -159,6 +159,7 @@ func (s *Storage) Last(name string) (*rspb.Release, error) {
 
 // LockRelease gains a mutually exclusive access to a release via a mutex.
 func (s *Storage) LockRelease(name string) error {
+	s.Log("locking release %s", name)
 	s.releaseLocksLock.Lock()
 	defer s.releaseLocksLock.Unlock()
 
@@ -191,6 +192,7 @@ func (s *Storage) LockRelease(name string) error {
 // UnlockRelease releases a mutually exclusive access to a release.
 // If release doesn't exist or wasn't previously locked - the unlock will pass
 func (s *Storage) UnlockRelease(name string) {
+	s.Log("unlocking release %s", name)
 	s.releaseLocksLock.Lock()
 	defer s.releaseLocksLock.Unlock()
 

pkg/tiller/release_history.go

@@ -25,6 +25,7 @@ import (
 
 // GetHistory gets the history for a given release.
 func (s *ReleaseServer) GetHistory(ctx context.Context, req *tpb.GetHistoryRequest) (*tpb.GetHistoryResponse, error) {
+	s.Log("getting history for release %s", req.Name)
 	h, err := s.env.Releases.History(req.Name)
 	if err != nil {
 		return nil, err

pkg/tiller/release_install.go

@@ -18,6 +18,8 @@ package tiller
 
 import (
 	"fmt"
+	"strings"
+
 	ctx "golang.org/x/net/context"
 	"k8s.io/helm/pkg/chartutil"
 	"k8s.io/helm/pkg/hooks"
@@ -25,14 +27,14 @@ import (
 	"k8s.io/helm/pkg/proto/hapi/services"
 	relutil "k8s.io/helm/pkg/releaseutil"
 	"k8s.io/helm/pkg/timeconv"
-	"strings"
 )
 
 // InstallRelease installs a release and stores the release record.
 func (s *ReleaseServer) InstallRelease(c ctx.Context, req *services.InstallReleaseRequest) (*services.InstallReleaseResponse, error) {
+	s.Log("preparing install for %s", req.Name)
 	rel, err := s.prepareRelease(req)
 	if err != nil {
-		s.Log("Failed install prepare step: %s", err)
+		s.Log("failed install prepare step: %s", err)
 		res := &services.InstallReleaseResponse{Release: rel}
 
 		// On dry run, append the manifest contents to a failed release. This is
@@ -43,9 +45,10 @@ func (s *ReleaseServer) InstallRelease(c ctx.Context, req *services.InstallRelea
 		return res, err
 	}
 
+	s.Log("performing install for %s", req.Name)
 	res, err := s.performRelease(rel, req)
 	if err != nil {
-		s.Log("Failed install perform step: %s", err)
+		s.Log("failed install perform step: %s", err)
 	}
 	return res, err
 }
@@ -132,7 +135,7 @@ func (s *ReleaseServer) performRelease(r *release.Release, req *services.Install
 	res := &services.InstallReleaseResponse{Release: r}
 
 	if req.DryRun {
-		s.Log("Dry run for %s", r.Name)
+		s.Log("dry run for %s", r.Name)
 		res.Release.Info.Description = "Dry run complete"
 		return res, nil
 	}
@@ -142,11 +145,14 @@ func (s *ReleaseServer) performRelease(r *release.Release, req *services.Install
 		if err := s.execHook(r.Hooks, r.Name, r.Namespace, hooks.PreInstall, req.Timeout); err != nil {
 			return res, err
 		}
+	} else {
+		s.Log("install hooks disabled for %s", req.Name)
 	}
 
 	switch h, err := s.env.Releases.History(req.Name); {
 	// if this is a replace operation, append to the release history
 	case req.ReuseName && err == nil && len(h) >= 1:
+		s.Log("name reuse for %s requested, replacing release", req.Name)
 		// get latest release revision
 		relutil.Reverse(h, relutil.SortByRevision)
 

pkg/tiller/release_rollback.go

@@ -18,6 +18,7 @@ package tiller
 
 import (
 	"fmt"
+
 	ctx "golang.org/x/net/context"
 	"k8s.io/helm/pkg/hooks"
 	"k8s.io/helm/pkg/proto/hapi/release"
@@ -33,17 +34,20 @@ func (s *ReleaseServer) RollbackRelease(c ctx.Context, req *services.RollbackRel
 	}
 	defer s.env.Releases.UnlockRelease(req.Name)
 
+	s.Log("preparing rollback of %s", req.Name)
 	currentRelease, targetRelease, err := s.prepareRollback(req)
 	if err != nil {
 		return nil, err
 	}
 
+	s.Log("performing rollback of %s", req.Name)
 	res, err := s.performRollback(currentRelease, targetRelease, req)
 	if err != nil {
 		return res, err
 	}
 
 	if !req.DryRun {
+		s.Log("creating rolled back release %s", req.Name)
 		if err := s.env.Releases.Create(targetRelease); err != nil {
 			return res, err
 		}
@@ -108,7 +112,7 @@ func (s *ReleaseServer) performRollback(currentRelease, targetRelease *release.R
 	res := &services.RollbackReleaseResponse{Release: targetRelease}
 
 	if req.DryRun {
-		s.Log("Dry run for %s", targetRelease.Name)
+		s.Log("dry run for %s", targetRelease.Name)
 		return res, nil
 	}
 
@@ -117,6 +121,8 @@ func (s *ReleaseServer) performRollback(currentRelease, targetRelease *release.R
 		if err := s.execHook(targetRelease.Hooks, targetRelease.Name, targetRelease.Namespace, hooks.PreRollback, req.Timeout); err != nil {
 			return res, err
 		}
+	} else {
+		s.Log("rollback hooks disabled for %s", req.Name)
 	}
 
 	if err := s.ReleaseModule.Rollback(currentRelease, targetRelease, req, s.env); err != nil {

pkg/tiller/release_server.go

@@ -113,13 +113,13 @@ func NewReleaseServer(env *environment.Environment, clientset internalclientset.
 func (s *ReleaseServer) reuseValues(req *services.UpdateReleaseRequest, current *release.Release) error {
 	if req.ResetValues {
 		// If ResetValues is set, we comletely ignore current.Config.
-		s.Log("Reset values to the chart's original version.")
+		s.Log("resetting values to the chart's original version")
 		return nil
 	}
 
 	// If the ReuseValues flag is set, we always copy the old values over the new config's values.
 	if req.ReuseValues {
-		s.Log("Reusing the old release's values")
+		s.Log("reusing the old release's values")
 
 		// We have to regenerate the old coalesced values:
 		oldVals, err := chartutil.CoalesceValues(current.Chart, current.Config)
@@ -142,7 +142,7 @@ func (s *ReleaseServer) reuseValues(req *services.UpdateReleaseRequest, current
 		current.Config != nil &&
 		current.Config.Raw != "" &&
 		current.Config.Raw != "{}\n" {
-		s.Log("Copying values from %s (v%d) to new release.", current.Name, current.Version)
+		s.Log("copying values from %s (v%d) to new release.", current.Name, current.Version)
 		req.Values = current.Config
 	}
 	return nil
@@ -168,13 +168,13 @@ func (s *ReleaseServer) uniqName(start string, reuse bool) (string, error) {
 
 		if st := rel.Info.Status.Code; reuse && (st == release.Status_DELETED || st == release.Status_FAILED) {
 			// Allowe re-use of names if the previous release is marked deleted.
-			s.Log("reusing name %q", start)
+			s.Log("name %s exists but is not in use, reusing name", start)
 			return start, nil
 		} else if reuse {
 			return "", errors.New("cannot re-use a name that is still in use")
 		}
 
-		return "", fmt.Errorf("a release named %q already exists.\nPlease run: helm ls --all %q; helm del --help", start, start)
+		return "", fmt.Errorf("a release named %s already exists.\nRun: helm ls --all %s; to check the status of the release\nOr run: helm del --purge %s; to delete it", start, start, start)
 	}
 
 	maxTries := 5
@@ -187,7 +187,7 @@ func (s *ReleaseServer) uniqName(start string, reuse bool) (string, error) {
 		if _, err := s.env.Releases.Get(name, 1); strings.Contains(err.Error(), "not found") {
 			return name, nil
 		}
-		s.Log("info: Name %q is taken. Searching again.", name)
+		s.Log("info: generated name %s is taken. Searching again.", name)
 	}
 	s.Log("warning: No available release names found after %d tries", maxTries)
 	return "ERROR", errors.New("no available release name found")
@@ -249,6 +249,7 @@ func (s *ReleaseServer) renderResources(ch *chart.Chart, values chartutil.Values
 		return nil, nil, "", fmt.Errorf("Chart incompatible with Tiller %s", sver)
 	}
 
+	s.Log("rendering %s chart using values", ch.GetMetadata().Name)
 	renderer := s.engine(ch)
 	files, err := renderer.Render(ch, values)
 	if err != nil {
@@ -306,10 +307,10 @@ func (s *ReleaseServer) renderResources(ch *chart.Chart, values chartutil.Values
 func (s *ReleaseServer) recordRelease(r *release.Release, reuse bool) {
 	if reuse {
 		if err := s.env.Releases.Update(r); err != nil {
-			s.Log("warning: Failed to update release %q: %s", r.Name, err)
+			s.Log("warning: Failed to update release %s: %s", r.Name, err)
 		}
 	} else if err := s.env.Releases.Create(r); err != nil {
-		s.Log("warning: Failed to record release %q: %s", r.Name, err)
+		s.Log("warning: Failed to record release %s: %s", r.Name, err)
 	}
 }
 
@@ -317,10 +318,10 @@ func (s *ReleaseServer) execHook(hs []*release.Hook, name, namespace, hook strin
 	kubeCli := s.env.KubeClient
 	code, ok := events[hook]
 	if !ok {
-		return fmt.Errorf("unknown hook %q", hook)
+		return fmt.Errorf("unknown hook %s", hook)
 	}
 
-	s.Log("Executing %s hooks for %s", hook, name)
+	s.Log("executing %d %s hooks for %s", len(hs), hook, name)
 	executingHooks := []*release.Hook{}
 	for _, h := range hs {
 		for _, e := range h.Events {
@@ -336,20 +337,20 @@ func (s *ReleaseServer) execHook(hs []*release.Hook, name, namespace, hook strin
 
 		b := bytes.NewBufferString(h.Manifest)
 		if err := kubeCli.Create(namespace, b, timeout, false); err != nil {
-			s.Log("warning: Release %q %s %s failed: %s", name, hook, h.Path, err)
+			s.Log("warning: Release %s %s %s failed: %s", name, hook, h.Path, err)
 			return err
 		}
 		// No way to rewind a bytes.Buffer()?
 		b.Reset()
 		b.WriteString(h.Manifest)
 		if err := kubeCli.WatchUntilReady(namespace, b, timeout, false); err != nil {
-			s.Log("warning: Release %q %s %s could not complete: %s", name, hook, h.Path, err)
+			s.Log("warning: Release %s %s %s could not complete: %s", name, hook, h.Path, err)
 			return err
 		}
 		h.LastRun = timeconv.Now()
 	}
 
-	s.Log("Hooks complete for %s %s", hook, name)
+	s.Log("hooks complete for %s %s", hook, name)
 	return nil
 }
 

pkg/tiller/release_testing.go

@@ -41,15 +41,15 @@ func (s *ReleaseServer) RunReleaseTest(req *services.TestReleaseRequest, stream
 		Timeout:    req.Timeout,
 		Stream:     stream,
 	}
-
+	s.Log("running tests for release %s", rel.Name)
 	tSuite, err := reltesting.NewTestSuite(rel)
 	if err != nil {
-		s.Log("Error creating test suite for %s", rel.Name)
+		s.Log("error creating test suite for %s: %s", rel.Name, err)
 		return err
 	}
 
 	if err := tSuite.Run(testEnv); err != nil {
-		s.Log("Error running test suite for %s", rel.Name)
+		s.Log("error running test suite for %s: %s", rel.Name, err)
 		return err
 	}
 

pkg/tiller/release_uninstall.go

@@ -18,13 +18,14 @@ package tiller
 
 import (
 	"fmt"
+	"strings"
+
 	ctx "golang.org/x/net/context"
 	"k8s.io/helm/pkg/hooks"
 	"k8s.io/helm/pkg/proto/hapi/release"
 	"k8s.io/helm/pkg/proto/hapi/services"
 	relutil "k8s.io/helm/pkg/releaseutil"
 	"k8s.io/helm/pkg/timeconv"
-	"strings"
 )
 
 // UninstallRelease deletes all of the resources associated with this release, and marks the release DELETED.
@@ -79,6 +80,8 @@ func (s *ReleaseServer) UninstallRelease(c ctx.Context, req *services.UninstallR
 		if err := s.execHook(rel.Hooks, rel.Name, rel.Namespace, hooks.PreDelete, req.Timeout); err != nil {
 			return res, err
 		}
+	} else {
+		s.Log("delete hooks disabled for %s", req.Name)
 	}
 
 	// From here on out, the release is currently considered to be in Status_DELETING
@@ -106,6 +109,7 @@ func (s *ReleaseServer) UninstallRelease(c ctx.Context, req *services.UninstallR
 	rel.Info.Description = "Deletion complete"
 
 	if req.Purge {
+		s.Log("purge requested for %s", req.Name)
 		err := s.purgeReleases(rels...)
 		if err != nil {
 			s.Log("uninstall: Failed to purge the release: %s", err)

pkg/tiller/release_update.go

@@ -18,6 +18,7 @@ package tiller
 
 import (
 	"fmt"
+
 	ctx "golang.org/x/net/context"
 	"k8s.io/helm/pkg/chartutil"
 	"k8s.io/helm/pkg/hooks"
@@ -34,17 +35,20 @@ func (s *ReleaseServer) UpdateRelease(c ctx.Context, req *services.UpdateRelease
 	}
 	defer s.env.Releases.UnlockRelease(req.Name)
 
+	s.Log("preparing update for %s", req.Name)
 	currentRelease, updatedRelease, err := s.prepareUpdate(req)
 	if err != nil {
 		return nil, err
 	}
 
+	s.Log("performing update for %s", req.Name)
 	res, err := s.performUpdate(currentRelease, updatedRelease, req)
 	if err != nil {
 		return res, err
 	}
 
 	if !req.DryRun {
+		s.Log("creating updated release for %s", req.Name)
 		if err := s.env.Releases.Create(updatedRelease); err != nil {
 			return res, err
 		}
@@ -129,7 +133,7 @@ func (s *ReleaseServer) performUpdate(originalRelease, updatedRelease *release.R
 	res := &services.UpdateReleaseResponse{Release: updatedRelease}
 
 	if req.DryRun {
-		s.Log("Dry run for %s", updatedRelease.Name)
+		s.Log("dry run for %s", updatedRelease.Name)
 		res.Release.Info.Description = "Dry run complete"
 		return res, nil
 	}
@@ -139,6 +143,8 @@ func (s *ReleaseServer) performUpdate(originalRelease, updatedRelease *release.R
 		if err := s.execHook(updatedRelease.Hooks, updatedRelease.Name, updatedRelease.Namespace, hooks.PreUpgrade, req.Timeout); err != nil {
 			return res, err
 		}
+	} else {
+		s.Log("update hooks disabled for %s", req.Name)
 	}
 	if err := s.ReleaseModule.Update(originalRelease, updatedRelease, req, s.env); err != nil {
 		msg := fmt.Sprintf("Upgrade %q failed: %s", updatedRelease.Name, err)