From 119fa6537cf734f6da42316f203b7506bae215f8 Mon Sep 17 00:00:00 2001 From: Taylor Thomas Date: Fri, 26 May 2017 18:34:15 -0700 Subject: [PATCH] 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 | 8 +++++--- pkg/kube/wait.go | 7 ++++--- pkg/storage/storage.go | 26 ++++++++++++++------------ pkg/tiller/release_history.go | 1 + pkg/tiller/release_install.go | 14 ++++++++++---- pkg/tiller/release_rollback.go | 10 ++++++++-- pkg/tiller/release_server.go | 27 ++++++++++++++------------- pkg/tiller/release_testing.go | 6 +++--- pkg/tiller/release_uninstall.go | 6 +++++- pkg/tiller/release_update.go | 8 +++++++- 10 files changed, 71 insertions(+), 42 deletions(-) diff --git a/pkg/kube/client.go b/pkg/kube/client.go index 515b34418..cfa3a1daa 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 9a75add60..23da33f5a 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)