diff --git a/pkg/kube/client.go b/pkg/kube/client.go index 28fb5c9cd..bd917f817 100644 --- a/pkg/kube/client.go +++ b/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 } diff --git a/pkg/kube/wait.go b/pkg/kube/wait.go index 960e06bf2..d917d79ed 100644 --- a/pkg/kube/wait.go +++ b/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 }) } diff --git a/pkg/storage/storage.go b/pkg/storage/storage.go index 48a41fd12..b5aa16ccb 100644 --- a/pkg/storage/storage.go +++ b/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() diff --git a/pkg/tiller/release_history.go b/pkg/tiller/release_history.go index 63f4275e9..09131fad8 100644 --- a/pkg/tiller/release_history.go +++ b/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 diff --git a/pkg/tiller/release_install.go b/pkg/tiller/release_install.go index 7ebd90d40..79b7b6354 100644 --- a/pkg/tiller/release_install.go +++ b/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) diff --git a/pkg/tiller/release_rollback.go b/pkg/tiller/release_rollback.go index be542c793..43e06a6b6 100644 --- a/pkg/tiller/release_rollback.go +++ b/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 } @@ -53,7 +57,7 @@ func (s *ReleaseServer) RollbackRelease(c ctx.Context, req *services.RollbackRel } // prepareRollback finds the previous release and prepares a new release object with -// the previous release's configuration +// the previous release's configuration func (s *ReleaseServer) prepareRollback(req *services.RollbackReleaseRequest) (*release.Release, *release.Release, error) { switch { case !ValidName.MatchString(req.Name): @@ -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 { diff --git a/pkg/tiller/release_server.go b/pkg/tiller/release_server.go index d71f5285c..07ea872df 100644 --- a/pkg/tiller/release_server.go +++ b/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 } diff --git a/pkg/tiller/release_testing.go b/pkg/tiller/release_testing.go index 4a5fa317c..4f9a38a96 100644 --- a/pkg/tiller/release_testing.go +++ b/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 } diff --git a/pkg/tiller/release_uninstall.go b/pkg/tiller/release_uninstall.go index a0c7fc9d7..8f7846d68 100644 --- a/pkg/tiller/release_uninstall.go +++ b/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) diff --git a/pkg/tiller/release_update.go b/pkg/tiller/release_update.go index f6051a64f..fb30d1661 100644 --- a/pkg/tiller/release_update.go +++ b/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)