Flaky test TestAdvertisedReferencesNotExists

[smola]

This test is flaky, it fails randomly and quite often:

FAIL: <autogenerated>:1: UploadPackSuite.TestAdvertisedReferencesNotExists
/home/travis/gopath/src/gopkg.in/src-d/go-git.v4/plumbing/transport/test/upload_pack.go:55:
    c.Assert(err, Equals, transport.ErrRepositoryNotFound)
... obtained *errors.errorString = &errors.errorString{s:"unexpected EOF"} ("unexpected EOF")
... expected *errors.errorString = &errors.errorString{s:"repository not found"} ("repository not found")
... Difference:
...     s: "unexpected EOF" != "repository not found"

https://travis-ci.org/src-d/go-git/jobs/433952695#L1615

[mccurdyc]

@smola I'd like to dig in here and try to figure out why this test is flaky. Can I claim this one?

[mccurdyc]

In the travis details that you linked, it looks like this test isn't even being run.

=== RUN   Test
OK: 36 passed, 1 skipped
--- PASS: Test (0.37s)
PASS
coverage: 73.5% of statements
ok  	gopkg.in/src-d/go-git.v4/plumbing/transport/ssh	0.376s	coverage: 73.5% of statements
?   	gopkg.in/src-d/go-git.v4/plumbing/transport/test	[no test files]
?   	gopkg.in/src-d/go-git.v4/storage	[no test files]

I tried the following:

cd plumbing/transport/test

Then,

$ go test -check.f UploadPackSuite
?   	gopkg.in/src-d/go-git.v4/plumbing/transport/test	[no test files]

Can you point me in the correct direction?

[smola]

@mccurdyc Of course, feel free to dig in (good luck!). The issue is actually in the ssh package tests, which uses transport/test.

The link I originally posted was probably to a job that was later manually re-triggered. Here's one failing example:

----------------------------------------------------------------------
FAIL: <autogenerated>:1: UploadPackSuite.TestAdvertisedReferencesNotExists
/home/travis/gopath/src/gopkg.in/src-d/go-git.v4/plumbing/transport/test/upload_pack.go:55:
    c.Assert(err, Equals, transport.ErrRepositoryNotFound)
... obtained *errors.errorString = &errors.errorString{s:"unexpected EOF"} ("unexpected EOF")
... expected *errors.errorString = &errors.errorString{s:"repository not found"} ("repository not found")
... Difference:
...     s: "unexpected EOF" != "repository not found"
OOPS: 35 passed, 1 skipped, 1 FAILED
--- FAIL: Test (0.58s)
FAIL
coverage: 73.5% of statements
FAIL	gopkg.in/src-d/go-git.v4/plumbing/transport/ssh	0.589s

I don't know anything else, but feel free to ask any specific question as you progress.

[mccurdyc]

@smola (or has anyone else) been able to get this to fail on their local machine or does it seem to only happen on the travis server?

[mccurdyc]

@smola I have gotten it to fail locally.

[mccurdyc]

