gospdylibchan

Spdy stream receiver is receiving nil object


I'm using the libchan library by docker. Their example goes like this:

// 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)
}

And this is the server:

// 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)
                        }
                    }
                }()
            }
        }()


    }
}

When I run the server and send a message with the client:

$ ./client /bin/echo "hello"

I see this output in the server logs:

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

My server receives the message with the echo command and executes it successfully. However, it also receives an empty command and then throws an 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

Why is the command an empty string?

My suspicion is that the client exits and then sends an exit signal. But if that was the case, why would the command be blank? Please help me understand what's going on.


Solution

  • It seems it is an attempted try to decode FIN ACK TCP packet coming from the client on exiting. The TCP connection is being closed, and at the server side we try to read this. We get EOF error because there is no more input to read. It seems to be a behaviour as specified in 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.

    Under the hood, libchan spdy uses msgpack encoder and decoder (source code) that, in order to read this TCP packet will call bufio ReadByte() function (source code), that returns error when no more data is there to be read (and that's the case when TCP connection was closed).

    // ReadByte reads and returns a single byte.
    // If no byte is available, returns an error.
    func (b *Reader) ReadByte() (byte, error) {
    ...
    

    You can see the TCP packet exchange running sudo tcpdump -i lo dst port 9323. The FIN ACK TCP packet that is causing this EOF error:

    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
    

    I think that this behaviour is normal and EOF error should be handled in the code. The command is blank, because client is not sending any specific command, just the stream is being closed.

    Also - from the 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.

    [EDIT] To answer more specifically what's happening behind the scenes with libchan:

    If you look in the code, you'll see that spdy.NewSpdyStreamProvider(c, true) creates new spdystream connection and then 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.

    In order to see in more detail what's happening, you can set env variable DEBUG=true

    $ export DEBUG=true
    $ ./server 
    

    The output:

    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