Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

bytes: Random behavior when reading ssh output with bytes.Buffer #45770

Closed
Canadadry opened this issue Apr 26, 2021 · 7 comments
Closed

bytes: Random behavior when reading ssh output with bytes.Buffer #45770

Canadadry opened this issue Apr 26, 2021 · 7 comments
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.

Comments

@Canadadry
Copy link

What version of Go are you using (go version)?

$ go version
go version go1.16.3 darwin/arm64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE=""
GOARCH="arm64"
GOBIN=""
GOCACHE="/Users/canadadry/Library/Caches/go-build"
GOENV="/Users/canadadry/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="arm64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/canadadry/go/pkg/mod"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/canadadry/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/canadadry/.brew/Cellar/go/1.16.3/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/canadadry/.brew/Cellar/go/1.16.3/libexec/pkg/tool/darwin_arm64"
GOVCS=""
GOVERSION="go1.16.3"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/Users/canadadry/Prog/ssh/go.mod"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/gj/q0mflgrx5tg41qsqh7hbfrm40000gn/T/go-build1246411259=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

I want to excecute a shell command over ssh then write the result into a bytes.Buffer and print the content of the Buffer. Here a minimal code reproducing the bug :

package main

import (
	"bytes"
	"flag"
	"fmt"
	"golang.org/x/crypto/ssh"
	"golang.org/x/crypto/ssh/knownhosts"
	"io/ioutil"
	"net"
	"os"
	"path/filepath"
)

type spy struct {
}

func (s *spy) Write(b []byte) (int, error) {
	fmt.Printf("%d : --%v--\n", len(b), b)
	return len(b), nil
}

func main() {
	if err := run(); err != nil {
		fmt.Println(err)
	}
}

func run() error {
	host := flag.String("h", "", "host")
	port := flag.String("p", "22", "port")
	user := flag.String("u", "", "user")
	useSpy := flag.Bool("s", false, "use spy")

	flag.Parse()

	PrivateKey, err := ioutil.ReadFile(filepath.Join(os.Getenv("HOME"), ".ssh", "id_rsa"))
	if err != nil {
		return err
	}
	key, err := ssh.ParsePrivateKey(PrivateKey)
	if err != nil {
		return err
	}
	hostKeyCallback, err := knownhosts.New(filepath.Join(os.Getenv("HOME"), ".ssh", "known_hosts"))
	if err != nil {
		return err
	}
	config := &ssh.ClientConfig{
		User:            *user,
		HostKeyCallback: hostKeyCallback,
		Auth: []ssh.AuthMethod{
			ssh.PublicKeys(key),
		},
	}
	c, err := ssh.Dial("tcp", net.JoinHostPort(*host, *port), config)
	if err != nil {
		return err
	}

	defer c.Close()

	session, err := c.NewSession()
	if err != nil {
		return err
	}

	defer session.Close()
	b := &bytes.Buffer{}
	s := &spy{}
	if *useSpy {
		session.Stdout = s
		session.Stderr = s
	} else {
		session.Stdout = b
		session.Stderr = b
	}
	err = session.Run("ls -la")
	if err != nil {
		return err
	}
	if !*useSpy {
		fmt.Println(b.String())
	}
	fmt.Println("end")
	return nil
}

What did you expect to see?

I want to always see the list of file on my server or a network error.

~/P/ssh > go run main.go -u $USER -h $HOST
total 28
drwxr-xr-x 7 root root 4096 Sep 15  2020 .
drwxr-xr-x 6 root root 4096 Sep 15  2020 ..
drwxr-xr-x 3 usr  usr  4096 Sep 15  2020 .config
drwxr-xr-x 3 usr  usr  4096 Sep 15  2020 public
drwxr-xr-x 2 usr  usr  4096 Sep 15  2020 sessions
drwxr-xr-x 2 root root 4096 Sep 15  2020 .ssh
drwxr-xr-x 2 usr  usr  4096 Apr 20 16:50 tmp

end

What did you see instead?

Some time I see nothing. No error and no output from the command. I suspect this to be linked on how the bytes.Buffer work inside since I am reading and writing in it but I have no idea on how make it more minimal.
Obviously when I use my spy I always see the result of my command.

~/P/ssh > go run main.go -u $USER -h $HOST
total 28
drwxr-xr-x 7 root root 4096 Sep 15  2020 .
drwxr-xr-x 6 root root 4096 Sep 15  2020 ..
drwxr-xr-x 3 usr  usr  4096 Sep 15  2020 .config
drwxr-xr-x 3 usr  usr  4096 Sep 15  2020 public
drwxr-xr-x 2 usr  usr  4096 Sep 15  2020 sessions
drwxr-xr-x 2 root root 4096 Sep 15  2020 .ssh
drwxr-xr-x 2 usr  usr  4096 Apr 20 16:50 tmp
end
~/P/ssh > go run main.go -u $USER -h $HOST

