code review 9711043: ssh: add Output and CombinedOutput helpers

ssh: add Output and CombinedOutput helpers

[kr, 2013-05-23 23:37:48]

Hello golang-dev@googlegroups.com,

I'd like you to review this change to
https://code.google.com/p/go.crypto

[dfc, 2013-05-23 23:52:27]

Thanks kr. The code looks good, could I ask you to try adding a test to
session_test.go. It should be possible to defined your own serverType handler
(look at what the dial function takes) which outputs some text to both stdout
and stderr, then closes the connection. In the Output case, the stderr text
should be discaded, in the Combined they should be both present.

[kr, 2013-05-24 02:14:34]

Hello golang-dev@googlegroups.com, dave@cheney.net (cc:
golang-dev@googlegroups.com),

Please take another look.

[dfc, 2013-05-25 02:44:48]

On 2013/05/24 02:14:34, kr wrote:
> Hello mailto:golang-dev@googlegroups.com, mailto:dave@cheney.net (cc:
> mailto:golang-dev@googlegroups.com),
> 
> Please take another look.

Interestingly, there might be a data race here.

WARNING: DATA RACE
Read by goroutine 62:
  bytes.(*Buffer).ReadFrom()
      /home/dfc/go/src/pkg/bytes/buffer.go:153 +0x9c
  io.Copy()
      /home/dfc/go/src/pkg/io/io.go:340 +0xb3
  code.google.com/p/go.crypto/ssh.func·009()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:500 +0xde
  code.google.com/p/go.crypto/ssh.func·006()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:366 +0x37
  gosched0()
      /home/dfc/go/src/pkg/runtime/proc.c:1218 +0x9f

Previous write by goroutine 61:
  bytes.(*Buffer).Truncate()
      /home/dfc/go/src/pkg/bytes/buffer.go:70 +0x118
  bytes.(*Buffer).ReadFrom()
      /home/dfc/go/src/pkg/bytes/buffer.go:154 +0xd2
  io.Copy()
      /home/dfc/go/src/pkg/io/io.go:340 +0xb3
  code.google.com/p/go.crypto/ssh.func·008()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:487 +0xde
  code.google.com/p/go.crypto/ssh.func·006()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:366 +0x37
  gosched0()
      /home/dfc/go/src/pkg/runtime/proc.c:1218 +0x9f

Goroutine 62 (running) created at:
  code.google.com/p/go.crypto/ssh.(*Session).start()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:367 +0x303
  code.google.com/p/go.crypto/ssh.(*Session).Start()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:274 +0x3c9
  code.google.com/p/go.crypto/ssh.(*Session).Run()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:290 +0x46
  code.google.com/p/go.crypto/ssh.(*Session).CombinedOutput()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:320 +0x354
  code.google.com/p/go.crypto/ssh.TestSessionCombinedOutput()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session_test.go:176 +0x20f
  testing.tRunner()
      /home/dfc/go/src/pkg/testing/testing.go:353 +0x12f
  gosched0()
      /home/dfc/go/src/pkg/runtime/proc.c:1218 +0x9f

Goroutine 61 (finished) created at:
  code.google.com/p/go.crypto/ssh.(*Session).start()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:367 +0x303
  code.google.com/p/go.crypto/ssh.(*Session).Start()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:274 +0x3c9
  code.google.com/p/go.crypto/ssh.(*Session).Run()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:290 +0x46
  code.google.com/p/go.crypto/ssh.(*Session).CombinedOutput()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session.go:320 +0x354
  code.google.com/p/go.crypto/ssh.TestSessionCombinedOutput()
      /home/dfc/src/code.google.com/p/go.crypto/ssh/session_test.go:176 +0x20f
  testing.tRunner()
      /home/dfc/go/src/pkg/testing/testing.go:353 +0x12f
  gosched0()
      /home/dfc/go/src/pkg/runtime/proc.c:1218 +0x9f

[kr, 2013-05-25 06:25:03]

On 2013/05/25 02:44:48, dfc wrote:
> Interestingly, there might be a data race here.

