lib: gosh: add "good PC" to error logs

addresses the remainder of https://v.io/i/1128.

MultiPart: 1/2
Change-Id: I639e208282d2b5ad153fb59998c7a8ac598e751f
diff --git a/gosh/.api b/gosh/.api
index 0dd3f73..8bac413 100644
--- a/gosh/.api
+++ b/gosh/.api
@@ -41,6 +41,7 @@
 pkg gosh, method (*Shell) Cmd(string, ...string) *Cmd
 pkg gosh, method (*Shell) FuncCmd(*Func, ...interface{}) *Cmd
 pkg gosh, method (*Shell) HandleError(error)
+pkg gosh, method (*Shell) HandleErrorWithSkip(error, int)
 pkg gosh, method (*Shell) MakeTempDir() string
 pkg gosh, method (*Shell) MakeTempFile() *os.File
 pkg gosh, method (*Shell) Move(string, string)
diff --git a/gosh/cmd.go b/gosh/cmd.go
index e72b4d6..9922b21 100644
--- a/gosh/cmd.go
+++ b/gosh/cmd.go
@@ -65,7 +65,7 @@
 	// Shell.HandleError.
 	IgnoreClosedPipeError bool
 	// ExtraFiles is used to populate ExtraFiles in the underlying exec.Cmd
-	// object.  Does not get cloned.
+	// object. Does not get cloned.
 	ExtraFiles []*os.File
 	// Internal state.
 	sh                *Shell
@@ -308,9 +308,10 @@
 		err = nil
 	}
 	c.Err = err
-	if !c.errorIsOk(err) {
-		c.sh.HandleError(err)
+	if c.errorIsOk(err) {
+		err = nil
 	}
+	c.sh.HandleErrorWithSkip(err, 3)
 }
 
 func (c *Cmd) isRunning() bool {
diff --git a/gosh/pipeline.go b/gosh/pipeline.go
index 296f2eb..f48dfef 100644
--- a/gosh/pipeline.go
+++ b/gosh/pipeline.go
@@ -11,8 +11,6 @@
 	"os"
 )
 
-var errPipelineCmdsHaveDifferentShells = errors.New("gosh: pipeline cmds have different shells")
-
 // Pipeline represents a pipeline of commands, where the stdout and/or stderr of
 // one command is connected to the stdin of the next command.
 //
@@ -173,7 +171,7 @@
 	if _, ok := err.(errAlreadyHandled); ok {
 		return // the shell has already handled this error
 	}
