Spdy 流接收器正在接收 nil 对象
Spdy stream receiver is receiving nil object
我正在使用 docker 的 libchan 库。他们的例子是这样的：
// client.go
package main
import (
"log"
"io"
"net"
"os"
"github.com/docker/libchan"
"github.com/docker/libchan/spdy"
)
type RemoteCommand struct {
Cmd string
Args []string
Stdin io.Writer
Stdout io.Reader
Stderr io.Reader
StatusChan libchan.Sender
}
type CommandResponse struct {
Status int
}
func main() {
var client net.Conn
client, err := net.Dial("tcp", "127.0.0.1:9323")
if err != nil {
log.Fatal(err)
}
p, err := spdy.NewSpdyStreamProvider(client, false)
transport := spdy.NewTransport(p)
sender, err := transport.NewSendChannel()
if err != nil {
log.Fatal(err)
}
receiver, remoteSender := libchan.Pipe()
command := &RemoteCommand{
Cmd: os.Args[1],
Args: os.Args[2:],
Stdin: os.Stdin,
Stdout: os.Stdout,
Stderr: os.Stderr,
StatusChan: remoteSender,
}
err = sender.Send(command)
if err != nil {
log.Fatal(err)
}
response := &CommandResponse{}
err = receiver.Receive(response)
if err != nil {
log.Fatal(err)
}
os.Exit(response.Status)
}
这是服务器：
// server.go
package main
import (
"log"
"net"
"io"
"os/exec"
"syscall"
"github.com/docker/libchan"
"github.com/docker/libchan/spdy"
)
type RemoteReceivedCommand struct {
Cmd string
Args []string
Stdin io.Reader
Stdout io.WriteCloser
Stderr io.WriteCloser
StatusChan libchan.Sender
}
type CommandResponse struct {
Status int
}
func main() {
var listener net.Listener
var err error
listener, err = net.Listen("tcp", "localhost:9323")
if err != nil {
log.Fatal(err)
}
for {
c, err := listener.Accept()
if err != nil {
log.Print("listener accept error")
log.Print(err)
break
}
p, err := spdy.NewSpdyStreamProvider(c, true)
if err != nil {
log.Print("spdy stream error")
log.Print(err)
break
}
t := spdy.NewTransport(p)
go func() {
for {
receiver, err := t.WaitReceiveChannel()
if err != nil {
log.Print("receiver error")
log.Print(err)
break
}
log.Print("about to spawn receive proc")
go func() {
for {
command := &RemoteReceivedCommand{}
err := receiver.Receive(command)
log.Print("received command")
log.Print(command)
if err != nil {
log.Print("command error")
log.Print(err)
break
}
cmd := exec.Command(command.Cmd, command.Args...)
cmd.Stdout = command.Stdout
cmd.Stderr = command.Stderr
stdin, err := cmd.StdinPipe()
if err != nil {
log.Print("stdin error")
log.Print(err)
break
}
go func() {
io.Copy(stdin, command.Stdin)
stdin.Close()
}()
log.Print("about to run the command")
res := cmd.Run()
command.Stdout.Close()
command.Stderr.Close()
returnResult := &CommandResponse{}
if res != nil {
if exiterr, ok := res.(*exec.ExitError); ok {
returnResult.Status = exiterr.Sys().(syscall.WaitStatus).ExitStatus()
} else {
log.Print("res")
log.Print(res)
returnResult.Status = 10
}
}
err = command.StatusChan.Send(returnResult)
if err != nil {
log.Print(err)
}
}
}()
}
}()
}
}
当我运行服务器和客户端发送消息时：
$ ./client /bin/echo "hello"
我在服务器日志中看到这个输出：
2018/06/18 23:13:56 about to spawn receive proc
2018/06/18 23:13:56 received command
2018/06/18 23:13:56 &{/bin/echo [hello] 0xc4201201b0 0xc42023c030 0xc42023c090 0xc420186080}
2018/06/18 23:13:56 about to run the command
2018/06/18 23:13:56 received command
2018/06/18 23:13:56 &{ [] <nil> <nil> <nil> <nil>}
2018/06/18 23:13:56 command error
2018/06/18 23:13:56 EOF
我的服务器收到带有echo命令的消息并成功执行。但是，它也收到一个空命令，然后抛出一个 EOF：
2018/06/18 23:13:56 &{ [] <nil> <nil> <nil> <nil>}
2018/06/18 23:13:56 command error
2018/06/18 23:13:56 EOF
为什么命令是空字符串？
我怀疑是客户端退出然后发送了一个exit信号。但如果是这样的话，为什么命令会是空白的呢？请帮助我了解发生了什么。
似乎是在尝试解码来自客户端退出时的 FIN ACK TCP 数据包。 TCP 连接正在关闭，在服务器端我们尝试读取它。我们得到 EOF 错误，因为没有更多的输入可以读取。这似乎是 documentation:
中指定的行为
EOF is the error returned by Read when no more input is available. Functions should return EOF only to signal a graceful end of input. If the EOF occurs unexpectedly in a structured data stream, the appropriate error is either ErrUnexpectedEOF or some other error giving more detail.
在幕后，libchan spdy 使用 msgpack 编码器和解码器 (source code) that, in order to read this TCP packet will call bufio ReadByte() function (source code)，当没有更多数据可读时会出现 returns 错误（这就是 TCP 连接关闭时的情况).
// ReadByte reads and returns a single byte.
// If no byte is available, returns an error.
func (b *Reader) ReadByte() (byte, error) {
...
您可以看到 TCP 数据包交换 运行 sudo tcpdump -i lo dst port 9323。导致此 EOF 错误的 FIN ACK TCP 数据包：
18:28:23.782337 IP localhost.47574 > localhost.9323: Flags [F.], seq 272, ack 166, win 342, options [nop,nop,TS val 73397258 ecr 73397258], length 0
我认为这种行为是正常的，应该在代码中处理 EOF 错误。命令为空，因为客户端没有发送任何特定命令，只是流被关闭。
另外 - 来自 io.Reader documentation:
When Read encounters an error or end-of-file condition after successfully reading n > 0 bytes, it returns the number of bytes read. It may return the (non-nil) error from the same call or return the error (and n == 0) from a subsequent call. An instance of this general case is that a Reader returning a non-zero number of bytes at the end of the input stream may return either err == EOF or err == nil. The next Read should return 0, EOF.
Callers should always process the n > 0 bytes returned before considering the error err. Doing so correctly handles I/O errors that happen after reading some bytes and also both of the allowed EOF behaviors.
[编辑] 更具体地回答 libchan 在幕后发生的事情：
如果您查看代码，您会看到 spdy.NewSpdyStreamProvider(c, true) 创建了新的 spdystream 连接，然后 runs Serve on that connection in a separate goroutine. Serve function of spdstream tries to read received FIN ACK packet and receives EOF (as specified in go documentation cited above). Then, it exits the main Loop of the function and closes channels. Then, we get our EOF error on Receive here。
为了更详细地了解发生了什么，您可以设置环境变量 DEBUG=true
$ export DEBUG=true
$ ./server
输出：
127.0.0.1:57652
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 1
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c000) Stream added, broadcasting: 1
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 3
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c0a0) Stream added, broadcasting: 3
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 5
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c140) Stream added, broadcasting: 5
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 7
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c1e0) Stream added, broadcasting: 7
2018/06/22 12:24:12 about to spawn receive proc
2018/06/22 12:24:12 trying to receive
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 9
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c280) Stream added, broadcasting: 9
2018/06/22 12:24:12 (0xc4200a42c0) Data frame received for 1
2018/06/22 12:24:12 (0xc42016c000) (1) Data frame handling
2018/06/22 12:24:12 (0xc42016c000) (1) Data frame sent
2018/06/22 12:24:12 received command
2018/06/22 12:24:12 &{/bin/echo [hello] 0xc420156570 0xc4201565a0 0xc420156120 0xc42013c4a0}
2018/06/22 12:24:12 about to run the command
2018/06/22 12:24:12 (0xc42016c140) (5) Writing data frame
2018/06/22 12:24:12 (0xc42016c140) (5) Writing data frame
2018/06/22 12:24:12 (0xc42016c1e0) (7) Writing data frame
2018/06/22 12:24:12 (0xc42016c280) (9) Writing data frame
2018/06/22 12:24:12 trying to receive
2018/06/22 12:24:12 (0xc4200a42c0) EOF received
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c000) Stream removed, broadcasting: 1
2018/06/22 12:24:12 (0xc42016c000) (1) Writing data frame
2018/06/22 12:24:12 received command
2018/06/22 12:24:12 &{ [] <nil> <nil> <nil> <nil>}
2018/06/22 12:24:12 command error
2018/06/22 12:24:12 EOF
我正在使用 docker 的 libchan 库。他们的例子是这样的：
// client.go
package main
import (
"log"
"io"
"net"
"os"
"github.com/docker/libchan"
"github.com/docker/libchan/spdy"
)
type RemoteCommand struct {
Cmd string
Args []string
Stdin io.Writer
Stdout io.Reader
Stderr io.Reader
StatusChan libchan.Sender
}
type CommandResponse struct {
Status int
}
func main() {
var client net.Conn
client, err := net.Dial("tcp", "127.0.0.1:9323")
if err != nil {
log.Fatal(err)
}
p, err := spdy.NewSpdyStreamProvider(client, false)
transport := spdy.NewTransport(p)
sender, err := transport.NewSendChannel()
if err != nil {
log.Fatal(err)
}
receiver, remoteSender := libchan.Pipe()
command := &RemoteCommand{
Cmd: os.Args[1],
Args: os.Args[2:],
Stdin: os.Stdin,
Stdout: os.Stdout,
Stderr: os.Stderr,
StatusChan: remoteSender,
}
err = sender.Send(command)
if err != nil {
log.Fatal(err)
}
response := &CommandResponse{}
err = receiver.Receive(response)
if err != nil {
log.Fatal(err)
}
os.Exit(response.Status)
}
这是服务器：
// server.go
package main
import (
"log"
"net"
"io"
"os/exec"
"syscall"
"github.com/docker/libchan"
"github.com/docker/libchan/spdy"
)
type RemoteReceivedCommand struct {
Cmd string
Args []string
Stdin io.Reader
Stdout io.WriteCloser
Stderr io.WriteCloser
StatusChan libchan.Sender
}
type CommandResponse struct {
Status int
}
func main() {
var listener net.Listener
var err error
listener, err = net.Listen("tcp", "localhost:9323")
if err != nil {
log.Fatal(err)
}
for {
c, err := listener.Accept()
if err != nil {
log.Print("listener accept error")
log.Print(err)
break
}
p, err := spdy.NewSpdyStreamProvider(c, true)
if err != nil {
log.Print("spdy stream error")
log.Print(err)
break
}
t := spdy.NewTransport(p)
go func() {
for {
receiver, err := t.WaitReceiveChannel()
if err != nil {
log.Print("receiver error")
log.Print(err)
break
}
log.Print("about to spawn receive proc")
go func() {
for {
command := &RemoteReceivedCommand{}
err := receiver.Receive(command)
log.Print("received command")
log.Print(command)
if err != nil {
log.Print("command error")
log.Print(err)
break
}
cmd := exec.Command(command.Cmd, command.Args...)
cmd.Stdout = command.Stdout
cmd.Stderr = command.Stderr
stdin, err := cmd.StdinPipe()
if err != nil {
log.Print("stdin error")
log.Print(err)
break
}
go func() {
io.Copy(stdin, command.Stdin)
stdin.Close()
}()
log.Print("about to run the command")
res := cmd.Run()
command.Stdout.Close()
command.Stderr.Close()
returnResult := &CommandResponse{}
if res != nil {
if exiterr, ok := res.(*exec.ExitError); ok {
returnResult.Status = exiterr.Sys().(syscall.WaitStatus).ExitStatus()
} else {
log.Print("res")
log.Print(res)
returnResult.Status = 10
}
}
err = command.StatusChan.Send(returnResult)
if err != nil {
log.Print(err)
}
}
}()
}
}()
}
}
当我运行服务器和客户端发送消息时：
$ ./client /bin/echo "hello"
我在服务器日志中看到这个输出：
2018/06/18 23:13:56 about to spawn receive proc
2018/06/18 23:13:56 received command
2018/06/18 23:13:56 &{/bin/echo [hello] 0xc4201201b0 0xc42023c030 0xc42023c090 0xc420186080}
2018/06/18 23:13:56 about to run the command
2018/06/18 23:13:56 received command
2018/06/18 23:13:56 &{ [] <nil> <nil> <nil> <nil>}
2018/06/18 23:13:56 command error
2018/06/18 23:13:56 EOF
我的服务器收到带有echo命令的消息并成功执行。但是，它也收到一个空命令，然后抛出一个 EOF：
2018/06/18 23:13:56 &{ [] <nil> <nil> <nil> <nil>}
2018/06/18 23:13:56 command error
2018/06/18 23:13:56 EOF
为什么命令是空字符串？
我怀疑是客户端退出然后发送了一个exit信号。但如果是这样的话，为什么命令会是空白的呢？请帮助我了解发生了什么。
似乎是在尝试解码来自客户端退出时的 FIN ACK TCP 数据包。 TCP 连接正在关闭，在服务器端我们尝试读取它。我们得到 EOF 错误，因为没有更多的输入可以读取。这似乎是 documentation:
中指定的行为EOF is the error returned by Read when no more input is available. Functions should return EOF only to signal a graceful end of input. If the EOF occurs unexpectedly in a structured data stream, the appropriate error is either ErrUnexpectedEOF or some other error giving more detail.
在幕后，libchan spdy 使用 msgpack 编码器和解码器 (source code) that, in order to read this TCP packet will call bufio ReadByte() function (source code)，当没有更多数据可读时会出现 returns 错误（这就是 TCP 连接关闭时的情况).
// ReadByte reads and returns a single byte.
// If no byte is available, returns an error.
func (b *Reader) ReadByte() (byte, error) {
...
您可以看到 TCP 数据包交换 运行 sudo tcpdump -i lo dst port 9323。导致此 EOF 错误的 FIN ACK TCP 数据包：
18:28:23.782337 IP localhost.47574 > localhost.9323: Flags [F.], seq 272, ack 166, win 342, options [nop,nop,TS val 73397258 ecr 73397258], length 0
我认为这种行为是正常的，应该在代码中处理 EOF 错误。命令为空，因为客户端没有发送任何特定命令，只是流被关闭。
另外 - 来自 io.Reader documentation:
When Read encounters an error or end-of-file condition after successfully reading n > 0 bytes, it returns the number of bytes read. It may return the (non-nil) error from the same call or return the error (and n == 0) from a subsequent call. An instance of this general case is that a Reader returning a non-zero number of bytes at the end of the input stream may return either err == EOF or err == nil. The next Read should return 0, EOF.
Callers should always process the n > 0 bytes returned before considering the error err. Doing so correctly handles I/O errors that happen after reading some bytes and also both of the allowed EOF behaviors.
[编辑] 更具体地回答 libchan 在幕后发生的事情：
如果您查看代码，您会看到 spdy.NewSpdyStreamProvider(c, true) 创建了新的 spdystream 连接，然后 runs Serve on that connection in a separate goroutine. Serve function of spdstream tries to read received FIN ACK packet and receives EOF (as specified in go documentation cited above). Then, it exits the main Loop of the function and closes channels. Then, we get our EOF error on Receive here。
为了更详细地了解发生了什么，您可以设置环境变量 DEBUG=true
$ export DEBUG=true
$ ./server
输出：
127.0.0.1:57652
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 1
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c000) Stream added, broadcasting: 1
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 3
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c0a0) Stream added, broadcasting: 3
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 5
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c140) Stream added, broadcasting: 5
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 7
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c1e0) Stream added, broadcasting: 7
2018/06/22 12:24:12 about to spawn receive proc
2018/06/22 12:24:12 trying to receive
2018/06/22 12:24:12 (0xc4200a42c0) Add stream frame: 9
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c280) Stream added, broadcasting: 9
2018/06/22 12:24:12 (0xc4200a42c0) Data frame received for 1
2018/06/22 12:24:12 (0xc42016c000) (1) Data frame handling
2018/06/22 12:24:12 (0xc42016c000) (1) Data frame sent
2018/06/22 12:24:12 received command
2018/06/22 12:24:12 &{/bin/echo [hello] 0xc420156570 0xc4201565a0 0xc420156120 0xc42013c4a0}
2018/06/22 12:24:12 about to run the command
2018/06/22 12:24:12 (0xc42016c140) (5) Writing data frame
2018/06/22 12:24:12 (0xc42016c140) (5) Writing data frame
2018/06/22 12:24:12 (0xc42016c1e0) (7) Writing data frame
2018/06/22 12:24:12 (0xc42016c280) (9) Writing data frame
2018/06/22 12:24:12 trying to receive
2018/06/22 12:24:12 (0xc4200a42c0) EOF received
2018/06/22 12:24:12 (0xc4200a42c0) (0xc42016c000) Stream removed, broadcasting: 1
2018/06/22 12:24:12 (0xc42016c000) (1) Writing data frame
2018/06/22 12:24:12 received command
2018/06/22 12:24:12 &{ [] <nil> <nil> <nil> <nil>}
2018/06/22 12:24:12 command error
2018/06/22 12:24:12 EOF