I get similar results from tip.

Do we need to put this CL on hold until the race
is fixed (or determined not to exist)?

[kr, 2013-05-25 06:32:26]

FWIW:

$ go test -race -v
...
=== RUN TestInvalidServerMessage
==================
WARNING: DATA RACE
Write by goroutine 20:
  code.google.com/p/go.crypto/ssh.(*clientChan).waitForChannelOpenResponse()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/channel.go:482 +0x250
  code.google.com/p/go.crypto/ssh.(*ClientConn).NewSession()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/session.go:538 +0x1f5
  code.google.com/p/go.crypto/ssh.TestInvalidServerMessage()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/session_test.go:287 +0xb0
  testing.tRunner()
      /usr/local/go/src/pkg/testing/testing.go:353 +0x12f
  gosched0()
      /usr/local/go/src/pkg/runtime/proc.c:1218 +0x9f

Previous read by goroutine 22:
  code.google.com/p/go.crypto/ssh.(*channel).sendClose()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/channel.go:105 +0x3f
  code.google.com/p/go.crypto/ssh.(*clientChan).Close()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/channel.go:499 +0x16d
  code.google.com/p/go.crypto/ssh.(*chanList).closeAll()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:510 +0xe9
  code.google.com/p/go.crypto/ssh.func·005()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:198 +0xab
  code.google.com/p/go.crypto/ssh.(*ClientConn).mainLoop()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:203 +0xfb
  gosched0()
      /usr/local/go/src/pkg/runtime/proc.c:1218 +0x9f

Goroutine 20 (running) created at:
  testing.RunTests()
      /usr/local/go/src/pkg/testing/testing.go:433 +0xaef
  testing.Main()
      /usr/local/go/src/pkg/testing/testing.go:365 +0xab
  main.main()
      code.google.com/p/go.crypto/ssh/_test/_testmain.go:125 +0xda
  runtime.main()
      /usr/local/go/src/pkg/runtime/proc.c:182 +0x91

Goroutine 22 (finished) created at:
  code.google.com/p/go.crypto/ssh.Client()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:47 +0x3b9
  code.google.com/p/go.crypto/ssh.Dial()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:431 +0xa7
  code.google.com/p/go.crypto/ssh.dial()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/session_test.go:75 +0x549
  code.google.com/p/go.crypto/ssh.TestInvalidServerMessage()
      /Users/kr/src/code.google.com/p/go.crypto/ssh/session_test.go:285 +0x45
  testing.tRunner()
      /usr/local/go/src/pkg/testing/testing.go:353 +0x12f
  gosched0()
      /usr/local/go/src/pkg/runtime/proc.c:1218 +0x9f

==================
--- PASS: TestInvalidServerMessage (0.23 seconds)
...

[dfc, 2013-05-27 10:45:48]

Yeah, that is a fair call. I think @fullung found another race in the
ssh package, which hasn't been addressed yet.

I'm also concerned that this code was copied (with the best of
intentions) from the os/exec package, so probably means that
cmd.CombinedOutput has a race as well.

I don't want to block this CL but currently the -race build is not
unhappy, so I don't want to upset it. What about introducing a wrapper
around bytes.Buffer with a Mutex to prevent concurrent writes ?

