golang代理io.Writer在日志中使用时的行为有所不同

Question

I am trying to implement a proxy that satisfies io.Writer, so I can plug it into a logger. The idea is that it will print the output like normal but also keeps a copy of the data to be read later.

The ProxyIO struct in the following code should do this, and indeed it does it as long as I directly call its Write() method. However, when I plug it into a log.Logger instance the output is unexpected.

(This is stripped down code, the original implementation I want to use is with a map and a circular pointer instead of the [][]byte buf used in the example code. Also I removed all the locking.)

package main

import (
    "fmt"
    "io"
    "io/ioutil"
    "log"
)

type ProxyIO struct {
    out io.Writer // the io we are proxying
    buf [][]byte
}

func newProxyIO(out io.Writer) *ProxyIO {
    return &ProxyIO{
        out: out,
        buf: [][]byte{},
    }
}

func (r *ProxyIO) Write(s []byte) (int, error) {
    r.out.Write(s)
    r.buf = append(r.buf, s)
    return len(s), nil
}

func main() {
    p := newProxyIO(ioutil.Discard)
    p.Write([]byte("test1
"))
    p.Write([]byte("test2
"))
    p.Write([]byte("test3
"))
    l := log.New(p, "", 0)
    l.Print("test4")
    l.Print("test5")
    l.Print("test6")
    for i, e := range p.buf {
        fmt.Printf("%d: %s", i, e)
    }
}

(Here is the code on the playground https://play.golang.org/p/UoOq4Nd-rmI)

I would expect the following output from this code:

0: test1
1: test2
2: test3
3: test4
4: test5
5: test6

However, it will always print this:

0: test1
1: test2
2: test3
3: test6
4: test6
5: test6

The behaviour with my map implementation is the same. I also tried using a doubly linked list from container/list as storage, it's always the same. So I must be missing something substantial here.

Why am I seeing the last log output three times in the buffer instead of the last three lines of log output?

Answer 1

If you look at the source code for Logger.Print you'll see it calls logger.Output. You'll notice how it sets the value of the string to l.buf and then calls Write

If you read this answer you'll see that even though everything is pass by value

when you pass a slice to a function, a copy will be made from this header, including the pointer, which will point to the same backing array.

So when you do:

l.Print("test4")
l.Print("test5")
l.Print("test6")

Logger is effectively reusing the same slice and you're appending a reference to that same slice three times so naturally upon printing it uses the most recent value set three times.

To fix this you can copy the []byte before using it like this:

func (r *ProxyIO) Write(s []byte) (int, error) {
    c := make([]byte, len(s))
    copy(c, s)
    r.out.Write(c)
    r.buf = append(r.buf, c)
    return len(c), nil
}

Updated playground: https://play.golang.org/p/DIWC1Xa6w0R