test: bug369 failing on Plan 9

[0intro]

The test bug369 was enabled as part of change 1774.

It is failing on Plan 9, because the working directory
is changed between two go tool 8g calls.

The test is run from /usr/go/test. When running the test,
the working directly is firstly set to ./fixedbugs/bug369.dir
using os.Chdir, then it is reset to /usr/go/test after the first
successfull go tool 8g call.

term% cd /usr/go/test
term% go run run.go -- fixedbugs/bug369.go
# go run run.go -- fixedbugs/bug369.go
exit status: 'go 1364366: 1'
getwd /usr/go/test/fixedbugs/bug369.dir
go tool 8g -N -o slow.8 pkg.go
getwd /usr/go/test
go tool 8g -o fast.8 pkg.go
open pkg.go: 'pkg.go' file does not exist

exit status: 'go 1364381: 1'
exit status: 'bug369 1364373: 1'

FAIL    fixedbugs/bug369.go 1.578s
exit status: 'run 1364363: 1'

[0intro]

Actually, the path is correct every two go tool 8g run.

term% go run run.go -- fixedbugs/bug369.go
# go run run.go -- fixedbugs/bug369.go
incorrect output
getwd /usr/go/test/fixedbugs/bug369.dir
go tool 8g -N -o slow.8 pkg.go
getwd /usr/go/test
go tool 8g -o fast.8 pkg.go
open pkg.go: 'pkg.go' file does not exist

exit status: 'go 1372660: 1'
getwd /usr/go/test/fixedbugs/bug369.dir
go tool 8g -o main.8 main.go
main.go:13: can't find import: "./fast"

exit status: 'go 1372664: 1'
getwd /usr/go/test
go tool 8l -o a.exe main.8
cannot open file: main.8

exit status: 'go 1372668: 1'
getwd /usr/go/test/fixedbugs/bug369.dir
./a.exe

fork/exec ./a.exe: './a.exe' file does not exist

FAIL    fixedbugs/bug369.go 1.787s
exit status: 'run 1372642: 1'

[0intro]

When running this program, I can't see any call to syscall.Chdir in Go
(except the first explicit os.Chdir), or any chdir syscall using ratrace.

It works fine when specifying the working directory explicitly
with exec.Cmd.Dir when forking, instead of calling os.Chdir
in the parent. For example:

cmd := exec.Command(name, args...)
cmd.Dir = filepath.Join(".", "fixedbugs", "bug369.dir")
_, err := cmd.CombinedOutput()

[josharian]

I think there's a similar working directory problem with Windows. It'd be good to understand what it happening, but either way, perhaps we should switch to using exec.Cmd.Dir.

[bradfitz]

I'd rather understand the problem before hiding from it.

[0intro]

I don't think we should change this test. It is actually very useful to trigger this particular issue on Plan 9.

[bradfitz]

We should probably also add a specific test for this issue once it's understood.

[0intro]

I'm now able to reproduce this issue with a smaller
program, without having to run go tool 8g.

To reproduce this issue reliably, you need a first program
forking a second one, forking a third one.

• /tmp/proc1 https://play.golang.org/p/bmvVPB_Zpf
• /tmp/proc2 https://play.golang.org/p/76T-7JRpI8
• /tmp/proc3 https://play.golang.org/p/krdvVrzBe2

term% pwd
/usr/djc
term% /tmp/proc1
proc1 start
proc1 getwd /usr/djc
proc1 chdir /sys/src/9/pc
proc1 getwd /sys/src/9/pc
proc2 start
proc2 getwd /sys/src/9/pc
proc3 start
proc3 getwd /sys/src/9/pc
proc2 getwd /sys/src/9/pc
proc1 getwd /usr/djc

If you comment run("/tmp/proc3") in proc2, you get a race:

term% /tmp/proc1
proc1 start
proc1 getwd /usr/djc
proc1 chdir /sys/src/9/pc
proc1 getwd /sys/src/9/pc
proc2 start
proc2 getwd /sys/src/9/pc
proc2 getwd /sys/src/9/pc
proc1 getwd /usr/djc

term% /tmp/proc1
proc1 start
proc1 getwd /usr/djc
proc1 chdir /sys/src/9/pc
proc1 getwd /sys/src/9/pc
proc2 start
proc2 getwd /sys/src/9/pc
proc2 getwd /sys/src/9/pc
proc1 getwd /sys/src/9/pc

The final working directory in proc1 is either /usr/djc or /sys/src/9/pc.
I suspect there could be an issue somewhere in forkAndExecInChild.