end
~/P/ssh > go run main.go -u $USER -h $HOST

end
~/P/ssh > go run main.go -u $USER -h $HOST
total 28
drwxr-xr-x 7 root root 4096 Sep 15  2020 .
drwxr-xr-x 6 root root 4096 Sep 15  2020 ..
drwxr-xr-x 3 usr  usr  4096 Sep 15  2020 .config
drwxr-xr-x 3 usr  usr  4096 Sep 15  2020 public
drwxr-xr-x 2 usr  usr  4096 Sep 15  2020 sessions
drwxr-xr-x 2 root root 4096 Sep 15  2020 .ssh
drwxr-xr-x 2 usr  usr  4096 Apr 20 16:50 tmp

end
@mvdan
Copy link
Member

mvdan commented Apr 26, 2021

I'd suggest that you use https://golang.org/wiki/Questions. This could be an issue with your program, such as a data race. Nothing seems to indicate a specific bug in the bytes package.

@mvdan mvdan added the WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided. label Apr 26, 2021
@ghost
Copy link

ghost commented Apr 26, 2021 •
edited by ghost
Loading

Try synchronizing writes: https://play.golang.org/p/GE50s3bxCtY

@seankhliao
Copy link
Member

There's a race between copying data to the buffer (which may grow) and reading the contents (also between writes from both stdin/stderr)

==================
WARNING: DATA RACE
Write at 0x00c00011e050 by goroutine 16:
  bytes.(*Buffer).ReadFrom()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:200 +0x44
  io.copyBuffer()
      /home/arccy/sdk/gotip/src/io/io.go:409 +0x1b3
  io.Copy()
      /home/arccy/sdk/gotip/src/io/io.go:382 +0xb2
  golang.org/x/crypto/ssh.(*Session).stderr.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:524 +0x2b
  golang.org/x/crypto/ssh.(*Session).start.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:383 +0x35
  golang.org/x/crypto/ssh.(*Session).start·dwrap·23()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:384 +0x47

Previous write at 0x00c00011e050 by goroutine 15:
  bytes.(*Buffer).ReadFrom()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:200 +0x44
  io.copyBuffer()
      /home/arccy/sdk/gotip/src/io/io.go:409 +0x1b3
  io.Copy()
      /home/arccy/sdk/gotip/src/io/io.go:382 +0x90
  golang.org/x/crypto/ssh.(*Session).stdout.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:511 +0x2b
  golang.org/x/crypto/ssh.(*Session).start.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:383 +0x35
  golang.org/x/crypto/ssh.(*Session).start·dwrap·23()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:384 +0x47

Goroutine 16 (running) created at:
  golang.org/x/crypto/ssh.(*Session).start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:382 +0x176
  golang.org/x/crypto/ssh.(*Session).Start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:293 +0x24b
  golang.org/x/crypto/ssh.(*Session).Run()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:310 +0x49
  main.run()
      /home/arccy/tmp/testrepo-394/main.go:80 +0x8f5
  main.main()
      /home/arccy/tmp/testrepo-394/main.go:24 +0x29

Goroutine 15 (running) created at:
  golang.org/x/crypto/ssh.(*Session).start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:382 +0x176
  golang.org/x/crypto/ssh.(*Session).Start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:293 +0x24b
  golang.org/x/crypto/ssh.(*Session).Run()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:310 +0x49
  main.run()
      /home/arccy/tmp/testrepo-394/main.go:80 +0x8f5
  main.main()
      /home/arccy/tmp/testrepo-394/main.go:24 +0x29
==================
==================
WARNING: DATA RACE
Read at 0x00c00011e030 by goroutine 16:
  bytes.(*Buffer).Len()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:73 +0x49
  bytes.(*Buffer).grow()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:118 +0x44
  bytes.(*Buffer).ReadFrom()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:202 +0x65
  io.copyBuffer()
      /home/arccy/sdk/gotip/src/io/io.go:409 +0x1b3
  io.Copy()
      /home/arccy/sdk/gotip/src/io/io.go:382 +0xb2
  golang.org/x/crypto/ssh.(*Session).stderr.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:524 +0x2b
  golang.org/x/crypto/ssh.(*Session).start.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:383 +0x35
  golang.org/x/crypto/ssh.(*Session).start·dwrap·23()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:384 +0x47