On Sat, May 25, 2013 at 4:32 PM,  <kr@xph.us> wrote:
> FWIW:
>
> $ go test -race -v
> ...
> === RUN TestInvalidServerMessage
> ==================
> WARNING: DATA RACE
> Write by goroutine 20:
>
> code.google.com/p/go.crypto/ssh.(*clientChan).waitForChannelOpenResponse()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/channel.go:482
> +0x250
>   code.google.com/p/go.crypto/ssh.(*ClientConn).NewSession()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/session.go:538
> +0x1f5
>   code.google.com/p/go.crypto/ssh.TestInvalidServerMessage()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/session_test.go:287
> +0xb0
>   testing.tRunner()
>       /usr/local/go/src/pkg/testing/testing.go:353 +0x12f
>   gosched0()
>       /usr/local/go/src/pkg/runtime/proc.c:1218 +0x9f
>
> Previous read by goroutine 22:
>   code.google.com/p/go.crypto/ssh.(*channel).sendClose()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/channel.go:105 +0x3f
>   code.google.com/p/go.crypto/ssh.(*clientChan).Close()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/channel.go:499
> +0x16d
>   code.google.com/p/go.crypto/ssh.(*chanList).closeAll()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:510 +0xe9
>   code.google.com/p/go.crypto/ssh.func·005()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:198 +0xab
>   code.google.com/p/go.crypto/ssh.(*ClientConn).mainLoop()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:203 +0xfb
>   gosched0()
>       /usr/local/go/src/pkg/runtime/proc.c:1218 +0x9f
>
> Goroutine 20 (running) created at:
>   testing.RunTests()
>       /usr/local/go/src/pkg/testing/testing.go:433 +0xaef
>   testing.Main()
>       /usr/local/go/src/pkg/testing/testing.go:365 +0xab
>   main.main()
>       code.google.com/p/go.crypto/ssh/_test/_testmain.go:125 +0xda
>   runtime.main()
>       /usr/local/go/src/pkg/runtime/proc.c:182 +0x91
>
> Goroutine 22 (finished) created at:
>   code.google.com/p/go.crypto/ssh.Client()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:47 +0x3b9
>   code.google.com/p/go.crypto/ssh.Dial()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/client.go:431 +0xa7
>   code.google.com/p/go.crypto/ssh.dial()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/session_test.go:75
> +0x549
>   code.google.com/p/go.crypto/ssh.TestInvalidServerMessage()
>       /Users/kr/src/code.google.com/p/go.crypto/ssh/session_test.go:285
> +0x45
>   testing.tRunner()
>       /usr/local/go/src/pkg/testing/testing.go:353 +0x12f
>   gosched0()
>       /usr/local/go/src/pkg/runtime/proc.c:1218 +0x9f
>
> ==================
> --- PASS: TestInvalidServerMessage (0.23 seconds)
> ...
>
>
> https://codereview.appspot.com/9711043/

[kr, 2013-05-28 23:40:48]

PTAL

[kr, 2013-05-29 01:58:04]

Adding a mutex, as you suggested, makes the race detector happy.

But I'm still a little concerned, because it seems reasonable for
users of this package to do something similar to what this patch
originally did. They'll be surprised when they use a single io.Writer
for stdout and stderr and it ends up being called concurrently.

[dfc, 2013-05-29 02:10:01]

Yeah. I'm also concerned that this pattern is being used inside
os/exec, and when I took a look last night there wasn't a test that
covered cmd.CombinedOutput so there might be a race there.

wrt/ people home brewing this solution themselves, I can see how that
could happen and be confusing. I'd like to address this once I know
how os/exec.Command.CombinedOutput handles, or will handle, this
situation as they are the mode the ssh package follows. Does that
sound like a reasonable approach ?

+agl for his views, i'll commit this patch after work tonight if there
are no other comments.

On Wed, May 29, 2013 at 11:58 AM,  <kr@xph.us> wrote:
> Adding a mutex, as you suggested, makes the race detector happy.
>
> But I'm still a little concerned, because it seems reasonable for
> users of this package to do something similar to what this patch
> originally did. They'll be surprised when they use a single io.Writer
> for stdout and stderr and it ends up being called concurrently.
>
> https://codereview.appspot.com/9711043/

[kr, 2013-05-29 05:14:54]

On 2013/05/29 02:10:01, dfc wrote:
> wrt/ people home brewing this solution themselves, I can see how that
> could happen and be confusing. I'd like to address this once I know
> how os/exec.Command.CombinedOutput handles, or will handle, this
> situation as they are the mode the ssh package follows. Does that
> sound like a reasonable approach ?

Sure.

os/exec says "If Stdout and Stderr are the same writer, at most one goroutine at
a time will call Write." It explicitly checks for equality in Cmd.stderr and
returns the same fd in that case, also avoiding creating another c.goroutine.
In ssh it would have to avoid creating another s.copyFuncs entry.

