Merge pull request #336 from metrumresearchgroup/cmd-errors

cmd: improve error reporting

cmd/local.go

@@ -151,7 +151,7 @@ func (l LocalModel) Prepare(channels *turnstile.ChannelMap) {
 		channels.Errors <- turnstile.ConcurrentError{
 			RunIdentifier: l.Nonmem.Model,
 			Error:         err,
-			Notes:         "An error occurred during the creation of the executable script for this model",
+			Notes:         "failed to generate executable script",
 		}
 
 		return
@@ -163,7 +163,7 @@ func (l LocalModel) Prepare(channels *turnstile.ChannelMap) {
 	if err = afero.WriteFile(fs, path.Join(l.Nonmem.OutputDir, l.Nonmem.FileName+".sh"), scriptContents, 0750); err != nil {
 		channels.Errors <- turnstile.ConcurrentError{
 			RunIdentifier: l.Nonmem.FileName,
-			Notes:         "writing the .sh file",
+			Notes:         "failed to write .sh file",
 			Error:         err,
 		}
 	}
@@ -172,7 +172,7 @@ func (l LocalModel) Prepare(channels *turnstile.ChannelMap) {
 		if err = writeParaFile(l.Nonmem); err != nil {
 			channels.Errors <- turnstile.ConcurrentError{
 				RunIdentifier: l.Nonmem.FileName,
-				Notes:         "writing to the parafile",
+				Notes:         "failed to write parafile",
 				Error:         err,
 			}
 			//			log.Fatalf("%s Configuration requires parallel operation, but generation or writing of the parafile has failed: %s", l.Nonmem.LogIdentifier(), err)
@@ -275,7 +275,7 @@ func (l LocalModel) Cleanup(channels *turnstile.ChannelMap) {
 		if err = afero.WriteFile(fs, path.Join(l.Nonmem.OriginalPath, l.Nonmem.FileName+"_copied.json"), copiedJSON, 0640); err != nil {
 			channels.Errors <- turnstile.ConcurrentError{
 				RunIdentifier: l.Nonmem.FileName,
-				Notes:         "could not write _copied.json file",
+				Notes:         "failed to write _copied.json file",
 				Error:         err,
 			}
 		}
@@ -305,7 +305,7 @@ func (l LocalModel) Cleanup(channels *turnstile.ChannelMap) {
 	if err = createNewGitIgnoreFile(l.Nonmem); err != nil {
 		channels.Errors <- turnstile.ConcurrentError{
 			RunIdentifier: l.Nonmem.FileName,
-			Notes:         "failed writing .gitignore file ",
+			Notes:         "failed to write .gitignore file",
 			Error:         err,
 		}
 	}
@@ -435,8 +435,6 @@ func WriteGitIgnoreFile(filepath string) error {
 
 func executeLocalJob(model *NonMemModel) turnstile.ConcurrentError {
 	log.Infof("%s Beginning local work phase", model.LogIdentifier())
-	fs := afero.NewOsFs()
-
 	log.Debugf("Output directory is currently set to %s", model.OutputDir)
 
 	scriptLocation := path.Join(model.OutputDir, model.FileName+".sh")
@@ -458,28 +456,7 @@ func executeLocalJob(model *NonMemModel) turnstile.ConcurrentError {
 
 	log.Debugf("%s Generated command was: %s", model.LogIdentifier(), command.String())
 
-	output, err := command.CombinedOutput()
-
-	if err != nil && !strings.Contains(string(output), "not well-formed (invalid token)") {
-		log.Debug(err)
-
-		var exitError *exec.ExitError
-		if errors.As(err, &exitError) {
-			code := exitError.ExitCode()
-			details := exitError.String()
-
-			log.Errorf("%s Exit code was %d, details were %s", model.LogIdentifier(), code, details)
-			log.Errorf("%s output details were: %s", model.LogIdentifier(), string(output))
-		}
-
-		return newConcurrentError(model.Model, "Running the programmatic shell script caused an error", err)
-	}
-
-	if err = afero.WriteFile(fs, path.Join(model.OutputDir, model.Model+".out"), output, 0640); err != nil {
-		return turnstile.ConcurrentError{Error: err, Notes: "unable to write model to output directory", RunIdentifier: model.FileName}
-	}
-
-	return turnstile.ConcurrentError{}
+	return runModelCommand(model, command, localIgnoreError)
 }
 
 func localModelsFromArguments(args []string, config configlib.Config) ([]LocalModel, error) {
@@ -554,3 +531,7 @@ func HashFileOnChannel(ch chan string, file string, identifier string) {
 	}
 	ch <- fmt.Sprintf("%x", h.Sum(nil))
 }
+
+func localIgnoreError(_ error, output string) bool {
+	return strings.Contains(output, "not well-formed (invalid token)")
+}

cmd/nonmem.go

@@ -323,7 +323,7 @@ func generateScript(fileTemplate string, l *NonMemModel) ([]byte, error) {
 	t, err := template.New("file").Parse(fileTemplate)
 	buf := new(bytes.Buffer)
 	if err != nil {
-		return []byte{}, errors.New("There was an error processing the provided script template")
+		return []byte{}, fmt.Errorf("parsing script template failed: %w", err)
 	}
 
 	type content struct {
@@ -344,7 +344,7 @@ func generateScript(fileTemplate string, l *NonMemModel) ([]byte, error) {
 	err = t.Execute(buf, cont)
 
 	if err != nil {
-		return []byte{}, errors.New("An error occured during the execution of the provided script template")
+		return []byte{}, fmt.Errorf("generating script template failed: %w", err)
 	}
 
 	if viper.GetBool("debug") {
@@ -696,7 +696,7 @@ func postWorkNotice(m *turnstile.Manager, t time.Time) {
 		log.Errorf("%d errors were experienced during the run", m.Errors)
 
 		for _, v := range m.ErrorList {
-			log.Errorf("Errors were experienced while running model %s. Details are %s", v.RunIdentifier, v.Notes)
+			log.Errorf("Error running model %s: %s\n\n%v", v.RunIdentifier, v.Notes, v.Error)
 		}
 	}
 

cmd/root.go

@@ -177,7 +177,7 @@ func logSetup(config configlib.Config) {
 // RecordConcurrentError handles the processing of cancellation messages as well placing concurrent errors onto the stack.
 func RecordConcurrentError(model string, notes string, err error, channels *turnstile.ChannelMap, cancel chan bool, executor PostWorkExecutor) {
 	cancel <- true
-	channels.Errors <- newConcurrentError(model, notes, err)
+	channels.Errors <- turnstile.ConcurrentError{RunIdentifier: model, Notes: notes, Error: err}
 
 	PostWorkExecution(executor, false, err)
 }

cmd/run.go

@@ -13,6 +13,7 @@ import (
 
 	"github.com/metrumresearchgroup/bbi/configlib"
 
+	"github.com/metrumresearchgroup/turnstile"
 	log "github.com/sirupsen/logrus"
 	"github.com/spf13/cobra"
 	"github.com/spf13/viper"
@@ -334,3 +335,67 @@ func onlyBbiVariables(provided []string) []string {
 
 	return matched
 }
+
+// runModelCommand runs command, writing the combined standard output and
+// standard error to {model.OutputDir}/{model.Model}.out.  command should be
+// primed to run; existing values for Stdout and Stderr are ignored.
+//
+// ignoreError is a function called if running the command fails.  It takes the
+// error and combined standard output and standard error as arguments.  A return
+// value of true indicates that the error should be swallowed rather propagated
+// as a turnstile.ConcurrentError.
+func runModelCommand(
+	model *NonMemModel, command *exec.Cmd, ignoreError func(error, string) bool,
+) turnstile.ConcurrentError {
+
+	outfile := filepath.Join(model.OutputDir, model.Model+".out")
+	outfh, err := os.OpenFile(outfile, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0o640)
+	if err != nil {
+		if errClose := outfh.Close(); errClose != nil {
+			log.Errorf("error closing output file: %v", errClose)
+		}
+
+		return turnstile.ConcurrentError{
+			RunIdentifier: model.Model,
+			Notes:         "unable to create model output file",
+			Error:         err,
+		}
+	}
+
+	command.Stdout = outfh
+	command.Stderr = outfh
+
+	if err = command.Run(); err != nil {
+		if errClose := outfh.Close(); errClose != nil {
+			log.Errorf("error closing output file: %v", errClose)
+		}
+
+		ignore := false
+		output, errRead := os.ReadFile(outfile)
+		if errRead == nil {
+			ignore = ignoreError(err, string(output))
+		} else {
+			log.Errorf("error reading output file: %v", errRead)
+		}
+
+		if !ignore {
+			log.Debug(err)
+
+			var exitError *exec.ExitError
+			if errors.As(err, &exitError) {
+				code := exitError.ExitCode()
+				log.Errorf("%s exit code: %d, output:\n%s",
+					model.LogIdentifier(), code, string(output))
+			}
+
+			return turnstile.ConcurrentError{
+				RunIdentifier: model.Model,
+				Notes: fmt.Sprintf("error running %q; command output written to %q",
+					command.String(), outfile),
+				Error: err,
+			}
+		}
+	}
+
+	return turnstile.ConcurrentError{}
+}

cmd/run_test.go

@@ -0,0 +1,91 @@
+package cmd
+
+import (
+	"os"
+	"os/exec"
+	"path/filepath"
+	"strings"
+	"testing"
+
+	"github.com/metrumresearchgroup/turnstile"
+	"github.com/metrumresearchgroup/wrapt"
+)
+
+func skipIfNoSh(t *wrapt.T) {
+	t.Helper()
+	_, err := exec.LookPath("sh")
+	if err != nil {
+		t.Skipf("skipped because sh is not available")
+	}
+}
+
+func never(_ error, _ string) bool {
+	return false
+}
+
+func TestRunModelCommand(tt *testing.T) {
+	t := wrapt.WrapT(tt)
+
+	skipIfNoSh(t)
+
+	cmd := exec.Command("sh", "-c", "printf 'stdout\n'; printf >&2 'stderr\n'")
+	mod := &NonMemModel{Model: "foo.ctl", FileName: "foo", OutputDir: t.TempDir()}
+	cerr := runModelCommand(mod, cmd, never)
+	t.A.Equal(cerr, turnstile.ConcurrentError{})
+
+	outfile := filepath.Join(mod.OutputDir, mod.Model+".out")
+	t.R.FileExists(outfile)
+	bs, err := os.ReadFile(outfile)
+	t.R.NoError(err)
+	output = string(bs)
+
+	t.A.Contains(output, "stdout")
+	t.A.Contains(output, "stderr")
+}
+
+func TestRunModelCommandError(tt *testing.T) {
+	t := wrapt.WrapT(tt)
+
+	skipIfNoSh(t)
+
+	cmd := exec.Command("sh", "-c", "printf 'stdout\n'; printf >&2 'stderr\n'; exit 1")
+	mod := &NonMemModel{Model: "foo.ctl", FileName: "foo", OutputDir: t.TempDir()}
+
+	cerr := runModelCommand(mod, cmd, never)
+	t.A.Error(cerr.Error)
+	t.A.Contains(cerr.Notes, mod.Model+".out")
+
+	outfile := filepath.Join(mod.OutputDir, mod.Model+".out")
+	t.R.FileExists(outfile)
+	bs, err := os.ReadFile(outfile)
+	t.R.NoError(err)
+	output = string(bs)
+
+	t.A.Contains(output, "stdout")
+	t.A.Contains(output, "stderr")
+}
+
+func TestRunModelCommandIgnoreError(tt *testing.T) {
+	t := wrapt.WrapT(tt)
+
+	skipIfNoSh(t)
+
+	cmd := exec.Command("sh", "-c", "printf 'stdout\n'; printf >&2 'IGNORE\n'; exit 1")
+	mod := &NonMemModel{Model: "foo.ctl", FileName: "foo", OutputDir: t.TempDir()}
+
+	ign := func(_ error, output string) bool {
+		return strings.Contains(output, "IGNORE")
+	}
+
+	cerr := runModelCommand(mod, cmd, ign)
+	t.A.Equal(cerr, turnstile.ConcurrentError{})
+
+	outfile := filepath.Join(mod.OutputDir, mod.Model+".out")
+	t.R.FileExists(outfile)
+	bs, err := os.ReadFile(outfile)
+	t.R.NoError(err)
+	output = string(bs)
+
+	t.A.Contains(output, "stdout")
+	t.A.Contains(output, "IGNORE")
+}