FAQ
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

--
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+unsubscribe@googlegroups.com.
For more options, visit https://groups.google.com/groups/opt_out.

Search Discussions

  • Dave Cheney at Jul 21, 2013 at 9:02 pm
    Readers have state, if fh at the start of the file, or somewhere in the middle ?


    On 21/07/2013, at 22:52, Ives van der Flaas wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Ives van der Flaas at Jul 22, 2013 at 11:55 am
    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)

    On Sun, Jul 21, 2013 at 11:01 PM, Dave Cheney wrote:

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



    On 21/07/2013, at 22:52, Ives van der Flaas wrote:

    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

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • David DENG at Jul 23, 2013 at 2:54 am
    Posting some code fragment for c.connWriter may help.

    David
    On Sunday, July 21, 2013 8:52:08 PM UTC+8, Ives van der Flaas wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Alex at Jul 23, 2013 at 3:33 am
    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
    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Ives van der Flaas at Jul 23, 2013 at 12:59 pm
    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Jesse McNelis at Jul 23, 2013 at 1:22 pm

    On Tue, Jul 23, 2013 at 10:59 PM, Ives van der Flaas 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

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Ives van der Flaas at Jul 23, 2013 at 1:33 pm
    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.

    On Tue, Jul 23, 2013 at 3:22 PM, Jesse McNelis wrote:
    On Tue, Jul 23, 2013 at 10:59 PM, Ives van der Flaas 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
    ☎ 0499/31.54.37

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Alex at Jul 23, 2013 at 2:40 pm
    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
    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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.



    On Tue, Jul 23, 2013 at 5:33 AM, <al...@lx.lc <javascript:>> wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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
    --
    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 <javascript:>.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Ives van der Flaas at Jul 23, 2013 at 3:18 pm
    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.

    On Tue, Jul 23, 2013 at 4:40 PM, wrote:

    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

    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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(**strco**nv.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
    --
    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<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Alex at Jul 23, 2013 at 7:33 pm
    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
    On Tuesday, July 23, 2013 11:17:54 AM UTC-4, Ives van der Flaas wrote:

    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.

    On Tue, Jul 23, 2013 at 4:40 PM, <al...@lx.lc <javascript:>> wrote:

    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

    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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(**strco**nv.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
    --
    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<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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 <javascript:>.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Ives van der Flaas at Jul 23, 2013 at 8:19 pm
    (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?

    On Tue, Jul 23, 2013 at 9:33 PM, wrote:

    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

    On Tuesday, July 23, 2013 11:17:54 AM UTC-4, Ives van der Flaas wrote:

    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.

    On Tue, Jul 23, 2013 at 4:40 PM, wrote:

    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

    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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(**strco**nv.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("**hell**o")
    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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(**strco****nv.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
    --
    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/**grou**ps/opt_out<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Alex at Jul 24, 2013 at 12:23 am
    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
    On Tuesday, July 23, 2013 4:19:13 PM UTC-4, Ives van der Flaas wrote:

    (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?

    On Tue, Jul 23, 2013 at 9:33 PM, <al...@lx.lc <javascript:>> wrote:

    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

    On Tuesday, July 23, 2013 11:17:54 AM UTC-4, Ives van der Flaas wrote:

    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.

    On Tue, Jul 23, 2013 at 4:40 PM, wrote:

    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

    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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(**strco**nv.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("**hell**o")
    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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(**strco****nv.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
    --
    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/**grou**ps/opt_out<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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 <javascript:>.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Ives van der Flaas at Jul 24, 2013 at 12:29 pm
    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).




    On Wed, Jul 24, 2013 at 2:23 AM, wrote:

    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

    On Tuesday, July 23, 2013 4:19:13 PM UTC-4, Ives van der Flaas wrote:

    (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?

    On Tue, Jul 23, 2013 at 9:33 PM, wrote:

    Stumped me...
    Perhaps at this point, try copying over the Copy function from
    http://golang.org/src/pkg/io/**io.go<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

    On Tuesday, July 23, 2013 11:17:54 AM UTC-4, Ives van der Flaas wrote:

    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(**strco**nv.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("**hell**o")
    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.

    On Tue, Jul 23, 2013 at 4:40 PM, wrote:

    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

    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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(**strco****nv.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("**hell****o")
    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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(**strco******nv.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
    --
    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.**co**m.

    For more options, visit https://groups.google.com/**grou****
    ps/opt_out <https://groups.google.com/groups/opt_out>.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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/**grou**ps/opt_out<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37

    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Alex at Jul 24, 2013 at 3:53 pm
    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
    On Wednesday, July 24, 2013 8:29:15 AM UTC-4, Ives van der Flaas wrote:

    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).




    On Wed, Jul 24, 2013 at 2:23 AM, <al...@lx.lc <javascript:>> wrote:

    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

    On Tuesday, July 23, 2013 4:19:13 PM UTC-4, Ives van der Flaas wrote:

    (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?

    On Tue, Jul 23, 2013 at 9:33 PM, wrote:

    Stumped me...
    Perhaps at this point, try copying over the Copy function from
    http://golang.org/src/pkg/io/**io.go<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

    On Tuesday, July 23, 2013 11:17:54 AM UTC-4, Ives van der Flaas wrote:

    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(**strco**nv.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("**hell**o")
    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.

    On Tue, Jul 23, 2013 at 4:40 PM, wrote:

    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

    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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(**strco****nv.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("**hell****o")
    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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

    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas wrote:

    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(**strco******nv.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
    --
    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.**co**m.

    For more options, visit https://groups.google.com/**grou****
    ps/opt_out <https://groups.google.com/groups/opt_out>.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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/**grou**ps/opt_out<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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<https://groups.google.com/groups/opt_out>
    .



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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 <javascript:>.
    For more options, visit https://groups.google.com/groups/opt_out.



    --
    Ives van der Flaas
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
  • Dave Cheney at Jul 25, 2013 at 3:30 am
    Ives, Alex, thank you for your persistence in getting to the bottom of
    this issue.
    On Thu, Jul 25, 2013 at 1:52 AM, wrote:
    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

    On Wednesday, July 24, 2013 8:29:15 AM UTC-4, Ives van der Flaas wrote:

    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:

    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
    A call to WriteString is made on the bufio.Writer with a string that's 5
    bytes long.

    Because the string fits in the buffer (filling it completely), the "for
    len(s) > b.Available() && b.err == nil {" is not entered.
    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.
    ReadFrom is now called with the internal buffer completely filled.
    This will cause the statement "m, err = r.Read(b.buf[b.n:])" in ReadFrom
    to read zero bytes (returned through m)
    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).




    On Wed, Jul 24, 2013 at 2:23 AM, wrote:

    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

    On Tuesday, July 23, 2013 4:19:13 PM UTC-4, Ives van der Flaas wrote:

    (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?

    On Tue, Jul 23, 2013 at 9:33 PM, wrote:

    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

    On Tuesday, July 23, 2013 11:17:54 AM UTC-4, Ives van der Flaas wrote:

    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.

    On Tue, Jul 23, 2013 at 4:40 PM, wrote:

    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

    On Tuesday, July 23, 2013 8:59:24 AM UTC-4, Ives van der Flaas wrote:

    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.



    On Tue, Jul 23, 2013 at 5:33 AM, wrote:

    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


    On Sunday, July 21, 2013 8:52:08 AM UTC-4, Ives van der Flaas
    wrote:
    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
    --
    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
    ☎ 0499/31.54.37
    --
    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
    ☎ 0499/31.54.37
    --
    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
    ☎ 0499/31.54.37
    --
    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
    ☎ 0499/31.54.37
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.
    --
    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+unsubscribe@googlegroups.com.
    For more options, visit https://groups.google.com/groups/opt_out.

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupgolang-nuts @
categoriesgo
postedJul 21, '13 at 8:12p
activeJul 25, '13 at 3:30a
posts16
users5
websitegolang.org

People

Translate

site design / logo © 2021 Grokbase