my thought is that it is resource-related (probably CPU as my memory didn't spike, but my CPU did) because I can quickly get it to fail when running 4 instances of the following script

#!/usr/bin/env bash
for i in {1..5000}
do
  echo $i

  mpstat -P ALL &>> out.txt
  go test -v &>> out.txt

  if grep -q 'FAIL' out.txt
  then
    break
  fi
done

[mccurdyc]

previously, I was able to get it to fail after about 350 iterations with a single instance of the script running, so I will try to collect more info during a single iteration

[mccurdyc]

Obviously still trying to figure out why, but the firstErrLine channel is sending an empty object when it fails:

A normal run (the expected output):

=== RUN   Test
OK: 36 passed, 1 skipped
--- PASS: Test (0.42s)
PASS
ok  	gopkg.in/src-d/go-git.v4/plumbing/transport/ssh	0.440s
s.firstErrLine: fatal: '//tmp/go-git-ssh-36699748929944/non-existent.git' does not appear to be a git repository OK: true
s.firstErrLine: fatal: '//tmp/go-git-ssh-36699748929944/non-existent.git' does not appear to be a git repository OK: true
OK: 36 passed, 1 skipped
--- PASS: Test (0.41s)
PASS
ok  	gopkg.in/src-d/go-git.v4/plumbing/transport/ssh	0.415s

The FAIL, unexpected output:

=== RUN   Test
s.firstErrLine: fatal: '//tmp/go-git-ssh-42559873101469/non-existent.git' does not appear to be a git repository OK: true
s.firstErrLine:  OK: false

----------------------------------------------------------------------
FAIL: <autogenerated>:1: UploadPackSuite.TestAdvertisedReferencesNotExists

/home/mccurdyc/go/src/gopkg.in/src-d/go-git.v4/plumbing/transport/test/upload_pack.go:55:
    c.Assert(err, Equals, transport.ErrRepositoryNotFound)
... obtained *errors.errorString = &errors.errorString{s:"unexpected EOF"} ("unexpected EOF")
... expected *errors.errorString = &errors.errorString{s:"repository not found"} ("repository not found")
... Difference:
...     s: "unexpected EOF" != "repository not found"


OOPS: 35 passed, 1 skipped, 1 FAILED
--- FAIL: Test (0.56s)
FAIL
exit status 1
FAIL	gopkg.in/src-d/go-git.v4/plumbing/transport/ssh	0.565s

[mccurdyc]

After digging in a bit more, I actually think it is something about https://github.com/src-d/go-git/blob/master/plumbing/transport/internal/common/common.go#L145 not being safe.

It may be related to reading a sub-processes' Stderr in a concurrent fashion.

[smola]

@mccurdyc There's no problem about reading stderr from a goroutine, but I think you got a bit closer.

We are reaching this point when we do not get any input from server's stdout. See:

go-git/plumbing/transport/internal/common/common.go

Lines 183 to 190 in 8b6ded6

	func (s *session) handleAdvRefDecodeError(err error) error {
	// If repository is not found, we get empty stdout and server writes an
	// error to stderr.
	if err == packp.ErrEmptyInput {
	s.finished = true
	if err := s.checkNotFoundError(); err != nil {
	return err
	}

But then on the goroutine where we read the error, we find that stderr is already closed:

go-git/plumbing/transport/internal/common/common.go

Lines 145 to 157 in 8b6ded6

	func (c *client) listenFirstError(r io.Reader) chan string {
	if r == nil {
	return nil
	}
	errLine := make(chan string, 1)
	go func() {
	s := bufio.NewScanner(r)
	if s.Scan() {
	errLine <- s.Text()
	} else {
	close(errLine)
	}

This code (package transport/internal/common) is reused for all protocols that we implement, but it's only failing for SSH, so it is probably be related to something in transport/ssh package or its tests.

I suspect it is related to the way we set up the testing SSH server (which uses the git-upload-pack binary under the hood):

go-git/plumbing/transport/ssh/upload_pack_test.go

Lines 90 to 110 in 8b6ded6

	if err := cmd.Start(); err != nil {
	fmt.Println(err)
	return
	}
	go func() {
	defer stdin.Close()
	io.Copy(stdin, s)
	}()
	go func() {
	defer stderr.Close()
	io.Copy(s.Stderr(), stderr)
	}()
	defer stdout.Close()
	io.Copy(s, stdout)
	if err := cmd.Wait(); err != nil {
	return
	}

I would say that it is one of these:

• We are closing stdout from git-upload-pack before starting to read stderr.
• Or, more likely, we close SSH session from the server before writing stderr from git-upload-pack to it.

Or something similar.

[mccurdyc]

@smola this is super helpful! I will continue looking

[smola]

Also defer stderr.Close() and defer stdout.Close() are probably not needed at all, closing stdin is good enough.

[mccurdyc]

@smola

go-git/plumbing/transport/test/upload_pack.go

Line 44 in 959dc01

defer func() { c.Assert(r.Close(), IsNil) }()

is where we are deferring the ssh session close, correct?