Previous write at 0x00c00011e030 by goroutine 15:
  bytes.(*Buffer).grow()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:144 +0x27a
  bytes.(*Buffer).ReadFrom()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:202 +0x65
  io.copyBuffer()
      /home/arccy/sdk/gotip/src/io/io.go:409 +0x1b3
  io.Copy()
      /home/arccy/sdk/gotip/src/io/io.go:382 +0x90
  golang.org/x/crypto/ssh.(*Session).stdout.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:511 +0x2b
  golang.org/x/crypto/ssh.(*Session).start.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:383 +0x35
  golang.org/x/crypto/ssh.(*Session).start·dwrap·23()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:384 +0x47

Goroutine 16 (running) created at:
  golang.org/x/crypto/ssh.(*Session).start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:382 +0x176
  golang.org/x/crypto/ssh.(*Session).Start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:293 +0x24b
  golang.org/x/crypto/ssh.(*Session).Run()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:310 +0x49
  main.run()
      /home/arccy/tmp/testrepo-394/main.go:80 +0x8f5
  main.main()
      /home/arccy/tmp/testrepo-394/main.go:24 +0x29

Goroutine 15 (running) created at:
  golang.org/x/crypto/ssh.(*Session).start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:382 +0x176
  golang.org/x/crypto/ssh.(*Session).Start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:293 +0x24b
  golang.org/x/crypto/ssh.(*Session).Run()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:310 +0x49
  main.run()
      /home/arccy/tmp/testrepo-394/main.go:80 +0x8f5
  main.main()
      /home/arccy/tmp/testrepo-394/main.go:24 +0x29
==================
==================
WARNING: DATA RACE
Read at 0x00c00011e048 by goroutine 16:
  bytes.(*Buffer).Len()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:73 +0x68
  bytes.(*Buffer).grow()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:118 +0x44
  bytes.(*Buffer).ReadFrom()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:202 +0x65
  io.copyBuffer()
      /home/arccy/sdk/gotip/src/io/io.go:409 +0x1b3
  io.Copy()
      /home/arccy/sdk/gotip/src/io/io.go:382 +0xb2
  golang.org/x/crypto/ssh.(*Session).stderr.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:524 +0x2b
  golang.org/x/crypto/ssh.(*Session).start.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:383 +0x35
  golang.org/x/crypto/ssh.(*Session).start·dwrap·23()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:384 +0x47

Previous write at 0x00c00011e048 by goroutine 15:
  bytes.(*Buffer).grow()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:147 +0x364
  bytes.(*Buffer).ReadFrom()
      /home/arccy/sdk/gotip/src/bytes/buffer.go:202 +0x65
  io.copyBuffer()
      /home/arccy/sdk/gotip/src/io/io.go:409 +0x1b3
  io.Copy()
      /home/arccy/sdk/gotip/src/io/io.go:382 +0x90
  golang.org/x/crypto/ssh.(*Session).stdout.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:511 +0x2b
  golang.org/x/crypto/ssh.(*Session).start.func1()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:383 +0x35
  golang.org/x/crypto/ssh.(*Session).start·dwrap·23()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:384 +0x47

Goroutine 16 (running) created at:
  golang.org/x/crypto/ssh.(*Session).start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:382 +0x176
  golang.org/x/crypto/ssh.(*Session).Start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:293 +0x24b
  golang.org/x/crypto/ssh.(*Session).Run()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:310 +0x49
  main.run()
      /home/arccy/tmp/testrepo-394/main.go:80 +0x8f5
  main.main()
      /home/arccy/tmp/testrepo-394/main.go:24 +0x29

Goroutine 15 (running) created at:
  golang.org/x/crypto/ssh.(*Session).start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:382 +0x176
  golang.org/x/crypto/ssh.(*Session).Start()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:293 +0x24b
  golang.org/x/crypto/ssh.(*Session).Run()
      /home/arccy/.data/go/pkg/mod/golang.org/x/crypto@v0.0.0-20210421170649-83a5a9bb288b/ssh/session.go:310 +0x49
  main.run()
      /home/arccy/tmp/testrepo-394/main.go:80 +0x8f5
  main.main()
      /home/arccy/tmp/testrepo-394/main.go:24 +0x29
==================

@mvdan
Copy link
Member

mvdan commented Apr 26, 2021

Others confirm my suspicion :) Closing as this is not a bug.

@mvdan mvdan closed this as completed Apr 26, 2021
@Canadadry
Copy link
Author

@seankhliao how did you got those error message ?

Thank you, I did not though this was a question. Well I did not except any response from you. May be we can improve the documentation on the crypto/ssh to explicitly warn about possible data race.

@davecheney
Copy link
Contributor

See https://blog.golang.org/race-detector .

@Canadadry
Copy link
Author

thank you

@golang golang locked and limited conversation to collaborators Apr 26, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge WaitingForInfo Issue is not actionable because of missing required information, which needs to be provided.
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@davecheney @Canadadry @mvdan @gopherbot @seankhliao