Skip to content

Commit

Permalink
Add actionset and phase name to controller logs (#287)
Browse files Browse the repository at this point in the history 
* Add actionset and phase name to controller logs

* Address review and avoid controller test errors
  • Loading branch information
@SupriyaKasten
SupriyaKasten committed Sep 13, 2019
1 parent 5063267 commit 81bfe05
Show file tree
Hide file tree
Showing 3 changed files with 42 additions and 26 deletions.
54 changes: 30 additions & 24 deletions pkg/controller/controller.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -45,6 +45,7 @@ import (
"github.com/kanisterio/kanister/pkg/client/clientset/versioned"
"github.com/kanisterio/kanister/pkg/client/clientset/versioned/scheme"
"github.com/kanisterio/kanister/pkg/eventer"
"github.com/kanisterio/kanister/pkg/field"
"github.com/kanisterio/kanister/pkg/param"
"github.com/kanisterio/kanister/pkg/reconcile"
"github.com/kanisterio/kanister/pkg/validate"
Expand Down Expand Up @@ -154,13 +155,13 @@ func (c *Controller) onUpdate(oldObj, newObj interface{}) {
if err := c.onUpdateActionSet(old, new); err != nil {
bpName := new.Spec.Actions[0].Blueprint
bp, _ := c.crClient.CrV1alpha1().Blueprints(new.GetNamespace()).Get(bpName, v1.GetOptions{})
c.logAndErrorEvent("Callback onUpdateActionSet() failed:", "Error", err, new, bp)
c.logAndErrorEvent(nil, "Callback onUpdateActionSet() failed:", "Error", err, new, bp)

}
case *crv1alpha1.Blueprint:
new := newObj.(*crv1alpha1.Blueprint)
if err := c.onUpdateBlueprint(old, new); err != nil {
c.logAndErrorEvent("Callback onUpdateBlueprint() failed:", "Error", err, new)
c.logAndErrorEvent(nil, "Callback onUpdateBlueprint() failed:", "Error", err, new)
}
default:
log.Errorf("Unknown object type <%T>", oldObj)
Expand All @@ -173,11 +174,11 @@ func (c *Controller) onDelete(obj interface{}) {
if err := c.onDeleteActionSet(v); err != nil {
bpName := v.Spec.Actions[0].Blueprint
bp, _ := c.crClient.CrV1alpha1().Blueprints(v.GetNamespace()).Get(bpName, v1.GetOptions{})
c.logAndErrorEvent("Callback onDeleteActionSet() failed:", "Error", err, v, bp)
c.logAndErrorEvent(nil, "Callback onDeleteActionSet() failed:", "Error", err, v, bp)
}
case *crv1alpha1.Blueprint:
if err := c.onDeleteBlueprint(v); err != nil {
c.logAndErrorEvent("Callback onDeleteBlueprint() failed:", "Error", err, v)
c.logAndErrorEvent(nil, "Callback onDeleteBlueprint() failed:", "Error", err, v)
}
default:
log.Errorf("Unknown object type <%T>", obj)
Expand All @@ -204,7 +205,7 @@ func (c *Controller) onAddActionSet(as *crv1alpha1.ActionSet) error {
}

func (c *Controller) onAddBlueprint(bp *crv1alpha1.Blueprint) error {
c.logAndSuccessEvent(fmt.Sprintf("Added blueprint %s", bp.GetName()), "Added", bp)
c.logAndSuccessEvent(nil, fmt.Sprintf("Added blueprint %s", bp.GetName()), "Added", bp)
return nil
}

Expand All @@ -217,7 +218,7 @@ func (c *Controller) onUpdateActionSet(oldAS, newAS *crv1alpha1.ActionSet) error
if newAS.Status == nil {
log.Infof("Updated ActionSet '%s' Status->nil", newAS.Name)
} else if newAS.Status.State == crv1alpha1.StateComplete {
c.logAndSuccessEvent(fmt.Sprintf("Updated ActionSet '%s' Status->%s", newAS.Name, newAS.Status.State), "Update Complete", newAS)
c.logAndSuccessEvent(nil, fmt.Sprintf("Updated ActionSet '%s' Status->%s", newAS.Name, newAS.Status.State), "Update Complete", newAS)
} else {
log.Infof("Updated ActionSet '%s' Status->%s", newAS.Name, newAS.Status.State)
}
Expand Down Expand Up @@ -267,12 +268,14 @@ func (c *Controller) onDeleteBlueprint(bp *crv1alpha1.Blueprint) error {
}

func (c *Controller) initActionSetStatus(as *crv1alpha1.ActionSet) {
ctx := context.Background()
ctx = field.Context(ctx, field.ActionsetNameKey, as.GetName())
if as.Spec == nil {
log.Error("Cannot initialize an ActionSet without a spec.")
log.WithContext(ctx).Error("Cannot initialize an ActionSet without a spec.")
return
}
if as.Status != nil {
log.Error("Cannot initialize non-nil ActionSet Status")
log.WithContext(ctx).Error("Cannot initialize non-nil ActionSet Status")
return
}
as.Status = &crv1alpha1.ActionSetStatus{State: crv1alpha1.StatePending}
Expand All @@ -284,7 +287,7 @@ func (c *Controller) initActionSetStatus(as *crv1alpha1.ActionSet) {
if err != nil {
bp, _ := c.crClient.CrV1alpha1().Blueprints(as.GetNamespace()).Get(a.Blueprint, v1.GetOptions{})
reason := fmt.Sprintf("ActionSetFailed Action: %s", a.Name)
c.logAndErrorEvent("Could not get initial action:", reason, err, as, bp)
c.logAndErrorEvent(ctx, "Could not get initial action:", reason, err, as, bp)
break
}
actions = append(actions, *actionStatus)
Expand All @@ -296,7 +299,7 @@ func (c *Controller) initActionSetStatus(as *crv1alpha1.ActionSet) {
as.Status.Actions = actions
}
if _, err = c.crClient.CrV1alpha1().ActionSets(as.GetNamespace()).Update(as); err != nil {
c.logAndErrorEvent("Could not update ActionSet:", "Update Failed", err, as)
c.logAndErrorEvent(ctx, "Could not update ActionSet:", "Update Failed", err, as)
}
}

Expand Down Expand Up @@ -342,27 +345,28 @@ func (c *Controller) handleActionSet(as *crv1alpha1.ActionSet) (err error) {
return errors.WithStack(err)
}
ctx := context.Background()
ctx = field.Context(ctx, field.ActionsetNameKey, as.GetName())
for i := range as.Status.Actions {
if err = c.runAction(ctx, as, i); err != nil {
// If runAction returns an error, it is a failure in the synchronous
// part of running the action.
bpName := as.Spec.Actions[i].Blueprint
bp, _ := c.crClient.CrV1alpha1().Blueprints(as.GetNamespace()).Get(bpName, v1.GetOptions{})
reason := fmt.Sprintf("ActionSetFailed Action: %s", as.Status.Actions[i].Name)
c.logAndErrorEvent(fmt.Sprintf("Failed to launch Action %s:", as.GetName()), reason, err, as, bp)
c.logAndErrorEvent(ctx, fmt.Sprintf("Failed to launch Action %s:", as.GetName()), reason, err, as, bp)
as.Status.State = crv1alpha1.StateFailed
as.Status.Actions[i].Phases[0].State = crv1alpha1.StateFailed
_, err = c.crClient.CrV1alpha1().ActionSets(as.GetNamespace()).Update(as)
return errors.WithStack(err)
}
}
log.Infof("Created actionset %s and started executing actions", as.GetName())
log.WithContext(ctx).Infof("Created actionset %s and started executing actions", as.GetName())
return nil
}

func (c *Controller) runAction(ctx context.Context, as *crv1alpha1.ActionSet, aIDX int) error {
action := as.Spec.Actions[aIDX]
c.logAndSuccessEvent(fmt.Sprintf("Executing action %s", action.Name), "Started Action", as)
c.logAndSuccessEvent(ctx, fmt.Sprintf("Executing action %s", action.Name), "Started Action", as)
bpName := as.Spec.Actions[aIDX].Blueprint
bp, err := c.crClient.CrV1alpha1().Blueprints(as.GetNamespace()).Get(bpName, v1.GetOptions{})
if err != nil {
Expand All @@ -380,9 +384,11 @@ func (c *Controller) runAction(ctx context.Context, as *crv1alpha1.ActionSet, aI
var t *tomb.Tomb
t, ctx = tomb.WithContext(ctx)
c.actionSetTombMap.Store(as.Name, t)
ctx = field.Context(ctx, field.ActionsetNameKey, as.GetName())
t.Go(func() error {
for i, p := range phases {
c.logAndSuccessEvent(fmt.Sprintf("Executing phase %s", p.Name()), "Started Phase", as)
ctx = field.Context(ctx, field.PhaseNameKey, p.Name())
c.logAndSuccessEvent(ctx, fmt.Sprintf("Executing phase %s", p.Name()), "Started Phase", as)
err = param.InitPhaseParams(ctx, c.clientset, tp, p.Name(), p.Objects())
var output map[string]interface{}
var msg string
Expand All @@ -408,19 +414,19 @@ func (c *Controller) runAction(ctx context.Context, as *crv1alpha1.ActionSet, aI
if rErr := reconcile.ActionSet(ctx, c.crClient.CrV1alpha1(), ns, name, rf); rErr != nil {
reason := fmt.Sprintf("ActionSetFailed Action: %s", as.Spec.Actions[aIDX].Name)
msg := fmt.Sprintf("Failed to update phase: %#v:", as.Status.Actions[aIDX].Phases[i])
c.logAndErrorEvent(msg, reason, rErr, as, bp)
c.logAndErrorEvent(ctx, msg, reason, rErr, as, bp)
return nil
}
if err != nil {
reason := fmt.Sprintf("ActionSetFailed Action: %s", as.Spec.Actions[aIDX].Name)
if msg == "" {
msg = fmt.Sprintf("Failed to execute phase: %#v:", as.Status.Actions[aIDX].Phases[i])
}
c.logAndErrorEvent(msg, reason, err, as, bp)
c.logAndErrorEvent(ctx, msg, reason, err, as, bp)
return nil
}
param.UpdatePhaseParams(ctx, tp, p.Name(), output)
c.logAndSuccessEvent(fmt.Sprintf("Completed phase %s", p.Name()), "Ended Phase", as)
c.logAndSuccessEvent(ctx, fmt.Sprintf("Completed phase %s", p.Name()), "Ended Phase", as)
}
// Check if output artifacts are present
artTpls := as.Status.Actions[aIDX].Artifacts
Expand All @@ -432,7 +438,7 @@ func (c *Controller) runAction(ctx context.Context, as *crv1alpha1.ActionSet, aI
}); rErr != nil {
reason := fmt.Sprintf("ActionSetFailed Action: %s", action.Name)
msg := fmt.Sprintf("Failed to update ActionSet: %s", name)
c.logAndErrorEvent(msg, reason, err, as, bp)
c.logAndErrorEvent(ctx, msg, reason, rErr, as, bp)
}
return nil
}
Expand All @@ -455,22 +461,22 @@ func (c *Controller) runAction(ctx context.Context, as *crv1alpha1.ActionSet, aI
if aErr := reconcile.ActionSet(ctx, c.crClient.CrV1alpha1(), ns, name, af); aErr != nil {
reason := fmt.Sprintf("ActionSetFailed Action: %s", action.Name)
msg := fmt.Sprintf("Failed to update Output Artifacts: %#v:", artTpls)
c.logAndErrorEvent(msg, reason, aErr, as, bp)
c.logAndErrorEvent(ctx, msg, reason, aErr, as, bp)
return nil
}
if err != nil {
reason := fmt.Sprintf("ActionSetFailed Action: %s", action.Name)
msg := "Failed to render output artifacts"
c.logAndErrorEvent(msg, reason, err, as, bp)
c.logAndErrorEvent(ctx, msg, reason, err, as, bp)
return nil
}
return nil
})
return nil
}

func (c *Controller) logAndErrorEvent(msg, reason string, err error, objects ...runtime.Object) {
log.Errorf("%s %+v", msg, err)
func (c *Controller) logAndErrorEvent(ctx context.Context, msg, reason string, err error, objects ...runtime.Object) {
log.WithContext(ctx).Errorf("%s %+v", msg, err)
if len(objects) == 0 {
return
}
Expand All @@ -487,8 +493,8 @@ func (c *Controller) logAndErrorEvent(msg, reason string, err error, objects ...

}

func (c *Controller) logAndSuccessEvent(msg, reason string, objects ...runtime.Object) {
log.Info(msg)
func (c *Controller) logAndSuccessEvent(ctx context.Context, msg, reason string, objects ...runtime.Object) {
log.WithContext(ctx).Info(msg)
if len(objects) == 0 {
return
}
Expand Down
7 changes: 5 additions & 2 deletions pkg/controller/controller_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -32,6 +32,7 @@ import (
"github.com/kanisterio/kanister/pkg/client/clientset/versioned/scheme"
crclientv1alpha1 "github.com/kanisterio/kanister/pkg/client/clientset/versioned/typed/cr/v1alpha1"
"github.com/kanisterio/kanister/pkg/eventer"
"github.com/kanisterio/kanister/pkg/field"
"github.com/kanisterio/kanister/pkg/kube"
"github.com/kanisterio/kanister/pkg/param"
"github.com/kanisterio/kanister/pkg/poll"
Expand Down Expand Up @@ -398,10 +399,12 @@ func (s *ControllerSuite) TestRuntimeObjEventLogs(c *C) {
c.Assert(err, IsNil)

//Test the logAndErrorEvent function
ctx := context.Background()
ctx = field.Context(ctx, field.ActionsetNameKey, as.GetName())
config, err := kube.LoadConfig()
c.Assert(err, IsNil)
ctlr := New(config)
ctlr.logAndErrorEvent(msg, reason, errors.New("Testing Event Logs"), as, nilAs, bp)
ctlr.logAndErrorEvent(ctx, msg, reason, errors.New("Testing Event Logs"), as, nilAs, bp)

// Test ActionSet error event logging
events, err := s.cli.CoreV1().Events(as.Namespace).Search(scheme.Scheme, as)
Expand All @@ -424,7 +427,7 @@ func (s *ControllerSuite) TestRuntimeObjEventLogs(c *C) {

//Testing empty Blueprint
testbp := &crv1alpha1.Blueprint{}
ctlr.logAndErrorEvent(msg, reason, errors.New("Testing Event Logs"), testbp)
ctlr.logAndErrorEvent(ctx, msg, reason, errors.New("Testing Event Logs"), testbp)
events, err = s.cli.CoreV1().Events(bp.Namespace).Search(scheme.Scheme, testbp)
c.Assert(err, NotNil)
c.Assert(len(events.Items), Equals, 0)
Expand Down
7 changes: 7 additions & 0 deletions pkg/field/context.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -4,6 +4,13 @@ import "context"

// context.Context support for fields

const (
ActionsetNameKey = "ActionSet"
PodNameKey = "Pod"
ContainerNameKey = "Container"
PhaseNameKey = "Phase"
)

type contextKey uint8

const ctxKey = contextKey(43)
Expand Down

0 comments on commit 81bfe05

Please sign in to comment.