misc/cgo/testcarchive: log command output more consistently

Also check that executables exist immediately after building them
in parallel tests.

The parallel tests in this package occasionally fail with
"no such file or directory", implying that either the build
command failed to actually write out the binary or something
concurrently deleted it.

This is purely a shot in the dark, but I'm hoping that perhaps
the stderr output from one of these commands will shed some
light on the underlying failure mode.

For #49693

Change-Id: I2e768190c56053550879b89a3ac88c027d4741dd
Reviewed-on: https://go-review.googlesource.com/c/go/+/369034
Trust: Bryan Mills <bcmills@google.com>
Run-TryBot: Bryan Mills <bcmills@google.com>
Reviewed-by: Ian Lance Taylor <iant@golang.org>
TryBot-Result: Gopher Robot <gobot@golang.org>

diff --git a/misc/cgo/testcarchive/carchive_test.go b/misc/cgo/testcarchive/carchive_test.go
index a2b43bb72d8d3a351d9c86f715d736d390f42bc5..c5193e3f193fa89ef5aa43e156a0d839199127dd 100644 (file)
--- a/misc/cgo/testcarchive/carchive_test.go
+++ b/misc/cgo/testcarchive/carchive_test.go
@@ -10,6 +10,7 @@ import (
        "debug/elf"
        "flag"
        "fmt"
+       "io/fs"
        "log"
        "os"
        "os/exec"
@@ -245,6 +246,29 @@ func testInstall(t *testing.T, exe, libgoa, libgoh string, buildcmd ...string) {
 
 var badLineRegexp = regexp.MustCompile(`(?m)^#line [0-9]+ "/.*$`)
 
+// checkIsExecutable verifies that exe exists and has execute permission.
+//
+// (https://golang.org/issue/49693 notes failures with "no such file or
+// directory", so we want to double-check that the executable actually exists
+// immediately after we build it in order to better understand that failure
+// mode.)
+func checkIsExecutable(t *testing.T, exe string) {
+       t.Helper()
+       fi, err := os.Stat(exe)
+       if err != nil {
+               t.Fatal(err)
+       }
+       if runtime.GOOS == "windows" {
+               // os.File doesn't check the "execute" permission on Windows files
+               // and as a result doesn't set that bit in a file's permissions.
+               // Assume that if the file exists it is “executable enough”.
+               return
+       }
+       if fi.Mode()&0111 == 0 {
+               t.Fatalf("%s is not executable: %0o", exe, fi.Mode()&fs.ModePerm)
+       }
+}
+
 // checkLineComments checks that the export header generated by
 // -buildmode=c-archive doesn't have any absolute paths in the #line
 // comments. We don't want those paths because they are unhelpful for
@@ -310,7 +334,7 @@ func TestEarlySignalHandler(t *testing.T) {
                defer func() {
                        os.Remove("libgo2.a")
                        os.Remove("libgo2.h")
-                       os.Remove("testp")
+                       os.Remove("testp" + exeSuffix)
                        os.RemoveAll(filepath.Join(GOPATH, "pkg"))
                }()
        }
@@ -350,7 +374,7 @@ func TestSignalForwarding(t *testing.T) {
                defer func() {
                        os.Remove("libgo2.a")
                        os.Remove("libgo2.h")
-                       os.Remove("testp")
+                       os.Remove("testp" + exeSuffix)
                        os.RemoveAll(filepath.Join(GOPATH, "pkg"))
                }()
        }
@@ -374,7 +398,7 @@ func TestSignalForwarding(t *testing.T) {
        cmd = exec.Command(bin[0], append(bin[1:], "1")...)
 
        out, err := cmd.CombinedOutput()
-       t.Logf("%s", out)
+       t.Logf("%v\n%s", cmd.Args, out)
        expectSignal(t, err, syscall.SIGSEGV)
 
        // SIGPIPE is never forwarded on darwin. See golang.org/issue/33384.
@@ -383,7 +407,9 @@ func TestSignalForwarding(t *testing.T) {
                cmd = exec.Command(bin[0], append(bin[1:], "3")...)
 
                out, err = cmd.CombinedOutput()
-               t.Logf("%s", out)
+               if len(out) > 0 {
+                       t.Logf("%s", out)
+               }
                expectSignal(t, err, syscall.SIGPIPE)
        }
 }
@@ -400,7 +426,7 @@ func TestSignalForwardingExternal(t *testing.T) {
                defer func() {
                        os.Remove("libgo2.a")
                        os.Remove("libgo2.h")
-                       os.Remove("testp")
+                       os.Remove("testp" + exeSuffix)
                        os.RemoveAll(filepath.Join(GOPATH, "pkg"))
                }()
        }
@@ -517,7 +543,7 @@ func TestOsSignal(t *testing.T) {
                defer func() {
                        os.Remove("libgo3.a")
                        os.Remove("libgo3.h")
-                       os.Remove("testp")
+                       os.Remove("testp" + exeSuffix)
                        os.RemoveAll(filepath.Join(GOPATH, "pkg"))
                }()
        }
@@ -554,7 +580,7 @@ func TestSigaltstack(t *testing.T) {
                defer func() {
                        os.Remove("libgo4.a")
                        os.Remove("libgo4.h")
-                       os.Remove("testp")
+                       os.Remove("testp" + exeSuffix)
                        os.RemoveAll(filepath.Join(GOPATH, "pkg"))
                }()
        }
@@ -747,8 +773,9 @@ func TestSIGPROF(t *testing.T) {
        }
 
        cmd := exec.Command("go", "build", "-buildmode=c-archive", "-o", "libgo6.a", "./libgo6")
-       if out, err := cmd.CombinedOutput(); err != nil {
-               t.Logf("%s", out)
+       out, err := cmd.CombinedOutput()
+       t.Logf("%v\n%s", cmd.Args, out)
+       if err != nil {
                t.Fatal(err)
        }
        checkLineComments(t, "libgo6.h")
@@ -757,15 +784,18 @@ func TestSIGPROF(t *testing.T) {
        if runtime.Compiler == "gccgo" {
                ccArgs = append(ccArgs, "-lgo")
        }
-       if out, err := exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput(); err != nil {
-               t.Logf("%s", out)
+       out, err = exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput()
+       t.Logf("%v\n%s", ccArgs, out)
+       if err != nil {
                t.Fatal(err)
        }
+       checkIsExecutable(t, "./testp6"+exeSuffix)
 
        argv := cmdToRun("./testp6")
        cmd = exec.Command(argv[0], argv[1:]...)
-       if out, err := cmd.CombinedOutput(); err != nil {
-               t.Logf("%s", out)
+       out, err = cmd.CombinedOutput()
+       t.Logf("%v\n%s", argv, out)
+       if err != nil {
                t.Fatal(err)
        }
 }
@@ -788,9 +818,8 @@ func TestCompileWithoutShared(t *testing.T) {
        }
 
        cmd := exec.Command("go", "build", "-buildmode=c-archive", "-gcflags=-shared=false", "-o", "libgo2.a", "./libgo2")
-       t.Log(cmd.Args)
        out, err := cmd.CombinedOutput()
-       t.Logf("%s", out)
+       t.Logf("%v\n%s", cmd.Args, out)
        if err != nil {
                t.Fatal(err)
        }
@@ -804,23 +833,22 @@ func TestCompileWithoutShared(t *testing.T) {
        if runtime.Compiler == "gccgo" {
                ccArgs = append(ccArgs, "-lgo")
        }
-       t.Log(ccArgs)
        out, err = exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput()
+       t.Logf("%v\n%s", ccArgs, out)
 
        // If -no-pie unrecognized, try -nopie if this is possibly clang
        if err != nil && bytes.Contains(out, []byte("unknown")) && !strings.Contains(cc[0], "gcc") {
                ccArgs = append(cc, "-o", exe, "-nopie", "main5.c", "libgo2.a")
-               t.Log(ccArgs)
                out, err = exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput()
+               t.Logf("%v\n%s", ccArgs, out)
        }
 
        // Don't use either -no-pie or -nopie
        if err != nil && bytes.Contains(out, []byte("unrecognized")) {
-               ccArgs := append(cc, "-o", exe, "main5.c", "libgo2.a")
-               t.Log(ccArgs)
+               ccArgs = append(cc, "-o", exe, "main5.c", "libgo2.a")
                out, err = exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput()
+               t.Logf("%v\n%s", ccArgs, out)
        }
-       t.Logf("%s", out)
        if err != nil {
                t.Fatal(err)
        }
@@ -829,17 +857,15 @@ func TestCompileWithoutShared(t *testing.T) {
        }
 
        binArgs := append(cmdToRun(exe), "1")
-       t.Log(binArgs)
        out, err = exec.Command(binArgs[0], binArgs[1:]...).CombinedOutput()
-       t.Logf("%s", out)
+       t.Logf("%v\n%s", binArgs, out)
        expectSignal(t, err, syscall.SIGSEGV)
 
        // SIGPIPE is never forwarded on darwin. See golang.org/issue/33384.
        if runtime.GOOS != "darwin" && runtime.GOOS != "ios" {
                binArgs := append(cmdToRun(exe), "3")
-               t.Log(binArgs)
                out, err = exec.Command(binArgs[0], binArgs[1:]...).CombinedOutput()
-               t.Logf("%s", out)
+               t.Logf("%v\n%s", binArgs, out)
                expectSignal(t, err, syscall.SIGPIPE)
        }
 }
@@ -894,8 +920,9 @@ func TestManyCalls(t *testing.T) {
        }
 
        cmd := exec.Command("go", "build", "-buildmode=c-archive", "-o", "libgo7.a", "./libgo7")
-       if out, err := cmd.CombinedOutput(); err != nil {
-               t.Logf("%s", out)
+       out, err := cmd.CombinedOutput()
+       t.Logf("%v\n%s", cmd.Args, out)
+       if err != nil {
                t.Fatal(err)
        }
        checkLineComments(t, "libgo7.h")
@@ -904,16 +931,18 @@ func TestManyCalls(t *testing.T) {
        if runtime.Compiler == "gccgo" {
                ccArgs = append(ccArgs, "-lgo")
        }
-       if out, err := exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput(); err != nil {
-               t.Logf("%s", out)
+       out, err = exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput()
+       t.Logf("%v\n%s", ccArgs, out)
+       if err != nil {
                t.Fatal(err)
        }
+       checkIsExecutable(t, "./testp7"+exeSuffix)
 
        argv := cmdToRun("./testp7")
        cmd = exec.Command(argv[0], argv[1:]...)
-       var sb strings.Builder
-       cmd.Stdout = &sb
-       cmd.Stderr = &sb
+       sb := new(strings.Builder)
+       cmd.Stdout = sb
+       cmd.Stderr = sb
        if err := cmd.Start(); err != nil {
                t.Fatal(err)
        }
@@ -926,8 +955,9 @@ func TestManyCalls(t *testing.T) {
        )
        defer timer.Stop()
 
-       if err := cmd.Wait(); err != nil {
-               t.Log(sb.String())
+       err = cmd.Wait()
+       t.Logf("%v\n%s", cmd.Args, sb)
+       if err != nil {
                t.Error(err)
        }
 }
@@ -949,23 +979,26 @@ func TestPreemption(t *testing.T) {
        }
 
        cmd := exec.Command("go", "build", "-buildmode=c-archive", "-o", "libgo8.a", "./libgo8")
-       if out, err := cmd.CombinedOutput(); err != nil {
-               t.Logf("%s", out)
+       out, err := cmd.CombinedOutput()
+       t.Logf("%v\n%s", cmd.Args, out)
+       if err != nil {
                t.Fatal(err)
        }
        checkLineComments(t, "libgo8.h")
 
        ccArgs := append(cc, "-o", "testp8"+exeSuffix, "main8.c", "libgo8.a")
-       if out, err := exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput(); err != nil {
-               t.Logf("%s", out)
+       out, err = exec.Command(ccArgs[0], ccArgs[1:]...).CombinedOutput()
+       t.Logf("%v\n%s", ccArgs, out)
+       if err != nil {
                t.Fatal(err)
        }
+       checkIsExecutable(t, "./testp8"+exeSuffix)
 
        argv := cmdToRun("./testp8")
        cmd = exec.Command(argv[0], argv[1:]...)
-       var sb strings.Builder
-       cmd.Stdout = &sb
-       cmd.Stderr = &sb
+       sb := new(strings.Builder)
+       cmd.Stdout = sb
+       cmd.Stderr = sb
        if err := cmd.Start(); err != nil {
                t.Fatal(err)
        }
@@ -978,8 +1011,9 @@ func TestPreemption(t *testing.T) {
        )
        defer timer.Stop()
 
-       if err := cmd.Wait(); err != nil {
-               t.Log(sb.String())
+       err = cmd.Wait()
+       t.Logf("%v\n%s", cmd.Args, sb)
+       if err != nil {
                t.Error(err)
        }
 }