veyron/lib/modules/core: fix flaky tests for the core modules.

Change-Id: I20e586e3b4a67c80066a1d9717400363afd1e259
diff --git a/lib/expect/expect.go b/lib/expect/expect.go
index a748a9d..28259a8 100644
--- a/lib/expect/expect.go
+++ b/lib/expect/expect.go
@@ -42,11 +42,14 @@
 	"errors"
 	"fmt"
 	"io"
+	"os"
 	"path/filepath"
 	"regexp"
 	"runtime"
 	"strings"
 	"time"
+
+	"veyron2/vlog"
 )
 
 var (
@@ -58,11 +61,13 @@
 	input   *bufio.Reader
 	timeout time.Duration
 	t       Testing
+	verbose bool
 	err     error
 }
 
 type Testing interface {
 	Error(args ...interface{})
+	Log(args ...interface{})
 }
 
 // NewSession creates a new Session. The parameter t may be safely be nil.
@@ -80,6 +85,28 @@
 	return s.err
 }
 
+// SetVerbosity enables/disable verbose debugging information, in particular,
+// every line of input read will be logged via Testing.Logf or, if it is nil,
+// to stderr.
+func (s *Session) SetVerbosity(v bool) {
+	s.verbose = v
+}
+
+func (s *Session) log(format string, args ...interface{}) {
+	if !s.verbose {
+		return
+	}
+	_, path, line, _ := runtime.Caller(2)
+	loc := fmt.Sprintf("%s:%d", filepath.Base(path), line)
+	o := strings.TrimRight(fmt.Sprintf(format, args...), "\n\t ")
+	vlog.VI(2).Infof("%s: %s", loc, o)
+	if s.t == nil {
+		fmt.Fprint(os.Stderr, loc, o)
+		return
+	}
+	s.t.Log(loc, o)
+}
+
 // ReportError calls Testing.Error to report any error currently stored
 // in the Session.
 func (s *Session) ReportError() {
@@ -123,12 +150,12 @@
 	ch := make(chan string, 1)
 	ech := make(chan error, 1)
 	go func(fn reader, io *bufio.Reader) {
-		s, err := fn(io)
+		str, err := fn(io)
 		if err != nil {
 			ech <- err
 			return
 		}
-		ch <- s
+		ch <- str
 	}(f, s.input)
 	select {
 	case err := <-ech:
@@ -146,11 +173,13 @@
 		return
 	}
 	line, err := s.read(readLine)
+	s.log("Expect: %v: %s", err, line)
 	if err != nil {
 		s.error(err)
 		return
 	}
 	line = strings.TrimRight(line, "\n")
+
 	if line != expected {
 		s.error(fmt.Errorf("got %q, want %q", line, expected))
 	}
@@ -180,6 +209,7 @@
 		return [][]string{}
 	}
 	l, m, err := s.expectRE(pattern, n)
+	s.log("ExpectRE: %v: %s", err, l)
 	if err != nil {
 		s.error(err)
 		return [][]string{}
@@ -197,6 +227,7 @@
 		return ""
 	}
 	l, m, err := s.expectRE(name+"=(.*)", 1)
+	s.log("ExpectVar: %v: %s", err, l)
 	if err != nil {
 		s.error(err)
 		return ""
@@ -215,6 +246,7 @@
 		return ""
 	}
 	l, err := s.read(readLine)
+	s.log("Readline: %v: %s", err, l)
 	if err != nil {
 		s.error(err)
 	}
diff --git a/lib/modules/core/core.go b/lib/modules/core/core.go
index 40da4c7..56b736d 100644
--- a/lib/modules/core/core.go
+++ b/lib/modules/core/core.go
@@ -1,5 +1,26 @@
 // Package core provides modules.Shell instances with commands preinstalled for
 // common core services such as naming, security etc.
+//
+// The available commands are:
+//
+// root     - runs a root mount table as a subprocess
+//            prints the MT_NAME=<root name>, PID=<pid> variables to stdout
+//            waits for stdin to be closed before it exits
+//            prints "done" to stdout when stdin is closed.
+// mt <mp>  - runs a mount table as a subprocess mounted on <mp>
+//            NAMESPACE_ROOT should be set to the name of another mount table
+//            (e.g. the value of MT_NAME from a root) in the shell's
+//            environment. mt similarly prints MT_NAME, PID and waits for stdout
+//            as per the root
+//            command
+//
+// ls <glob>...  - ls issues one or more globs using the local,
+//                 in-process namespace
+// lse <glob>... - lse issues one or more globs from a subprocess and hence
+//                 the subprocesses namespace. NAMESPACE_ROOT can be set in
+//                 the shell's environment prior to calling lse to have the
+//                 subprocesses namespace be relative to it.
+//
 package core
 
 import "veyron/lib/modules"
@@ -9,7 +30,8 @@
 	MTCommand         = "mt"
 	LSCommand         = "ls"
 	LSExternalCommand = "lse"
