io.Copy copies zero bytes (nil error) of file

[Ives van der Flaas]

I'm sending a large number of files over a tcp connection by calling io.Copy() to a bufio.Writer. Although the first few hundred files are transferred correctly, at some point io.Copy() decides to call it quits and copies exactly zero bytes (and returns nil as its error value). 

The file this happens on changes every time I run the program (and the files are definitely readable, as evidenced by the fact that after the problem occurs I can just use the existing file handle to copy it to a different file). 

The function in question is this one:

func (c *ClientRunContext) sendFileContents(

file string,

fh *os.File,

stats os.FileInfo) (err error) {

// c.connWriter is a bufio.Writer with attached tcp connection

if _, err = c.connWriter.WriteString("c" + file + "\n"); err != nil {

return err

}

size := stats.Size()

log.Debug("Length of file = %v", size)

if _, err := c.connWriter.WriteString(strconv.FormatInt(size, 10) + "\n"); err != nil {

return err

}

log.Debug("Length sent")

sz, err := io.Copy(c.connWriter, fh)

if err != nil {

log.Error("Problem sending %v", err)

return err

}

if sz != size {

// Something went wrong, all that follows is trying to pinpoint the error, not original code

log.Debug("Sent size = %v", sz)

log.Debug("trying again")

a, b := io.Copy(c.connWriter, fh)

log.Debug("", a, b) // still not working

newf, err := os.Create("C:\\tmp\\f.txt")

log.Debug("", newf, err) // ok

a, b = io.Copy(newf, fh)

log.Debug("", a, b) // has copied all bytes

panic("end")

}

}

The "err != nil" block is never entered, but the sz != size block is (after the first few hundred files are processed succesfully). If I try to copy the file once more to the bufio.Writer after the error occurs, the problem remains and io.Copy still does nothing. 

If I use the existing file handle to then copy to a new file, the file is copied succesfully, indicating that there's nothing wrong with the file handle. 

After the problem has occurred I can also c.connWriter.WriteString() succesfully, so the socket or bufio.Writer isn't dead either. 

I'm running go 1.1.1 on Windows. Anyone got any ideas? 

--
Ives van der Flaas
☎ 0499/31.54.37

[Dave Cheney]

Readers have state, if fh at the start of the file, or somewhere in the middle ? 

--
You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Ives van der Flaas]

fh is at the beginning of the file. In fact, it has only been Open()'ed and subsequently Stat()'ed to provide the os.FileInfo structure in one of the parameters. It is then passed to the function I showed above. 