[dfc, 2013-05-29 06:06:35]

*** Submitted as
https://code.google.com/p/go/source/detail?r=273987d8ccbc&repo=crypto ***

ssh: add Output and CombinedOutput helpers

R=golang-dev, dave
CC=golang-dev
https://codereview.appspot.com/9711043

Committer: Dave Cheney <dave@cheney.net>

[dfc, 2013-05-29 06:11:32]

Thanks. I did not want to block this CL any further. Now we have a
test case that will trigger the race detector I have raised
https://code.google.com/p/go/issues/detail?id=5582, to address the
underlying problem. Then we can remove the singleWriter shim.

On Wed, May 29, 2013 at 4:06 PM,  <dave@cheney.net> wrote:
> *** Submitted as
> https://code.google.com/p/go/source/detail?r=273987d8ccbc&repo=crypto
> ***
>
>
> ssh: add Output and CombinedOutput helpers
>
> R=golang-dev, dave
> CC=golang-dev
> https://codereview.appspot.com/9711043
>
> Committer: Dave Cheney <dave@cheney.net>
>
>
> https://codereview.appspot.com/9711043/

[albert.strasheim, 2013-05-30 06:33:04]

On 2013/05/29 06:11:32, dfc wrote:
> On Wed, May 29, 2013 at 4:06 PM,  <mailto:dave@cheney.net> wrote:
> > *** Submitted as
> > https://code.google.com/p/go/source/detail?r=273987d8ccbc&repo=crypto
> > ***
> > ssh: add Output and CombinedOutput helpers

This test is flaky:

--- FAIL: TestSessionCombinedOutput-96 (0.08 seconds)
session_test.go:183: Remote command did not return expected string:
session_test.go:184: want "this-is-stdout.this-is-stderr."
session_test.go:185: got  "this-is-stderr.this-is-stdout."

[dfc, 2013-05-30 06:33:52]

I was afraid of that, I will make a note to submit a small patch to
try both variations.

On Thu, May 30, 2013 at 4:33 PM,  <fullung@gmail.com> wrote:
> On 2013/05/29 06:11:32, dfc wrote:
>
>> On Wed, May 29, 2013 at 4:06 PM,  <mailto:dave@cheney.net> wrote:
>> > *** Submitted as
>> >
>
> https://code.google.com/p/go/source/detail?r=273987d8ccbc&repo=crypto
>>
>> > ***
>> > ssh: add Output and CombinedOutput helpers
>
>
> This test is flaky:
>
> --- FAIL: TestSessionCombinedOutput-96 (0.08 seconds)
> session_test.go:183: Remote command did not return expected string:
> session_test.go:184: want "this-is-stdout.this-is-stderr."
> session_test.go:185: got  "this-is-stderr.this-is-stdout."
>
> https://codereview.appspot.com/9711043/

[dfc, 2013-06-01 00:06:43]

Sent https://codereview.appspot.com/9921044/

On Thu, May 30, 2013 at 4:33 PM, Dave Cheney <dave@cheney.net> wrote:
> I was afraid of that, I will make a note to submit a small patch to
> try both variations.
>
> On Thu, May 30, 2013 at 4:33 PM,  <fullung@gmail.com> wrote:
>> On 2013/05/29 06:11:32, dfc wrote:
>>
>>> On Wed, May 29, 2013 at 4:06 PM,  <mailto:dave@cheney.net> wrote:
>>> > *** Submitted as
>>> >
>>
>> https://code.google.com/p/go/source/detail?r=273987d8ccbc&repo=crypto
>>>
>>> > ***
>>> > ssh: add Output and CombinedOutput helpers
>>
>>
>> This test is flaky:
>>
>> --- FAIL: TestSessionCombinedOutput-96 (0.08 seconds)
>> session_test.go:183: Remote command did not return expected string:
>> session_test.go:184: want "this-is-stdout.this-is-stderr."
>> session_test.go:185: got  "this-is-stderr.this-is-stdout."
>>
>> https://codereview.appspot.com/9711043/