encoding/base64: SetReadDeadline fails to set deadline on socket when piped thru base64 decoder

[gopherbot]

by branimirkaradzic:

What steps will reproduce the problem?
Connect client to server, expect base64 encoded stream from client, but do not send any
data from client to server.

SetReadDeadline fails to set deadline on socket when piped thru base64 decoder. When
using socket without piping thru decoder it works properly. Incoming client connection
is not sending any data to server. Read should time out every 8 seconds since it's not
getting data, but it seems that deadline except first two times is not respected at all.

Code looks like (sorry for just snippets of code, didn't have time to make simple repro):

            nowNs := time.Now().UnixNano()
            nextNs := nowNs + 4e9
            var recvs uint64

            // rw is net.Conn
            dec = base64.NewDecoder(base64.StdEncoding, rw) // BUG

            for valid {

                rw.SetReadDeadline(time.Now().Add(time.Duration(8e9)))
                size, err = dec.Read(conn.buf[conn.write : MaxConnectionBufferSize-1]) // BUG

                // size, err = rw.Read(conn.buf[conn.write : MaxConnectionBufferSize-1]) // WORKS

                // ...

                recvs++
                nowNs = time.Now().UnixNano()
                if nowNs > nextNs {
                    nextNs += 4e9
                    common.LogPrint("Recvs in 4secs: ", recvs)
                }

                // ...
            }



What is the expected output?

TCP/Socket Expected

2012/04/28 20:41:07 Recvs in 4secs: 1
2012/04/28 20:41:15 Recvs in 4secs: 2
2012/04/28 20:41:23 Recvs in 4secs: 3
2012/04/28 20:41:31 Recvs in 4secs: 4
2012/04/28 20:41:39 Recvs in 4secs: 5
2012/04/28 20:41:47 Recvs in 4secs: 6
2012/04/28 20:41:55 Recvs in 4secs: 7
2012/04/28 20:42:03 Recvs in 4secs: 8
2012/04/28 20:42:11 Recvs in 4secs: 9
2012/04/28 20:42:19 Recvs in 4secs: 10
2012/04/28 20:42:27 Recvs in 4secs: 11
2012/04/28 20:42:35 Recvs in 4secs: 12
2012/04/28 20:42:43 Recvs in 4secs: 13
2012/04/28 20:42:51 Recvs in 4secs: 14

What do you see instead?

WebSocket (base64 decoded) BUG

2012/04/28 20:39:02 Recvs in 4secs: 1
2012/04/28 20:39:02 Recvs in 4secs: 2
2012/04/28 20:39:06 Recvs in 4secs: 11736743
2012/04/28 20:39:10 Recvs in 4secs: 23067466
2012/04/28 20:39:14 Recvs in 4secs: 34411471
2012/04/28 20:39:18 Recvs in 4secs: 45633855
2012/04/28 20:39:22 Recvs in 4secs: 57184139
2012/04/28 20:39:26 Recvs in 4secs: 68857818
2012/04/28 20:39:30 Recvs in 4secs: 80664859
2012/04/28 20:39:34 Recvs in 4secs: 92219575
2012/04/28 20:39:38 Recvs in 4secs: 103553508
2012/04/28 20:39:42 Recvs in 4secs: 115327688
2012/04/28 20:39:46 Recvs in 4secs: 127280610
2012/04/28 20:39:50 Recvs in 4secs: 138754879

Which compiler are you using (5g, 6g, 8g, gccgo)?
6g

Which operating system are you using?
Linux

Which version are you using?  (run 'go version')
go version go1.0.1

Please provide any additional information below.

[bradfitz]

Comment 1:

Owner changed to @bradfitz.

Status changed to Started.

[bradfitz]

Comment 2:

Proposed fix: http://golang.org/cl/6137054

[bradfitz]

Comment 3:

Labels changed: removed priority-triage.

[bradfitz]

Comment 4:

This issue was closed by revision ed90fbc.

Status changed to Fixed.

[bradfitz]

Comment 5:

Labels changed: added go1.0.2.

[gopherbot]

Comment 6 by branimirkaradzic:

I integrated change and still doesn't appear fixed. I stripped down code and got better
repro case. See line with conn.decode = true (in func NewConn), change it to false to
get expected behavior. Let me know if I need to better describe the problem.
package main
import (
    "code.google.com/p/go.net/websocket"
    "encoding/base64"
    "fmt"
    "io"
    "net"
    "net/http"
    "syscall"
    "time"
)
const (
    DefaultTimeout time.Duration = 8e9
)
type Conn struct {
    rw     net.Conn
    dec    io.Reader
    decode bool
}
func NewConn(rw net.Conn) (conn *Conn) {
    conn = new(Conn)
    conn.rw = rw
    conn.dec = base64.NewDecoder(base64.StdEncoding, rw)
    conn.decode = true // change this to false to see expected results.
    return
}
func (conn *Conn) Read(b []byte) (n int, err error) {
    conn.rw.SetReadDeadline(time.Now().Add(DefaultTimeout))
    if conn.decode {
        n, err = conn.dec.Read(b)
    } else {
        n, err = conn.rw.Read(b)
    }
    if err != syscall.EAGAIN {
        err2, ok := err.(*net.OpError)
        if !ok || !err2.Temporary() {
            return
        }
        return n, nil
    }
    return
}
func webSocketHandler(rw *websocket.Conn) {
    defer rw.Close()
    fmt.Print("server: incoming\n")
    conn := NewConn(rw, )
    var (
        err error
        n   int
    )
    nowNs := time.Now().UnixNano()
    nextNs := nowNs + 4e9
    var calls uint64
    for err == nil && n == 0 {
        b := make([]byte, 1024)
        n, err = conn.Read(b)
        calls++
        nowNs = time.Now().UnixNano()
        if nowNs > nextNs {
            nextNs += 4e9
            fmt.Print("Calls in 4 secs: ", calls, "\n")
        }
    }
    fmt.Print("server: client left\n")
}
func client() {
    for {
        <-time.After(4e9)
        fmt.Print("client: connect attempt\n")
        ws, err := websocket.Dial("ws://localhost:1234/ws", "", "http://localhost/")
        if err == nil {
            conn := NewConn(ws)
            var (
                err error
                n   int
            )
            for err == nil && n == 0 {
                b := make([]byte, 1024)
                n, err = conn.Read(b)
            }
            ws.Close()
            fmt.Print("client: left\n")
        } else {
            fmt.Print("client: ", err, "\n")
        }
    }
}
func main() {
    go client()
    http.Handle("/ws", websocket.Handler(webSocketHandler))
    err := http.ListenAndServe(":1234", nil)
    if err != nil {
        panic("ListenAndServe: " + err.Error())
    }
}

[bradfitz]

Comment 7:

Your program appears to spin as a result of your syscall.EAGAIN check.  If I remove
that, it appears to work.
It's not clear what your expected results are supposed to be, though.

[gopherbot]

Comment 8 by branimirkaradzic:

This is the problem code:
    conn.rw.SetReadDeadline(time.Now().Add(DefaultTimeout))
    if conn.decode {
        n, err = conn.dec.Read(b)
    } else {
        n, err = conn.rw.Read(b)
    }
Expected result for case when no data is sent is 'idle timeout' where Read blocks
execution until it times out after period set by SetReadDeadline expires. That's how it
behaves when conn.rw.Read is called (conn.decode = false). When going thru decoder,
deadline is ignored and I get Read to behave as if SetReadDeadline is not set at all.
'calls' counter should increment every 8 seconds, and output should be sequential
numbers.

[gopherbot]

Comment 9 by branimirkaradzic:

Do you need more info on this issue?

[bradfitz]

Comment 10:

Could you cut it down to a single unit test:
func TestWhatever(t *testing.T) {
   ...
}
... and one that doesn't sleep for 8+ seconds?
I looked at your code for awhile and didn't understand what it was trying to do.  I
could observe differences, but I wasn't convinced that your code was even correct to
begin with.  I wrapped the readers with printing wrappers and it just looked like your
code was spinning.  Probably due to those EAGAIN checks.
This bug did fix a real issue, but I don't see another issue.

[gopherbot]

Comment 11 by branimirkaradzic:

Even if it is wrong code around EAGAIN, when data is not sent thru, this block of code:
    conn.rw.SetReadDeadline(time.Now().Add(8e9))
    n, err = conn.dec.Read(b)
Should behave as:
    <-time.After(8e9)
Anyhow, writing tests now...

[gopherbot]

Comment 12 by branimirkaradzic:

Here is the test:
package main
import (
    "encoding/base64"
    "net"
    "syscall"
    "testing"
    "time"
)
func client() {
    rw, err := net.Dial("tcp", ":1234")
    for err == nil {
        b := make([]byte, 1024)
        rw.SetReadDeadline(time.Now().Add(8e9))
        _, err = rw.Read(b)
        if err != syscall.EAGAIN {
            err = nil // do not disconnect on timeout!
        }
    }
    rw.Close()
}
func TestExpected(t *testing.T) {
    l, err := net.Listen("tcp", ":1234")
    if err != nil {
        t.Fatalf("listen error: %v", err)
    }
    defer l.Close()
    go client()
    rw, err := l.Accept()
    defer rw.Close()
    nowNs := time.Now().UnixNano()
    exitNs := nowNs + 15e9
    var calls uint64
    for err == nil && nowNs < exitNs {
        b := make([]byte, 1024)
        rw.SetReadDeadline(time.Now().Add(1e9))
        _, err = rw.Read(b)
        calls++
        if err != syscall.EAGAIN {
            err = nil // do not disconnect on timeout!
        }
        nowNs = time.Now().UnixNano()
    }
    t.Logf("Calls %d", calls)
    if calls > 30 {
        t.Fatalf("Read called %d times. Expected ~15.", calls)
    }
}
func TestBug(t *testing.T) {
    l, err := net.Listen("tcp", ":1234")
    if err != nil {
        t.Fatalf("listen error: %v", err)
    }
    defer l.Close()
    go client()
    rw, err := l.Accept()
    defer rw.Close()
    dec := base64.NewDecoder(base64.StdEncoding, rw)
    nowNs := time.Now().UnixNano()
    exitNs := nowNs + 15e9
    var calls uint64
    for err == nil && nowNs < exitNs {
        b := make([]byte, 1024)
        rw.SetReadDeadline(time.Now().Add(1e9))
        _, err = dec.Read(b)
        calls++
        if err != syscall.EAGAIN {
            err = nil // do not disconnect on timeout!
        }
        nowNs = time.Now().UnixNano()
    }
    t.Logf("Calls %d", calls)
    if calls > 30 {
        t.Fatalf("Read called %d times. Expected ~15.", calls)
    }
}

[bradfitz]

Comment 13:

Your code is never hitting that syscall.EAGAIN code path.  That's a distraction and has
nothing to do with this bug.
The problem with your code is that you're assuming you can continue to use a base64
Decoder after it's encountered a ReadError (an I/O timeout from SetReadDeadline). You
can not.  Once the base64 decoder hits a read error, the decoder is permanently busted. 
Don't set a deadline if you don't want one, or if you want to mask the read error, do it
in a wrapped reader that you give to the base64 decoder.  Just don't like base64 see an
error.
Anyway, this isn't a bug in the base64 code.

[gopherbot]

Comment 14 by branimirkaradzic:

Sorry that err != syscall.EAGAIN should be:
        err2, ok := err.(*net.OpError)
        if ok && err2.Temporary() {
            err = nil
        }
Timeout is temporary error, data might come thru at later point.
Maybe this should be changed to not be base64 specific. I used it just because I
encountered it by using base64 with websockets, probably other decoders have this issue
too.
I just expected that temporary error like timeout is handled in the way that decoder
will retry Read at later point. I didn't look into base64 code, but it sounds like
you're caching error result from Read and then returning it without calling Read again.
Anyhow I'm going to change my code to not rely on piping thru decoder.

[bradfitz]

Comment 15:

We're not going to change every 1-line Read call in the Go source tree to do a retry
loop waiting for temporary errors to go away.
This is a problem for a higher layer.

[gopherbot]

Comment 16 by branimirkaradzic:

I wouldn't want you to add retry loops anywhere. But decoder should not just assume that
error is permanent, unless decoder itself can detect that. I see early out at the top of
base64 Read. If d.err is not generated by decoder and you let code pass to Read
everything would work properly.

[bradfitz]

Comment 17:

We're not going to change every 1-line Read call in the Go source tree to check if Reads
are temporary or not.

[gopherbot]

Comment 18 by branimirkaradzic:

No need to get all frustrated. I'm friendly here, and love Go and you guys for all Go
work you're doing! :) I'm just trying to point out from the point of view of language
user that it's bit confusing why it doesn't work without looking into source code.
Anyhow I made copy of base64 for our project and made change in base64.Read function to
pass io.ReadAtLeast error directly to higher level without caching it internally, and it
fixes the issue...
    nn, err = io.ReadAtLeast(d.r, d.buf[d.nbuf:nn], 4-d.nbuf)
    d.nbuf += nn
    if err != nil {
        return 0, err
    }

[bradfitz]

Comment 19:

I'm not frustrated, but I still think your design is wrong.  Forking base64 does not
seem like the answer.
But like I said: you can make your own Reader type and give that to base64 to mask
errors if that was actually the answer, but I still think it's not. You shouldn't be
setting a deadline if that's not an error.  And if you're not setting the deadline, then
something else is broken.