(My apologies if you receive this message twice, I tried responding through the google-groups webinterface about 10 hours ago but my message still hasn't appeared)

[David DENG]

Posting some code fragment for c.connWriter may help.

David

[al...@lx.lc]

Have you tried copying into a buffer, then writing the buffer to the conn?  In this way, perhaps we can begin to see whether the read or the write is failing.  I don't see how the read could fail in this manner, unless the length of the buffer passed to it(not controlled by your code) is 0, which also doesn't seem possible.  Interesting problem nonetheless.

Regards,

Alex

[Ives van der Flaas]

I just tried that, and you are right, it is the copy *to* the bufio.Writer that fails. Code follows:

func (c *ClientRunContext) sendFileContents(

file string,

fh *os.File,

stats os.FileInfo) (err error) {

if _, err = c.connWriter.WriteString("c" + file + "\n"); err != nil {

return err

}

size := stats.Size()

log.Debug("Length of file = %v", size)

if _, err := c.connWriter.WriteString(strconv.FormatInt(size, 10) + "\n"); err != nil {

return err

}

log.Debug("Length sent")

buf := new(bytes.Buffer)

sz, err := io.Copy(buf, fh)

if err != nil {

log.Error("Problem copying to buf", err)

return err

}

if sz != size {

log.Debug("Copy to buf does not match:")

log.Debug("Sent size = %v", sz)

panic("end")

} else {

log.Debug("Copy to buf succesful")

}

sz, err = io.Copy(c.connWriter, buf)

if err != nil {

log.Error("Problem copying from buf to connection %v", err)

return err

}

if sz != size {

log.Debug("Copy from buf does not match:")

log.Debug("Sent size = %v", sz)

log.Debug("trying again")

sz, err := c.connWriter.WriteString("hello")

log.Debug("Sending a random string: %v bytes and error %v", sz, err)

panic("end")

}

//if sentSize, err := io.CopyN(c.connWriter, fh, size); err != nil {

// log.Error("Only %v bytes sent io %v, %v", sentSize, size, err)

// return err

//}

log.Debug("File contents sent (but not flushed)")

return nil

}

and results in output:

2013/07/23 14:55:25 client.go:218: Length of file = 2796

2013/07/23 14:55:25 client.go:224: Length sent

2013/07/23 14:55:25 client.go:241: Copy to buf succesful

2013/07/23 14:55:25 client.go:252: Copy from buf does not match:

2013/07/23 14:55:25 client.go:253: Sent size = 0

2013/07/23 14:55:25 client.go:254: trying again

2013/07/23 14:55:25 client.go:257: Sending a random string: 5 bytes and error <nil>

panic: end

So for some reason the connWriter seems to "break", but not in such a way that it doesn't work anymore?

The connWriter is made with

log.Debug("Processing source %v", src)

conn, err := net.Dial("tcp", "127.0.0.1:"+port)

if err != nil {

log.Error("Error connecting %v", err.Error())

return

}

defer conn.Close()

log.Debug("Connected to server")

connWriter := bufio.NewWriter(conn)

in a parent function. 

--

You received this message because you are subscribed to the Google Groups "golang-nuts" group.
To unsubscribe from this group and stop receiving emails from it, send an email to golang-nuts...@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.
 
 

[Jesse McNelis]

On Tue, Jul 23, 2013 at 10:59 PM, Ives van der Flaas <ives...@gmail.com> wrote:

I just tried that, and you are right, it is the copy *to* the bufio.Writer that fails. Code follows:

  

Could you provide a full example including the code opening the file and passing it to the 'sendFileContents' method?

I still suspect you're moving the os.File cursor to the end of the file somehow before the io.Copy.

--
=====================
http://jessta.id.au

[Ives van der Flaas]

sendFileContents is called by 

func (c *ClientRunContext) evaluateAndSend(

filename string,

file *os.File,

info os.FileInfo,

est EvaluateAndSendType) error {

fmt.Println("Sending", filename)

if est == DecideToSendContents && c.run.Type == store.Fullfiles {

filemodTime := info.ModTime()

relRunTime := c.run.RelativeTo

fileChanged := filemodTime.After(relRunTime)

log.Debug("File modified at  %v", filemodTime)

log.Debug("Relative run time %v", relRunTime)

log.Debug("File changed = %v", fileChanged)

if fileChanged {

return c.sendFileContents(filename, file, info)

} else {

return c.sendFileNothing(filename, file, info)

}

} else {

return c.sendFileContents(filename, file, info)

}

}

which in turn is called by 

func sendFileSlice(

includes []string,

exclude func(string) bool,

shouldBeBackedUp func(string, *os.File, os.FileInfo) error) error {

for _, include := range includes {

log.Debug("Processing include %s", include)

f, err := os.Open(include)

if err != nil {

log.Error("Could not open include %s because %s",

include, err.Error())

continue

}

defer f.Close()

fi, err := f.Stat()

if err != nil {

log.Error("Could not stat %s", include)

continue

}

switch mode := fi.Mode(); {

case mode.IsDir():

contents, err := f.Readdirnames(0)

if err != nil {

log.Error("Could not read contents of directory %s because %s",

include, err.Error())

continue

}

var toVisit []string

for _, file := range contents {

absfile := filepath.Join(include, file)

if !exclude(absfile) {

toVisit = append(toVisit, absfile)

} else {

log.Debug("%s was excluded", absfile)

}

}

if err = sendFileSlice(toVisit[:], exclude, shouldBeBackedUp); err != nil {

return err

}

case mode.IsRegular():

if !exclude(include) {

err := shouldBeBackedUp(include, f, fi)

if err != nil {

log.Warning("Error while sending: %v", err.Error())

return err

}

// Close the file here already, if we wait until we leave the

// ftion, due to the BFS it'll be too late

f.Close()

} else {

log.Debug("%s was excluded", include)

}

}

}

return nil

}

The call to sendContents happens on the line

err := shouldBeBackedUp(include, f, fi)

which is a lambda function that's passed as an argument:

 

esw := func(filename string, file *os.File, info os.FileInfo) error {

return c.evaluateAndSend(filename, file, info, est)

}

I think that's the complete callchain from the moment the file is opened to entering the function. 

[al...@lx.lc]

I agree, I think it is the write also.  I don't understand how we can blame the read when the read operation itself works as evident by the len(buf) call.  Now, to test whether it's nested in copy behavior, can you try writing the buf to the connection and flushing rather than copying?  If this works, we'll know that something about 'copy' behavior is failing.  If not, we'll know the connwriter is misbehaving.

Thanks,
Alex

[Ives van der Flaas]

If I replace the io.Copy to the connWriter with 

szi, err := c.connWriter.Write(buf.Bytes())

giving 

func (c *ClientRunContext) sendFileContents(

file string,

fh *os.File,

stats os.FileInfo) (err error) {

if _, err = c.connWriter.WriteString("c" + file + "\n"); err != nil {

return err

}

size := stats.Size()

log.Debug("Length of file = %v", size)

if _, err := c.connWriter.WriteString(strconv.FormatInt(size, 10) + "\n"); err != nil {

return err

}

log.Debug("Length sent")

buf := new(bytes.Buffer)

sz, err := io.Copy(buf, fh)

if err != nil {

log.Error("Problem copying to buf", err)

return err

}

if sz != size {

log.Debug("Copy to buf does not match:")

log.Debug("Sent size = %v", sz)

panic("end")

} else {

log.Debug("Copy to buf succesful")

}

szi, err := c.connWriter.Write(buf.Bytes())

if err != nil {

log.Error("Problem copying from buf to connection %v", err)

return err

}

if int64(szi) != size {

log.Debug("Copy from buf does not match:")

log.Debug("Sent size = %v", sz)

log.Debug("trying again")

sz, err := c.connWriter.WriteString("hello")

log.Debug("Sending a random string: %v bytes and error %v", sz, err)

panic("end")

}

//if sentSize, err := io.CopyN(c.connWriter, fh, size); err != nil {

// log.Error("Only %v bytes sent io %v, %v", sentSize, size, err)

// return err

//}

log.Debug("File contents sent (but not flushed)")

return nil

}

Everything works fine and the program completes succesfully. 

[al...@lx.lc]

Stumped me... 
Perhaps at this point, try copying over the Copy function from http://golang.org/src/pkg/io/io.go (starting line 336) and add in debug logging between each step?  I'm genuinely curious now how or where it is failing.

Regards,
Alex

[Ives van der Flaas]

(For a second there I was really scared I wouldn't be able to reproduce it anymore, luckily that wasn't the case...) 

I tried debugging the Copy function, but as expected it simply delegates to 

if rt, ok := dst.(ReaderFrom); ok {
	return rt.ReadFrom(src)
}

which makes sense because the destination (connWriter) is a bufio Object which supports the ReaderFrom interface. So the Copy function itself actually does almost nothing. 

Any ideas on how to debug bufio.ReadFrom? 

[al...@lx.lc]

Nice catch, and sure.  Copy the ReadFrom source over, add in your debugs, and call it directly on your conn object rather than copy.  

Question - you aren't running these concurrently on the same conn object are you?  From what I see of the go source, there's nothing to stop races in this method.  

Please keep us updated.

Thanks,

Alex

[Ives van der Flaas]

Okay, I did a slight variant on that (copied the entire bufio.go, the ReadFrom file uses non-exported datamembers).

And while I'm not sure what a solution would be, I have found an explanation for the behaviour. 

The code for bufio can be found at 

https://gist.github.com/Ivesvdf/c8af83211021585027b7

And the output just before it fails (newlines mine):

2013/07/24 14:12:32 writer.go:573: Entered WriteString

2013/07/24 14:12:32 writer.go:590: Copied 106 bytes

2013/07/24 14:12:32 writer.go:592: b.n is now 319

2013/07/24 14:12:32 writer.go:594: Returning 106

2013/07/24 14:12:32 client.go:218: Length of file = 3659

2013/07/24 14:12:32 writer.go:573: Entered WriteString

2013/07/24 14:12:32 writer.go:590: Copied 5 bytes

2013/07/24 14:12:32 writer.go:592: b.n is now 324

2013/07/24 14:12:32 writer.go:594: Returning 5

2013/07/24 14:12:32 client.go:224: Length sent

2013/07/24 14:12:32 client.go:241: Copy to buf succesful

2013/07/24 14:12:32 writer.go:600: Entering readFrom

2013/07/24 14:12:32 writer.go:610: Starting to read in buf at 324, len of buf = 4096

2013/07/24 14:12:32 writer.go:612: Read 3659 bytes into buf, err = <nil>

2013/07/24 14:12:32 writer.go:618: b.n is now 3983

2013/07/24 14:12:32 writer.go:621: 113 bytes unused in buffer

2013/07/24 14:12:32 writer.go:610: Starting to read in buf at 3983, len of buf = 4096

2013/07/24 14:12:32 writer.go:612: Read 0 bytes into buf, err = EOF

2013/07/24 14:12:32 writer.go:614: breaking

2013/07/24 14:12:32 writer.go:637: Erasing EOF error

2013/07/24 14:12:32 writer.go:640: Returning 3659, <nil>

2013/07/24 14:12:32 client.go:246: %!(EXTRA int64=3659, <nil>)

2013/07/24 14:12:32 client.go:265: File contents sent (but not flushed)

2013/07/24 14:12:32 source.go:30: Processing include E:\cygwin\home\ives\pieces\cute-chess.googlecode.com\svn\trunk\Chess\PieceSets\Chesscube\White Knight.xaml

Sending E:\cygwin\home\ives\pieces\cute-chess.googlecode.com\svn\trunk\Chess\PieceSets\Chesscube\White Knight.xaml

2013/07/24 14:12:32 writer.go:573: Entered WriteString

2013/07/24 14:12:32 writer.go:590: Copied 108 bytes

2013/07/24 14:12:32 writer.go:592: b.n is now 4091

2013/07/24 14:12:32 writer.go:594: Returning 108

2013/07/24 14:12:32 client.go:218: Length of file = 5071

2013/07/24 14:12:32 writer.go:573: Entered WriteString

2013/07/24 14:12:32 writer.go:590: Copied 5 bytes

2013/07/24 14:12:32 writer.go:592: b.n is now 4096

2013/07/24 14:12:32 writer.go:594: Returning 5

2013/07/24 14:12:32 client.go:224: Length sent

2013/07/24 14:12:32 client.go:241: Copy to buf succesful

2013/07/24 14:12:32 writer.go:600: Entering readFrom

2013/07/24 14:12:32 writer.go:610: Starting to read in buf at 4096, len of buf = 4096

2013/07/24 14:12:32 writer.go:612: Read 0 bytes into buf, err = <nil>

2013/07/24 14:12:32 writer.go:614: breaking

2013/07/24 14:12:32 writer.go:640: Returning 0, <nil>

2013/07/24 14:12:32 client.go:246: %!(EXTRA int64=0, <nil>)

2013/07/24 14:12:32 client.go:254: Copy from buf does not match:

2013/07/24 14:12:32 client.go:255: Sent size = 0

So if I'm correct, the sequence of events is like this: 

1. A series of calls has almost filled up the internal buffer of the bufio.Writer. Say that there are 5 bytes free in the buffer
2. A call to WriteString is made on the bufio.Writer with a string that's 5 bytes long. 
   
   
3. Because the string fits in the buffer (filling it completely), the "for len(s) > b.Available() && b.err == nil {" is not entered. 
4. If that len(s) > avail is not entered, WriteString does not flush (this is key). It only flushes if the string does not fit in the buffer.
5. ReadFrom is now called with the internal buffer completely filled. 
6. This will cause the statement "m, err = r.Read(b.buf[b.n:])" in ReadFrom to read zero bytes (returned through m)
7. Therefore the if statement "if m == 0 {" is entered, breaking from the loop that copies data, without actually copying any data.

So, to summarize: WriteString fills the internal buffer completely while ReadFrom assumes it can always read at least one byte. ReadFrom makes sure never to fill the buffer completely and apparently assumes all other functions do the same. 

So, to fix this I guess either WriteString has to check if it has completely filled the buffer (possible similar bugs in the other Write* functions?) and Flush if so, or ReadFrom has to stop assuming at least one byte in the buffer is available when the function is entered. 

Few, finding this one was a bit of work. 

PS: No, I'm not using the bufio concurrently, that obviously wouldn't work (and the code is limited by IO anyway so I probably wouldn't get much of a speed advantage if I were to add synchronization code). 

[al...@lx.lc]

Excellent investigation!  I knew where the issue was occurring, but not how as it didn't make sense.  The only way was for something else to be writing, which is why I asked about concurrent writes.  I completely missed the fact you were writing strings each time.  Your analysis is 100% correct.  I'll look into submitting a bug and/or patch. 

Thanks,
Alex

[Dave Cheney]

Ives, Alex, thank you for your persistence in getting to the bottom of
this issue.