-	MountCommand      = "mount"
+	// TODO(cnicolaou): provide a simple service that can be mounted.
+	MountCommand = "mount"
 )
 
 func NewShell() *modules.Shell {
diff --git a/lib/modules/core/core_test.go b/lib/modules/core/core_test.go
index 0d5e42e..753077a 100644
--- a/lib/modules/core/core_test.go
+++ b/lib/modules/core/core_test.go
@@ -82,14 +82,19 @@
 	if t.Failed() {
 		return
 	}
-	mountPoints := []string{"a", "b", "c"}
+	mountPoints := []string{"a", "b", "c", "d", "e"}
 
 	// Start 3 mount tables
 	for _, mp := range mountPoints {
-		_, err := shell.Start(core.MTCommand, mp)
+		h, err := shell.Start(core.MTCommand, mp)
 		if err != nil {
 			t.Fatalf("unexpected error: %s", err)
 		}
+		s := expect.NewSession(t, h.Stdout(), time.Second)
+		// Wait until each mount table has at least called Serve to
+		// mount itself.
+		s.ExpectVar("MT_NAME")
+
 	}
 
 	ls, err := shell.Start(core.LSCommand, rootName+"/...")
@@ -97,6 +102,8 @@
 		t.Fatalf("unexpected error: %s", err)
 	}
 	lsSession := expect.NewSession(t, ls.Stdout(), time.Second)
+
+	lsSession.SetVerbosity(testing.Verbose())
 	lsSession.Expect(rootName)
 
 	// Look for names that correspond to the mountpoints above (i.e, a, b or c)
@@ -107,9 +114,9 @@
 	pattern = pattern[:len(pattern)-1]
 
 	found := []string{}
-	found = append(found, getMatchingMountpoint(lsSession.ExpectRE(pattern, 1)))
-	found = append(found, getMatchingMountpoint(lsSession.ExpectRE(pattern, 1)))
-	found = append(found, getMatchingMountpoint(lsSession.ExpectRE(pattern, 1)))
+	for i := 0; i < len(mountPoints); i++ {
+		found = append(found, getMatchingMountpoint(lsSession.ExpectRE(pattern, 1)))
+	}
 	sort.Strings(found)
 	sort.Strings(mountPoints)
 	if got, want := found, mountPoints; !reflect.DeepEqual(got, want) {
@@ -122,19 +129,20 @@
 		t.Fatalf("unexpected error: %s", err)
 	}
 	lseSession := expect.NewSession(t, lse.Stdout(), time.Second)
+	lseSession.SetVerbosity(testing.Verbose())
 
 	pattern = ""
 	for _, n := range mountPoints {
 		// Since the LSExternalCommand runs in a subprocess with NAMESPACE_ROOT
-		// set to the name of the root mount table it sees the relative name
+		// set to the name of the root mount table it sees to the relative name
 		// format of the mounted mount tables.
 		pattern = pattern + "(^" + n + "$)|"
 	}
 	pattern = pattern[:len(pattern)-1]
 	found = []string{}
-	found = append(found, getMatchingMountpoint(lseSession.ExpectRE(pattern, 1)))
-	found = append(found, getMatchingMountpoint(lseSession.ExpectRE(pattern, 1)))
-	found = append(found, getMatchingMountpoint(lseSession.ExpectRE(pattern, 1)))
+	for i := 0; i < len(mountPoints); i++ {
+		found = append(found, getMatchingMountpoint(lseSession.ExpectRE(pattern, 1)))
+	}
 	sort.Strings(found)
 	sort.Strings(mountPoints)
 	if got, want := found, mountPoints; !reflect.DeepEqual(got, want) {
diff --git a/lib/modules/core/mounttable.go b/lib/modules/core/mounttable.go
index b7862f5..b9e2d0d 100644
--- a/lib/modules/core/mounttable.go
+++ b/lib/modules/core/mounttable.go
@@ -56,12 +56,10 @@
 		return fmt.Errorf("root failed: %s", err)
 	}
 	name := naming.JoinAddressName(ep.String(), "")
-	fmt.Fprintf(os.Stderr, "Serving MountTable on %q", name)
-
-	fmt.Printf("MT_NAME=%s\n", name)
-	fmt.Printf("PID=%d\n", os.Getpid())
+	fmt.Fprintf(stdout, "MT_NAME=%s\n", name)
+	fmt.Fprintf(stdout, "PID=%d\n", os.Getpid())
 	modules.WaitForEOF(stdin)
-	fmt.Println("done\n")
+	fmt.Fprintf(stdout, "done\n")
 	return nil
 }
 
diff --git a/lib/modules/exec.go b/lib/modules/exec.go
index b364171..279e6dc 100644
--- a/lib/modules/exec.go
+++ b/lib/modules/exec.go
@@ -227,3 +227,13 @@
 	}
 	return m(os.Stdin, os.Stdout, os.Stderr, osEnvironMap(), flag.Args()...)
 }
+
+// WaitForEof returns when a read on its io.Reader parameter returns io.EOF
+func WaitForEOF(stdin io.Reader) {
+	buf := [1024]byte{}
+	for {
+		if _, err := stdin.Read(buf[:]); err == io.EOF {
+			return
+		}
+	}
+}
diff --git a/lib/modules/shell.go b/lib/modules/shell.go
index 4df120b..3105b4b 100644
--- a/lib/modules/shell.go
+++ b/lib/modules/shell.go
@@ -99,8 +99,7 @@
 }
 
 // String returns a string representation of the Shell, which is a
-// concatenation of the help messages of each Command currently available
-// to it.
+// list of the commands currently available in the shell.
 func (sh *Shell) String() string {
 	sh.mu.Lock()
 	defer sh.mu.Unlock()
@@ -237,12 +236,3 @@
 type command interface {
 	start(sh *Shell, args ...string) (Handle, error)
 }
-
-func WaitForEOF(stdin io.Reader) {
-	buf := [1024]byte{}
-	for {
-		if _, err := stdin.Read(buf[:]); err == io.EOF {
-			return
-		}
-	}
-}