-	sh.HandleError(err)
+	sh.HandleErrorWithSkip(err, 3)
 }
 
 type errAlreadyHandled struct {
@@ -208,7 +206,7 @@
 
 func (p *Pipeline) pipeTo(c *Cmd, mode pipeMode, clone bool) (e error) {
 	if p.sh != c.Shell() {
-		return errPipelineCmdsHaveDifferentShells
+		return errors.New("gosh: pipeline cmds have different shells")
 	}
 	if clone {
 		c = c.Clone()
diff --git a/gosh/shell.go b/gosh/shell.go
index a42d69c..3bebf8c 100644
--- a/gosh/shell.go
+++ b/gosh/shell.go
@@ -24,6 +24,7 @@
 	"os/signal"
 	"path"
 	"path/filepath"
+	"runtime"
 	"runtime/debug"
 	"sync"
 	"syscall"
@@ -85,21 +86,42 @@
 // testing.TB instance; non-tests should pass nil.
 func NewShell(tb TB) *Shell {
 	sh, err := newShell(tb)
-	sh.HandleError(err)
+	sh.handleError(err)
 	return sh
 }
 
 // HandleError sets sh.Err. If err is not nil and sh.ContinueOnError is false,
 // it also calls TB.FailNow.
 func (sh *Shell) HandleError(err error) {
+	sh.HandleErrorWithSkip(err, 2)
+}
+
+// handleError is intended for use by public Shell method implementations.
+func (sh *Shell) handleError(err error) {
+	sh.HandleErrorWithSkip(err, 3)
+}
+
+// HandleErrorWithSkip is like HandleError, but allows clients to specify the
+// skip value to pass to runtime.Caller.
+func (sh *Shell) HandleErrorWithSkip(err error, skip int) {
 	sh.Ok()
 	sh.Err = err
-	if err != nil && !sh.ContinueOnError {
-		if sh.tb != pkgLevelDefaultTB {
-			sh.tb.Logf(string(debug.Stack()))
-		}
-		sh.tb.FailNow()
+	if err == nil {
+		return
 	}
+	_, file, line, _ := runtime.Caller(skip)
+	toLog := fmt.Sprintf("%s:%d: %v\n", filepath.Base(file), line, err)
+	if sh.ContinueOnError {
+		sh.tb.Logf(toLog)
+		return
+	}
+	if sh.tb != pkgLevelDefaultTB {
+		sh.tb.Logf(string(debug.Stack()))
+	}
+	// Unfortunately, if FailNow panics, there's no way to make toLog get printed
+	// beneath the stack trace.
+	sh.tb.Logf(toLog)
+	sh.tb.FailNow()
 }
 
 // Cmd returns a Cmd for an invocation of the named program. The given arguments
@@ -107,7 +129,7 @@
 func (sh *Shell) Cmd(name string, args ...string) *Cmd {
 	sh.Ok()
 	res, err := sh.cmd(nil, name, args...)
-	sh.HandleError(err)
+	sh.handleError(err)
 	return res
 }
 
@@ -118,20 +140,20 @@
 func (sh *Shell) FuncCmd(f *Func, args ...interface{}) *Cmd {
 	sh.Ok()
 	res, err := sh.funcCmd(f, args...)
-	sh.HandleError(err)
+	sh.handleError(err)
 	return res
 }
 
 // Wait waits for all commands started by this Shell to exit.
 func (sh *Shell) Wait() {
 	sh.Ok()
-	sh.HandleError(sh.wait())
+	sh.handleError(sh.wait())
 }
 
 // Move moves a file.
 func (sh *Shell) Move(oldpath, newpath string) {
 	sh.Ok()
-	sh.HandleError(sh.move(oldpath, newpath))
+	sh.handleError(sh.move(oldpath, newpath))
 }
 
 // MakeTempFile creates a new temporary file in os.TempDir, opens the file for
@@ -139,7 +161,7 @@
 func (sh *Shell) MakeTempFile() *os.File {
 	sh.Ok()
 	res, err := sh.makeTempFile()
-	sh.HandleError(err)
+	sh.handleError(err)
 	return res
 }
 
@@ -148,20 +170,20 @@
 func (sh *Shell) MakeTempDir() string {
 	sh.Ok()
 	res, err := sh.makeTempDir()
-	sh.HandleError(err)
+	sh.handleError(err)
 	return res
 }
 
 // Pushd behaves like Bash pushd.
 func (sh *Shell) Pushd(dir string) {
 	sh.Ok()
-	sh.HandleError(sh.pushd(dir))
+	sh.handleError(sh.pushd(dir))
 }
 
 // Popd behaves like Bash popd.
 func (sh *Shell) Popd() {
 	sh.Ok()
-	sh.HandleError(sh.popd())
+	sh.handleError(sh.popd())
 }
 
 // AddCleanupHandler registers the given function to be called during cleanup.
@@ -169,7 +191,7 @@
 // spawned by gosh.
 func (sh *Shell) AddCleanupHandler(f func()) {
 	sh.Ok()
-	sh.HandleError(sh.addCleanupHandler(f))
+	sh.handleError(sh.addCleanupHandler(f))
 }
 
 // Cleanup cleans up all resources (child processes, temporary files and
@@ -542,7 +564,7 @@
 func BuildGoPkg(sh *Shell, binDir, pkg string, flags ...string) string {
 	sh.Ok()
 	res, err := buildGoPkg(sh, binDir, pkg, flags...)
-	sh.HandleError(err)
+	sh.handleError(err)
 	return res
 }
 
diff --git a/gosh/shell_test.go b/gosh/shell_test.go
index 00147c4..5771c99 100644
--- a/gosh/shell_test.go
+++ b/gosh/shell_test.go
@@ -22,6 +22,7 @@
 	"os/signal"
 	"path/filepath"
 	"reflect"
+	"runtime"
 	"runtime/debug"
 	"strings"
 	"testing"
@@ -133,6 +134,7 @@
 type customTB struct {
 	t             *testing.T
 	calledFailNow bool
+	buf           *bytes.Buffer
 }
 
 func (tb *customTB) FailNow() {
@@ -140,7 +142,11 @@
 }
 
 func (tb *customTB) Logf(format string, args ...interface{}) {
-	tb.t.Logf(format, args...)
+	if tb.buf == nil {
+		tb.t.Logf(format, args...)
+	} else {
+		fmt.Fprintf(tb.buf, format, args...)
+	}
 }
 
 func TestCustomTB(t *testing.T) {
@@ -498,7 +504,7 @@
 	// write to the command's stdin concurrently with the command's exit waiter
 	// goroutine closing stdin. Use "go test -race" catch races.
 	//
-	// Set a non-zero exit code, so that os.Exit exits immediately.  See the
+	// Set a non-zero exit code, so that os.Exit exits immediately. See the
 	// implementation of https://golang.org/pkg/os/#Exit for details.
 	c := sh.FuncCmd(exitFunc, 1)
 	c.ExitErrorIsOk = true
@@ -810,7 +816,7 @@
 	return 0, w.error
 }
 
-// Tests that sh.Ok panics under various conditions.
+// Tests that Shell.Ok panics under various conditions.
 func TestOkPanics(t *testing.T) {
 	func() { // errDidNotCallNewShell
 		sh := gosh.Shell{}
@@ -834,7 +840,7 @@
 	}()
 }
 
-// Tests that sh.HandleError panics under various conditions.
+// Tests that Shell.HandleError panics under various conditions.
 func TestHandleErrorPanics(t *testing.T) {
 	func() { // errDidNotCallNewShell
 		sh := gosh.Shell{}
@@ -858,7 +864,7 @@
 	}()
 }
 
-// Tests that sh.Cleanup panics under various conditions.
+// Tests that Shell.Cleanup panics under various conditions.
 func TestCleanupPanics(t *testing.T) {
 	func() { // errDidNotCallNewShell
 		sh := gosh.Shell{}
@@ -867,20 +873,67 @@
 	}()
 }
 
-// Tests that sh.Cleanup succeeds even if sh.Err is not nil.
+// Tests that Shell.Cleanup succeeds even if sh.Err is not nil.
 func TestCleanupAfterError(t *testing.T) {
 	sh := gosh.NewShell(t)
 	sh.Err = fakeError
 	sh.Cleanup()
 }
 
-// Tests that sh.Cleanup can be called multiple times.
+// Tests that Shell.Cleanup can be called multiple times.
 func TestMultipleCleanup(t *testing.T) {
 	sh := gosh.NewShell(t)
 	sh.Cleanup()
 	sh.Cleanup()
 }
 
+// Tests that Shell.HandleError logs errors using an appropriate runtime.Caller
+// skip value.
+func TestHandleErrorLogging(t *testing.T) {
+	tb := &customTB{t: t, buf: &bytes.Buffer{}}
+	sh := gosh.NewShell(tb)
+	defer sh.Cleanup()
+
+	// Call HandleError, then check that the stack trace and error got logged.
+	tb.buf.Reset()
+	sh.HandleError(fakeError)
+	_, file, line, _ := runtime.Caller(0)
+	got, wantSuffix := tb.buf.String(), fmt.Sprintf("%s:%d: %v\n", filepath.Base(file), line-1, fakeError)
+	if !strings.HasSuffix(got, wantSuffix) {
+		t.Fatalf("got %v, want suffix %v", got, wantSuffix)
+	}
+	if got == wantSuffix {
+		t.Fatalf("missing stack trace: %v", got)
+	}
+	sh.Err = nil
+
+	// Same as above, but with ContinueOnError set to true. Only the error should
+	// get logged.
+	sh.ContinueOnError = true
+	tb.buf.Reset()
+	sh.HandleError(fakeError)
+	_, file, line, _ = runtime.Caller(0)
+	got, want := tb.buf.String(), fmt.Sprintf("%s:%d: %v\n", filepath.Base(file), line-1, fakeError)
+	eq(t, got, want)
+	sh.Err = nil
+
+	// Same as above, but calling HandleErrorWithSkip, with skip set to 1.
+	tb.buf.Reset()
+	sh.HandleErrorWithSkip(fakeError, 1)
+	_, file, line, _ = runtime.Caller(0)
+	got, want = tb.buf.String(), fmt.Sprintf("%s:%d: %v\n", filepath.Base(file), line-1, fakeError)
+	eq(t, got, want)
+	sh.Err = nil
+
+	// Same as above, but with skip set to 2.
+	tb.buf.Reset()
+	sh.HandleErrorWithSkip(fakeError, 2)
+	_, file, line, _ = runtime.Caller(1)
+	got, want = tb.buf.String(), fmt.Sprintf("%s:%d: %v\n", filepath.Base(file), line, fakeError)
+	eq(t, got, want)
+	sh.Err = nil
+}
+
 func TestMain(m *testing.M) {
 	gosh.InitMain()
 	os.Exit(m.Run())