Merge lp:~thumper/juju-core/refactor-uniter-tests into lp:~go-bot/juju-core/trunk

[Tim Penhey]

Refactor uniter tests

We needed to have a better way to match the hooks that had been executed by
the uniter in the tests. Instead of relying on log messages that the hooks
wrote out, instead we have the uniter optionally call out to an observer.

Part of this work also involved breaking up some of the larger methods in the
Context and the Uniter methods. These broken up bits are used by the code
that runs generic commands coming shortly.

A fundamental change is that now if a hook is missing, instead of silently
passing, the context now returns a missingHookError.

https://codereview.appspot.com/41210043/

Refactor uniter tests

We needed to have a better way to match the hooks that had been executed by
the uniter in the tests. Instead of relying on log messages that the hooks
wrote out, instead we have the uniter optionally call out to an observer.

Part of this work also involved breaking up some of the larger methods in the
Context and the Uniter methods. These broken up bits are used by the code
that runs generic commands coming shortly.

A fundamental change is that now if a hook is missing, instead of silently
passing, the context now returns a missingHookError.

https://codereview.appspot.com/41210043/

[Tim Penhey (thumper)]

Reviewers: mp+198668_code.launchpad.net,

Message:
Please take a look.

Description:
Refactor uniter tests

We needed to have a better way to match the hooks that had been executed
by
the uniter in the tests. Instead of relying on log messages that the
hooks
wrote out, instead we have the uniter optionally call out to an
observer.

Part of this work also involved breaking up some of the larger methods
in the
Context and the Uniter methods. These broken up bits are used by the
code
that runs generic commands coming shortly.

A fundamental change is that now if a hook is missing, instead of
silently
passing, the context now returns a missingHookError.

https://code.launchpad.net/~thumper/juju-core/refactor-uniter-tests/+merge/198668

Requires:
https://code.launchpad.net/~thumper/juju-core/juju-run-listener/+merge/198662

(do not edit description out of merge proposal)

Please review this at https://codereview.appspot.com/41210043/

Affected files (+181, -109 lines):
   A [revision details]
   M worker/uniter/context.go
   M worker/uniter/context_test.go
   A worker/uniter/export_test.go
   M worker/uniter/uniter.go
   M worker/uniter/uniter_test.go

[Ian Booth (wallyworld)]

LGTM with some tweaks

https://codereview.appspot.com/41210043/diff/1/worker/uniter/context.go
File worker/uniter/context.go (right):