[alexbrainman]

I don't see any problems with directory changing on windows:

diff --git a/test/fixedbugs/bug369.go b/test/fixedbugs/bug369.go
index 519703f..59d535f 100644
--- a/test/fixedbugs/bug369.go
+++ b/test/fixedbugs/bug369.go
@@ -1,4 +1,3 @@
-// +build !nacl,!windows
 // run

 // Copyright 2011 The Go Authors.  All rights reserved.
@@ -37,6 +36,8 @@ func main() {
 }

 func run(name string, args ...string) {
+   wd, _ := os.Getwd()
+   fmt.Printf("%v: %v %v\n", wd, name, args)
    cmd := exec.Command(name, args...)
    out, err := cmd.CombinedOutput()
    if err != nil {

C:\go\root\test>go run run.go -- fixedbugs/bug369.go
# go run run.go -- fixedbugs/bug369.go
exit status 1
C:\go\root\test\fixedbugs\bug369.dir: go [tool 8g -N -o slow.8 pkg.go]
C:\go\root\test\fixedbugs\bug369.dir: go [tool 8g -o fast.8 pkg.go]
C:\go\root\test\fixedbugs\bug369.dir: go [tool 8g -o main.8 main.go]
main.go:8: imported and not used: "flag"
main.go:9: imported and not used: "os"
main.go:10: imported and not used: "runtime"
main.go:11: imported and not used: "testing"
main.go:13: import path contains invalid character ':': "C:/go/root/test/fixedbugs/bug369.dir/fast"
main.go:14: import path contains invalid character ':': "C:/go/root/test/fixedbugs/bug369.dir/slow"
main.go:19: undefined: <nil>.testing
main.go:21: undefined: <nil>.fast
main.go:25: undefined: <nil>.testing
main.go:27: undefined: <nil>.slow
main.go:27: too many errors

exit status 1
exit status 1

FAIL    fixedbugs\bug369.go     0.906s
exit status 1

[ality]

Sorry for the delay. Holidays ...

This happens because the runtime on Plan 9 uses distinct
processes for each M. There are no threads like on the
other Unix-like systems.

Notably, if you call os.Chdir and then the runtime moves
your goroutine onto another proc, the working directory
will not have changed. This also happens if you call
os.Chdir in another goroutine that runs on another proc.

https://play.golang.org/p/HPJ_3_82EP

To fix this, we'd have to change os.Chdir to notify each
runtime proc that working directory needs to be updated.

(The same problem occurs with with os.Getwd, os.Getpid, and
os.Getppid.)

I will fix this but it's not going to be pretty. I'll
either have to send each runtime proc a note or somehow
arrange for the runtime to set the working directory
when a goroutine becomes runnable. I think Russ will
hurt me if I try the latter, though. :)

[josharian]

Interesting.

Here's a very naive suggestion. Rather than setting the working directory when a goroutine becomes runnable, what if it were set instead at the beginning of every (relevant) syscall? There shouldn't be anything that depends on the cwd, pid, or ppid outside of syscall (right?), and that would keep the change scope limited.

[bradfitz]

I was about to reply with the exact same thing.

I can only think of a handful of places. We could add a couple new functions to pkg syscall (or an internal/syscall), to set, test, and fix the desired program-wide working directory, protected by a mutex in the syscall package, similar to the ForkLock.

[bradfitz]

FWIW, and mostly as a note to myself, I am able to replicate this bug with gomote, even though gomote isn't very polished or easy to use yet:

$ gomote create plan9-386-gcepartial
2015/02/08 13:35:34 Sent create request. Waiting for operation.
2015/02/08 13:35:55 Instance created.
plan9-386-gcepartial    https://104.154.73.115

$ gomote put14 plan9-386-gcepartial
$ gomote puttar -gorev=a35181ba7fcb -dir=go plan9-386-gcepartial
$ gomote run plan9-386-gcepartial go/src/make.rc
$ gomote run  plan9-386-gcepartial /bin/rc -c 'path=$WORKDIR/go/bin; cd $WORKDIR/go/test && go run run.go -- fixedbugs/bug369.go'
# go run run.go -- fixedbugs/bug369.go
exit status: 'go 890: 1'
open pkg.go: 'pkg.go' file does not exist

exit status: 'go 907: 1'
exit status: 'bug369 899: 1'

FAIL    fixedbugs/bug369.go     0.951s
exit status: 'run 888: 1'
Error running run: exit status: 'rc 880: go 881: 1'

[bradfitz]

I sent out https://go-review.googlesource.com/6350 which fixes this.