https://codereview.appspot.com/41210043/diff/1/worker/uniter/context.go#newcode191
worker/uniter/context.go:191: writeChanges := err == nil
Why not just make writeChanges a method param?
And set it accordingly in the caller if the err the caller has is nil?

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter.go
File worker/uniter/uniter.go (right):

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter.go#newcode35
worker/uniter/uniter.go:35: type UniterExecutionObserver interface {
Doc string please

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter_test.go
File worker/uniter/uniter_test.go (left):

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter_test.go#oldcode192
worker/uniter/uniter_test.go:192: func (ctx *context) matchLogHooks(c
*gc.C) (match bool, overshoot bool) {
Is this still the best method name?

https://codereview.appspot.com/41210043/

[Tim Penhey (thumper)]

Please take a look.

https://codereview.appspot.com/41210043/diff/1/worker/uniter/context.go
File worker/uniter/context.go (right):

https://codereview.appspot.com/41210043/diff/1/worker/uniter/context.go#newcode191
worker/uniter/context.go:191: writeChanges := err == nil
On 2013/12/13 00:23:11, wallyworld wrote:
> Why not just make writeChanges a method param?
> And set it accordingly in the caller if the err the caller has is nil?

Because doing it this way makes the caller much cleaner, and we need the
error anyway as we return that if it is not-nil.

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter.go
File worker/uniter/uniter.go (right):

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter.go#newcode35
worker/uniter/uniter.go:35: type UniterExecutionObserver interface {
On 2013/12/13 00:23:11, wallyworld wrote:
> Doc string please

Done.

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter_test.go
File worker/uniter/uniter_test.go (left):

https://codereview.appspot.com/41210043/diff/1/worker/uniter/uniter_test.go#oldcode192
worker/uniter/uniter_test.go:192: func (ctx *context) matchLogHooks(c
*gc.C) (match bool, overshoot bool) {
On 2013/12/13 00:23:11, wallyworld wrote:
> Is this still the best method name?

Haha, ah, no. I'll change to something more meaningful.

https://codereview.appspot.com/41210043/

=== modified file 'worker/uniter/context.go'
--- worker/uniter/context.go	2013-10-04 17:38:30 +0000
+++ worker/uniter/context.go	2013-12-13 02:48:10 +0000
@@ -22,6 +22,19 @@
 	"launchpad.net/juju-core/worker/uniter/jujuc"
 )
 
+type missingHookError struct {
+	hookName string
+}
+
+func (e *missingHookError) Error() string {
+	return e.hookName + " does not exist"
+}
+
+func IsMissingHookError(err error) bool {
+	_, ok := err.(*missingHookError)
+	return ok
+}
+
 // HookContext is the implementation of jujuc.Context.
 type HookContext struct {
 	unit *uniter.Unit
@@ -174,25 +187,14 @@
 	return vars
 }
 
-// RunHook executes a hook in an environment which allows it to to call back
-// into ctx to execute jujuc tools.
-func (ctx *HookContext) RunHook(hookName, charmDir, toolsDir, socketPath string) error {
-	var err error
-	env := ctx.hookVars(charmDir, toolsDir, socketPath)
-	debugctx := unitdebug.NewHooksContext(ctx.unit.Name())
-	if session, _ := debugctx.FindSession(); session != nil && session.MatchHook(hookName) {
-		logger.Infof("executing %s via debug-hooks", hookName)
-		err = session.RunHook(hookName, charmDir, env)
-	} else {
-		err = runCharmHook(hookName, charmDir, env)
-	}
-	write := err == nil
+func (ctx *HookContext) finalizeContext(process string, err error) error {
+	writeChanges := err == nil
 	for id, rctx := range ctx.relations {
-		if write {
+		if writeChanges {
 			if e := rctx.WriteSettings(); e != nil {
 				e = fmt.Errorf(
 					"could not write settings from %q to relation %d: %v",
-					hookName, id, e,
+					process, id, e,
 				)
 				logger.Errorf("%v", e)
 				if err == nil {
@@ -205,6 +207,21 @@
 	return err
 }
 
+// RunHook executes a hook in an environment which allows it to to call back
+// into ctx to execute jujuc tools.
+func (ctx *HookContext) RunHook(hookName, charmDir, toolsDir, socketPath string) error {
+	var err error
+	env := ctx.hookVars(charmDir, toolsDir, socketPath)
+	debugctx := unitdebug.NewHooksContext(ctx.unit.Name())
+	if session, _ := debugctx.FindSession(); session != nil && session.MatchHook(hookName) {
+		logger.Infof("executing %s via debug-hooks", hookName)
+		err = session.RunHook(hookName, charmDir, env)
+	} else {
+		err = runCharmHook(hookName, charmDir, env)
+	}
+	return ctx.finalizeContext(hookName, err)
+}
+
 func runCharmHook(hookName, charmDir string, env []string) error {
 	ps := exec.Command(filepath.Join(charmDir, "hooks", hookName))
 	ps.Env = env
@@ -230,7 +247,7 @@
 		if os.IsNotExist(ee.Err) {
 			// Missing hook is perfectly valid, but worth mentioning.
 			logger.Infof("skipped %q hook (not implemented)", hookName)
-			return nil
+			return &missingHookError{hookName}
 		}
 	}
 	return err
 
=== modified file 'worker/uniter/context_test.go'
--- worker/uniter/context_test.go	2013-11-14 12:32:14 +0000
+++ worker/uniter/context_test.go	2013-12-13 02:48:10 +0000
@@ -19,6 +19,7 @@
 	"launchpad.net/juju-core/state/api"
 	"launchpad.net/juju-core/state/api/params"
 	apiuniter "launchpad.net/juju-core/state/api/uniter"
+	jc "launchpad.net/juju-core/testing/checkers"
 	"launchpad.net/juju-core/utils"
 	"launchpad.net/juju-core/worker/uniter"
 	"launchpad.net/juju-core/worker/uniter/jujuc"
@@ -206,9 +207,10 @@
 	uuid, err := utils.NewUUID()
 	c.Assert(err, gc.IsNil)
 	for i, t := range runHookTests {
-		c.Logf("test %d: %s; perm %v", i, t.summary, t.spec.perm)
+		c.Logf("\ntest %d: %s; perm %v", i, t.summary, t.spec.perm)
 		ctx := s.GetHookContext(c, uuid.String(), t.relid, t.remote)
 		var charmDir, outPath string
+		var hookExists bool
 		if t.spec.perm == 0 {
 			charmDir = c.MkDir()
 		} else {
@@ -216,12 +218,15 @@
 			spec.name = "something-happened"
 			c.Logf("makeCharm %#v", spec)
 			charmDir, outPath = makeCharm(c, spec)
+			hookExists = true
 		}
 		toolsDir := c.MkDir()
 		t0 := time.Now()
 		err := ctx.RunHook("something-happened", charmDir, toolsDir, "/path/to/socket")
-		if t.err == "" {
+		if t.err == "" && hookExists {
 			c.Assert(err, gc.IsNil)
+		} else if !hookExists {
+			c.Assert(uniter.IsMissingHookError(err), jc.IsTrue)
 		} else {
 			c.Assert(err, gc.ErrorMatches, t.err)
 		}
 
=== added file 'worker/uniter/export_test.go'
--- worker/uniter/export_test.go	1970-01-01 00:00:00 +0000
+++ worker/uniter/export_test.go	2013-12-13 02:48:10 +0000
@@ -0,0 +1,8 @@
+// Copyright 2013 Canonical Ltd.
+// Licensed under the AGPLv3, see LICENCE file for details.
+
+package uniter
+
+func SetUniterObserver(u *Uniter, observer UniterExecutionObserver) {
+	u.observer = observer
+}
 
=== modified file 'worker/uniter/uniter.go'
--- worker/uniter/uniter.go	2013-11-14 12:32:14 +0000
+++ worker/uniter/uniter.go	2013-12-13 02:48:10 +0000
@@ -32,6 +32,14 @@
 
 var logger = loggo.GetLogger("juju.worker.uniter")
 
+// A UniterExecutionObserver gets the appropriate methods called when a hook
+// is executed and either succeeds or fails.  Missing hooks don't get reported
+// in this way.
+type UniterExecutionObserver interface {
+	HookCompleted(hookName string)
+	HookFailed(hookName string)
+}
+
 // Uniter implements the capabilities of the unit agent. It is not intended to
 // implement the actual *behaviour* of the unit agent; that responsibility is
 // delegated to Mode values, which are expected to react to events and direct
@@ -59,6 +67,9 @@
 	hookLock     *fslock.Lock
 
 	ranConfigChanged bool
+	// The execution observer is only used in tests at this stage. Should this
+	// need to be extended, perhaps a list of observers would be needed.
+	observer UniterExecutionObserver
 }
 
 // NewUniter creates a new Uniter which will install, run, and upgrade
@@ -274,23 +285,26 @@
 // operation is not affected by the error.
 var errHookFailed = stderrors.New("hook execution failed")
 
-// runHook executes the supplied hook.Info in an appropriate hook context. If
-// the hook itself fails to execute, it returns errHookFailed.
-func (u *Uniter) runHook(hi hook.Info) (err error) {
-	// Prepare context.
-	if err = hi.Validate(); err != nil {
-		return err
-	}
-
-	hookName := string(hi.Kind)
-	relationId := -1
-	if hi.Kind.IsRelation() {
-		relationId = hi.RelationId
-		if hookName, err = u.relationers[relationId].PrepareHook(hi); err != nil {
-			return err
-		}
-	}
-	hctxId := fmt.Sprintf("%s:%s:%d", u.unit.Name(), hookName, u.rand.Int63())
+func (u *Uniter) getHookContext(hctxId string, relationId int, remoteUnitName string) (context *HookContext, err error) {
+
+	apiAddrs, err := u.st.APIAddresses()
+	if err != nil {
+		return nil, err
+	}
+	ownerTag, err := u.service.GetOwnerTag()
+	if err != nil {
+		return nil, err
+	}
+	ctxRelations := map[int]*ContextRelation{}
+	for id, r := range u.relationers {
+		ctxRelations[id] = r.Context()
+	}
+
+	return NewHookContext(u.unit, hctxId, u.uuid, relationId, remoteUnitName,
+		ctxRelations, apiAddrs, ownerTag)
+}
+
+func (u *Uniter) acquireHookLock(message string) (err error) {
 	// We want to make sure we don't block forever when locking, but take the
 	// tomb into account.
 	checkTomb := func() error {
@@ -302,48 +316,88 @@
 		}
 		return nil
 	}
-	lockMessage := fmt.Sprintf("%s: running hook %q", u.unit.Name(), hookName)
-	if err = u.hookLock.LockWithFunc(lockMessage, checkTomb); err != nil {
-		return err
-	}
-	defer u.hookLock.Unlock()
-
-	ctxRelations := map[int]*ContextRelation{}
-	for id, r := range u.relationers {
-		ctxRelations[id] = r.Context()
-	}
-	apiAddrs, err := u.st.APIAddresses()
-	if err != nil {
-		return err
-	}
-
-	ownerTag, err := u.service.GetOwnerTag()
-	if err != nil {
-		return err
-	}
-	hctx, err := NewHookContext(u.unit, hctxId, u.uuid, relationId, hi.RemoteUnit,
-		ctxRelations, apiAddrs, ownerTag)
-	if err != nil {
-		return err
-	}
-
+	if err = u.hookLock.LockWithFunc(message, checkTomb); err != nil {
+		return err
+	}
+	return nil
+}
+
+func (u *Uniter) startJujucServer(context *HookContext) (*jujuc.Server, string, error) {
 	// Prepare server.
 	getCmd := func(ctxId, cmdName string) (cmd.Command, error) {
 		// TODO: switch to long-running server with single context;
 		// use nonce in place of context id.
-		if ctxId != hctxId {
-			return nil, fmt.Errorf("expected context id %q, got %q", hctxId, ctxId)
+		if ctxId != context.id {
+			return nil, fmt.Errorf("expected context id %q, got %q", context.id, ctxId)
 		}
-		return jujuc.NewCommand(hctx, cmdName)
+		return jujuc.NewCommand(context, cmdName)
 	}
 	socketPath := filepath.Join(u.baseDir, "agent.socket")
 	// Use abstract namespace so we don't get stale socket files.
 	socketPath = "@" + socketPath
 	srv, err := jujuc.NewServer(getCmd, socketPath)
 	if err != nil {
-		return err
+		return nil, "", err
 	}
 	go srv.Run()
+	return srv, socketPath, nil
+}
+
+func (u *Uniter) notifyHookInternal(hook string, hctx *HookContext, method func(string)) {
+	if r, ok := hctx.HookRelation(); ok {
+		remote, _ := hctx.RemoteUnitName()
+		if remote != "" {
+			remote = " " + remote
+		}
+		hook = hook + remote + " " + r.FakeId()
+	}
+	method(hook)
+}
+
+func (u *Uniter) notifyHookCompleted(hook string, hctx *HookContext) {
+	if u.observer != nil {
+		u.notifyHookInternal(hook, hctx, u.observer.HookCompleted)
+	}
+}
+
+func (u *Uniter) notifyHookFailed(hook string, hctx *HookContext) {
+	if u.observer != nil {
+		u.notifyHookInternal(hook, hctx, u.observer.HookFailed)
+	}
+}
+
+// runHook executes the supplied hook.Info in an appropriate hook context. If
+// the hook itself fails to execute, it returns errHookFailed.
+func (u *Uniter) runHook(hi hook.Info) (err error) {
+	// Prepare context.
+	if err = hi.Validate(); err != nil {
+		return err
+	}
+
+	hookName := string(hi.Kind)
+	relationId := -1
+	if hi.Kind.IsRelation() {
+		relationId = hi.RelationId
+		if hookName, err = u.relationers[relationId].PrepareHook(hi); err != nil {
+			return err
+		}
+	}
+	hctxId := fmt.Sprintf("%s:%s:%d", u.unit.Name(), hookName, u.rand.Int63())
+
+	lockMessage := fmt.Sprintf("%s: running hook %q", u.unit.Name(), hookName)
+	if err = u.acquireHookLock(lockMessage); err != nil {
+		return err
+	}
+	defer u.hookLock.Unlock()
+
+	hctx, err := u.getHookContext(hctxId, relationId, hi.RemoteUnit)
+	if err != nil {
+		return err
+	}
+	srv, socketPath, err := u.startJujucServer(hctx)
+	if err != nil {
+		return err
+	}
 	defer srv.Close()
 
 	// Run the hook.
@@ -351,14 +405,24 @@
 		return err
 	}
 	logger.Infof("running %q hook", hookName)
-	if err := hctx.RunHook(hookName, u.charm.Path(), u.toolsDir, socketPath); err != nil {
+	ranHook := true
+	err = hctx.RunHook(hookName, u.charm.Path(), u.toolsDir, socketPath)
+	if IsMissingHookError(err) {
+		ranHook = false
+	} else if err != nil {
 		logger.Errorf("hook failed: %s", err)
+		u.notifyHookFailed(hookName, hctx)
 		return errHookFailed
 	}
 	if err := u.writeState(RunHook, Done, &hi, nil); err != nil {
 		return err
 	}
-	logger.Infof("ran %q hook", hookName)
+	if ranHook {
+		logger.Infof("ran %q hook", hookName)
+		u.notifyHookCompleted(hookName, hctx)
+	} else {
+		logger.Infof("skipped %q hook (missing)", hookName)
+	}
 	return u.commitHook(hi)
 }
 
 
=== modified file 'worker/uniter/uniter_test.go'
--- worker/uniter/uniter_test.go	2013-11-07 09:09:55 +0000
+++ worker/uniter/uniter_test.go	2013-12-13 02:48:10 +0000
@@ -14,9 +14,7 @@
 	"os"
 	"os/exec"
 	"path/filepath"
-	"regexp"
 	"strconv"
-	"strings"
 	stdtesting "testing"
 	"time"
 
@@ -32,7 +30,7 @@
 	"launchpad.net/juju-core/state/api/params"
 	apiuniter "launchpad.net/juju-core/state/api/uniter"
 	coretesting "launchpad.net/juju-core/testing"
-	"launchpad.net/juju-core/testing/checkers"
+	jc "launchpad.net/juju-core/testing/checkers"
 	"launchpad.net/juju-core/utils"
 	"launchpad.net/juju-core/utils/fslock"
 	"launchpad.net/juju-core/worker"
@@ -153,6 +151,18 @@
 	relation      *state.Relation
 	relationUnits map[string]*state.RelationUnit
 	subordinate   *state.Unit
+
+	hooksCompleted []string
+}
+
+var _ uniter.UniterExecutionObserver = (*context)(nil)
+
+func (ctx *context) HookCompleted(hookName string) {
+	ctx.hooksCompleted = append(ctx.hooksCompleted, hookName)
+}
+
+func (ctx *context) HookFailed(hookName string) {
+	ctx.hooksCompleted = append(ctx.hooksCompleted, "fail-"+hookName)
 }
 
 func (ctx *context) run(c *gc.C, steps []stepper) {
@@ -189,49 +199,17 @@
 	c.Assert(err, gc.IsNil)
 }
 
-func (ctx *context) matchLogHooks(c *gc.C) (match bool, overshoot bool) {
-	// TODO(thumper): fix this to actually use a log writer to catch interesting log messages.
-	// hookPattern matches juju-log calls as generated by writeHook.
-	hookPattern := fmt.Sprintf(`^.* INFO juju `+
-		`u/0(| [a-z0-9-]+:[0-9]+)`+ // juju-log badge; group matches relation id
-		`: %s`+ // JUJU_ENV_UUID (context badge; prevents cross-test pollution)
-		` ([0-9a-z-/ ]+)$`, // foo-relation-joined bar/123
-		ctx.uuid,
-	)
-	// donePattern matches uniter logging that indicates a hook has run.
-	donePattern := `^.* (INFO|ERROR) juju\.worker\.uniter (ran "[a-z0-9-]+" hook|hook failed)`
-	hookRegexp := regexp.MustCompile(hookPattern)
-	doneRegexp := regexp.MustCompile(donePattern)
-
-	// pending is empty while we scan for a new hook, and holds a value while
-	// we scan for output indicating that hook execution has finished; at which
-	// point, we add it to...
-	pending := ""
-	// ...actual, which holds a list of executed hooks, with basic information
-	// about the relation context, and which will be compared against ctx's
-	// complete list of expected hooks.
-	var actual []string
-	for _, line := range strings.Split(c.GetTestLog(), "\n") {
-		if pending == "" {
-			if parts := hookRegexp.FindStringSubmatch(line); parts != nil {
-				// "hook-name[ JUJU_REMOTE_UNIT]" + "[ JUJU_RELATION_ID]
-				pending = parts[2] + parts[1]
-			}
-		} else if doneRegexp.MatchString(line) {
-			actual = append(actual, pending)
-			pending = ""
-		}
-	}
-	c.Logf("actual: %#v", actual)
-	if len(actual) < len(ctx.hooks) {
+func (ctx *context) matchHooks(c *gc.C) (match bool, overshoot bool) {
+	c.Logf("ctx.hooksCompleted: %#v", ctx.hooksCompleted)
+	if len(ctx.hooksCompleted) < len(ctx.hooks) {
 		return false, false
 	}
 	for i, e := range ctx.hooks {
-		if actual[i] != e {
+		if ctx.hooksCompleted[i] != e {
 			return false, false
 		}
 	}
-	return true, len(actual) > len(ctx.hooks)
+	return true, len(ctx.hooksCompleted) > len(ctx.hooks)
 }
 
 var startupTests = []uniterTest{
@@ -827,7 +805,7 @@
 
 			// ignore should not (only in v1)
 			_, err = os.Stat(filepath.Join(ctx.path, "charm", "ignore"))
-			c.Assert(err, checkers.Satisfies, os.IsNotExist)
+			c.Assert(err, jc.Satisfies, os.IsNotExist)
 
 			// data should contain what was written in the start hook
 			data, err := ioutil.ReadFile(filepath.Join(ctx.path, "charm", "data"))
@@ -1257,6 +1235,7 @@
 		panic("API connection not established")
 	}
 	ctx.uniter = uniter.NewUniter(ctx.s.uniter, s.unitTag, ctx.dataDir)
+	uniter.SetUniterObserver(ctx.uniter, ctx)
 }
 
 type waitUniterDead struct {
@@ -1487,7 +1466,7 @@
 	}
 	ctx.hooks = append(ctx.hooks, s...)
 	c.Logf("waiting for hooks: %#v", ctx.hooks)
-	match, overshoot := ctx.matchLogHooks(c)
+	match, overshoot := ctx.matchHooks(c)
 	if overshoot && len(s) == 0 {
 		c.Fatalf("ran more hooks than expected")
 	}
@@ -1499,7 +1478,7 @@
 		ctx.s.BackingState.StartSync()
 		select {
 		case <-time.After(coretesting.ShortWait):
-			if match, _ = ctx.matchLogHooks(c); match {
+			if match, _ = ctx.matchHooks(c); match {
 				return
 			}
 		case <-timeout:
@@ -1680,7 +1659,7 @@
 func (s relationState) step(c *gc.C, ctx *context) {
 	err := ctx.relation.Refresh()
 	if s.removed {
-		c.Assert(err, checkers.Satisfies, errors.IsNotFoundError)
+		c.Assert(err, jc.Satisfies, errors.IsNotFoundError)
 		return
 	}
 	c.Assert(err, gc.IsNil)
@@ -1908,10 +1887,10 @@
 
 var verifyHookSyncLockUnlocked = custom{func(c *gc.C, ctx *context) {
 	lock := createHookLock(c, ctx.dataDir)
-	c.Assert(lock.IsLocked(), gc.Equals, false)
+	c.Assert(lock.IsLocked(), jc.IsFalse)
 }}
 
 var verifyHookSyncLockLocked = custom{func(c *gc.C, ctx *context) {
 	lock := createHookLock(c, ctx.dataDir)
-	c.Assert(lock, checkers.Satisfies, (*fslock.Lock).IsLocked)
+	c.Assert(lock.IsLocked(), jc.IsTrue)
 }}