Go detects a data race only when TraceLog is not in use
dcrosta opened this issue · 2 comments
dcrosta commented
I recently switched off the built-in TraceLog in favor of custom logging, and discovered a data race via go's race detector as a result. Here's a reproducing case:
main.go
package main
import (
"fmt"
"io"
"log"
"net"
"os"
"reflect"
"time"
"aqwari.net/net/styx"
)
var (
fileMode = os.FileMode(0644)
dirMode = os.FileMode(0755) | os.ModeDir
)
type staticFileInfo struct {
name string
size int64
mode os.FileMode
modTime time.Time
}
// os.FileInfo interface
func (f staticFileInfo) Name() string { return f.name }
func (f staticFileInfo) Size() int64 { return f.size }
func (f staticFileInfo) Mode() os.FileMode { return f.mode }
func (f staticFileInfo) ModTime() time.Time { return f.modTime }
func (f staticFileInfo) IsDir() bool { return f.mode&os.ModeType == os.ModeDir }
func (f staticFileInfo) Sys() interface{} { return nil }
// styx.OwnerInfo interface
func (f staticFileInfo) Uid() string { return "dcrosta" }
func (f staticFileInfo) Gid() string { return "dcrosta" }
func (f staticFileInfo) Muid() string { return "dcrosta" }
type dirReader struct {
offset int
}
func (d *dirReader) Readdir(n int) ([]os.FileInfo, error) {
if d.offset == 0 {
d.offset = 1
return []os.FileInfo{getFileInfo()}, nil
}
return nil, io.EOF
}
type fileReader struct {
offset int
}
func (f *fileReader) Read(out []byte) (int, error) {
contents := []byte("hello, world!\n")
if f.offset >= len(contents) {
return 0, io.EOF
}
toReturn := contents[f.offset:]
bytesRead := copy(out, toReturn)
f.offset += bytesRead
return bytesRead, nil
}
func getFileInfo() os.FileInfo {
return staticFileInfo{name: "hello.txt", size: int64(len("hello, world!\n")), mode: fileMode, modTime: time.Now()}
}
func getDirInfo() os.FileInfo {
return staticFileInfo{name: "", size: int64(8192), mode: dirMode, modTime: time.Now()}
}
func makeHandler() styx.HandlerFunc {
return func (s *styx.Session) {
for s.Next() {
req := s.Request()
var fileInfo os.FileInfo
if req.Path() == "/" {
fileInfo = getDirInfo()
} else if req.Path() == "/hello.txt" {
fileInfo = getFileInfo()
} else {
fmt.Printf("returning No Such File")
req.Rerror("No such file or directory")
continue
}
fmt.Printf("%v: path is '%s', fileInfo is %v\n", reflect.TypeOf(req), req.Path(), fileInfo)
switch msg := req.(type) {
case styx.Tstat:
msg.Rstat(fileInfo, nil)
case styx.Twalk:
msg.Rwalk(fileInfo, nil)
case styx.Topen:
if msg.Path() == "/" {
msg.Ropen(&dirReader{}, nil)
} else {
msg.Ropen(&fileReader{}, nil)
}
}
}
}
}
type logger struct { }
func (l logger) Printf(msg string, args ...interface{}) {
fmt.Printf(msg + "\n", args...)
}
func main() {
handler := makeHandler()
server := styx.Server{
Handler: styx.HandlerFunc(handler),
// TraceLog: logger{},
}
listener, err := net.Listen("unix", "/tmp/styx.sock")
if err != nil {
log.Fatal(err.Error())
}
fmt.Println("listening at /tmp/styx.sock")
server.Serve(listener)
}
I run this with go -race main.go, then in another terminal do:
$ sudo mount -t 9p /tmp/styx.sock -o trans=unix,version=9p2000.L,uname="dcrosta" /home/dcrosta/mnt
$ ls -l /home/dcrosta/mnt
This gives the following output from the styx server program:
$ go run -race go/src/test/main.go
listening at /tmp/styx.sock
styx.Tstat: path is '/', fileInfo is { 8192 2147484141 {13788149845776717098 5772412826 0x7fc520}}
styx.Tstat: path is '/', fileInfo is { 8192 2147484141 {13788149847199729987 7121683885 0x7fc520}}
styx.Topen: path is '/', fileInfo is { 8192 2147484141 {13788149847200370103 7122323982 0x7fc520}}
styx.Tstat: path is '/', fileInfo is { 8192 2147484141 {13788149847200643024 7122596895 0x7fc520}}
==================
WARNING: DATA RACE
Write at 0x00c0000b8000 by goroutine 7:
syscall.Read()
/home/dcrosta/.../go/src/internal/race/race.go:49 +0x9b
internal/poll.(*FD).Read()
/home/dcrosta/.../go/src/internal/poll/fd_unix.go:165 +0x1a5
net.(*netFD).Read()
/home/dcrosta/.../go/src/net/fd_unix.go:202 +0x65
net.(*conn).Read()
/home/dcrosta/.../go/src/net/net.go:177 +0xa1
net.(*UnixConn).Read()
<autogenerated>:1 +0x69
bufio.(*Reader).fill()
/home/dcrosta/.../go/src/bufio/bufio.go:100 +0x199
bufio.(*Reader).Peek()
/home/dcrosta/.../go/src/bufio/bufio.go:138 +0x94
aqwari.net/net/styx/styxproto.(*Decoder).fill()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:195 +0x108
aqwari.net/net/styx/styxproto.(*Decoder).growdot()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:183 +0x9e
aqwari.net/net/styx/styxproto.(*Decoder).fetchMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/parse.go:46 +0x5a
aqwari.net/net/styx/styxproto.(*Decoder).Next()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:129 +0x135
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:185 +0xaf
Previous read at 0x00c0000b8006 by goroutine 9:
encoding/binary.littleEndian.Uint16-fm()
/home/dcrosta/.../go/src/encoding/binary/binary.go:52 +0x51
aqwari.net/net/styx.(*Session).handleTread.func1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/proto.go:24 +0x3df
Goroutine 7 (running) created at:
aqwari.net/net/styx.(*Server).Serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/server.go:129 +0x4a8
main.main()
/home/dcrosta/.../go/src/test/main.go:130 +0x22b
Goroutine 9 (finished) created at:
aqwari.net/net/styx.(*Session).handleTread()
/home/dcrosta/.../go/src/aqwari.net/net/styx/session.go:299 +0x3ca
aqwari.net/net/styx.(*conn).handleFcall()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:403 +0xb70
aqwari.net/net/styx.(*conn).handleMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:212 +0x91f
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:186 +0x119
==================
==================
WARNING: DATA RACE
Write at 0x00c0000b8008 by goroutine 7:
syscall.Read()
/home/dcrosta/.../go/src/internal/race/race.go:49 +0x9b
internal/poll.(*FD).Read()
/home/dcrosta/.../go/src/internal/poll/fd_unix.go:165 +0x1a5
net.(*netFD).Read()
/home/dcrosta/.../go/src/net/fd_unix.go:202 +0x65
net.(*conn).Read()
/home/dcrosta/.../go/src/net/net.go:177 +0xa1
net.(*UnixConn).Read()
<autogenerated>:1 +0x69
bufio.(*Reader).fill()
/home/dcrosta/.../go/src/bufio/bufio.go:100 +0x199
bufio.(*Reader).Peek()
/home/dcrosta/.../go/src/bufio/bufio.go:138 +0x94
aqwari.net/net/styx/styxproto.(*Decoder).fill()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:195 +0x108
aqwari.net/net/styx/styxproto.(*Decoder).growdot()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:183 +0x9e
aqwari.net/net/styx/styxproto.(*Decoder).fetchMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/parse.go:46 +0x5a
aqwari.net/net/styx/styxproto.(*Decoder).Next()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:129 +0x135
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:185 +0xaf
Previous read at 0x00c0000b800e by goroutine 10:
encoding/binary.littleEndian.Uint64-fm()
/home/dcrosta/.../go/src/encoding/binary/binary.go:77 +0xb3
aqwari.net/net/styx.(*Session).handleTread.func1.1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/proto.go:454 +0x87
Goroutine 7 (running) created at:
aqwari.net/net/styx.(*Server).Serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/server.go:129 +0x4a8
main.main()
/home/dcrosta/.../go/src/test/main.go:130 +0x22b
Goroutine 10 (finished) created at:
aqwari.net/net/styx.(*Session).handleTread.func1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/session.go:312 +0x1fc
==================
==================
WARNING: DATA RACE
Write at 0x00c0000b8010 by goroutine 7:
syscall.Read()
/home/dcrosta/.../go/src/internal/race/race.go:49 +0x9b
internal/poll.(*FD).Read()
/home/dcrosta/.../go/src/internal/poll/fd_unix.go:165 +0x1a5
net.(*netFD).Read()
/home/dcrosta/.../go/src/net/fd_unix.go:202 +0x65
net.(*conn).Read()
/home/dcrosta/.../go/src/net/net.go:177 +0xa1
net.(*UnixConn).Read()
<autogenerated>:1 +0x69
bufio.(*Reader).fill()
/home/dcrosta/.../go/src/bufio/bufio.go:100 +0x199
bufio.(*Reader).Peek()
/home/dcrosta/.../go/src/bufio/bufio.go:138 +0x94
aqwari.net/net/styx/styxproto.(*Decoder).fill()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:195 +0x108
aqwari.net/net/styx/styxproto.(*Decoder).growdot()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:183 +0x9e
aqwari.net/net/styx/styxproto.(*Decoder).fetchMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/parse.go:46 +0x5a
aqwari.net/net/styx/styxproto.(*Decoder).Next()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:129 +0x135
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:185 +0xaf
Previous read at 0x00c0000b8010 by goroutine 10:
encoding/binary.littleEndian.Uint64-fm()
/home/dcrosta/.../go/src/encoding/binary/binary.go:78 +0xe9
aqwari.net/net/styx.(*Session).handleTread.func1.1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/proto.go:454 +0x87
Goroutine 7 (running) created at:
aqwari.net/net/styx.(*Server).Serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/server.go:129 +0x4a8
main.main()
/home/dcrosta/.../go/src/test/main.go:130 +0x22b
Goroutine 10 (finished) created at:
aqwari.net/net/styx.(*Session).handleTread.func1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/session.go:312 +0x1fc
==================
==================
WARNING: DATA RACE
Write at 0x00c0000b8011 by goroutine 7:
syscall.Read()
/home/dcrosta/.../go/src/internal/race/race.go:49 +0x9b
internal/poll.(*FD).Read()
/home/dcrosta/.../go/src/internal/poll/fd_unix.go:165 +0x1a5
net.(*netFD).Read()
/home/dcrosta/.../go/src/net/fd_unix.go:202 +0x65
net.(*conn).Read()
/home/dcrosta/.../go/src/net/net.go:177 +0xa1
net.(*UnixConn).Read()
<autogenerated>:1 +0x69
bufio.(*Reader).fill()
/home/dcrosta/.../go/src/bufio/bufio.go:100 +0x199
bufio.(*Reader).Peek()
/home/dcrosta/.../go/src/bufio/bufio.go:138 +0x94
aqwari.net/net/styx/styxproto.(*Decoder).fill()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:195 +0x108
aqwari.net/net/styx/styxproto.(*Decoder).growdot()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:183 +0x9e
aqwari.net/net/styx/styxproto.(*Decoder).fetchMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/parse.go:46 +0x5a
aqwari.net/net/styx/styxproto.(*Decoder).Next()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:129 +0x135
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:185 +0xaf
Previous read at 0x00c0000b8011 by goroutine 10:
encoding/binary.littleEndian.Uint64-fm()
/home/dcrosta/.../go/src/encoding/binary/binary.go:78 +0x104
aqwari.net/net/styx.(*Session).handleTread.func1.1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/proto.go:454 +0x87
Goroutine 7 (running) created at:
aqwari.net/net/styx.(*Server).Serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/server.go:129 +0x4a8
main.main()
/home/dcrosta/.../go/src/test/main.go:130 +0x22b
Goroutine 10 (finished) created at:
aqwari.net/net/styx.(*Session).handleTread.func1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/session.go:312 +0x1fc
==================
==================
WARNING: DATA RACE
Write at 0x00c0000b8012 by goroutine 7:
syscall.Read()
/home/dcrosta/.../go/src/internal/race/race.go:49 +0x9b
internal/poll.(*FD).Read()
/home/dcrosta/.../go/src/internal/poll/fd_unix.go:165 +0x1a5
net.(*netFD).Read()
/home/dcrosta/.../go/src/net/fd_unix.go:202 +0x65
net.(*conn).Read()
/home/dcrosta/.../go/src/net/net.go:177 +0xa1
net.(*UnixConn).Read()
<autogenerated>:1 +0x69
bufio.(*Reader).fill()
/home/dcrosta/.../go/src/bufio/bufio.go:100 +0x199
bufio.(*Reader).Peek()
/home/dcrosta/.../go/src/bufio/bufio.go:138 +0x94
aqwari.net/net/styx/styxproto.(*Decoder).fill()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:195 +0x108
aqwari.net/net/styx/styxproto.(*Decoder).growdot()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:183 +0x9e
aqwari.net/net/styx/styxproto.(*Decoder).fetchMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/parse.go:46 +0x5a
aqwari.net/net/styx/styxproto.(*Decoder).Next()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:129 +0x135
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:185 +0xaf
Previous read at 0x00c0000b8012 by goroutine 10:
encoding/binary.littleEndian.Uint64-fm()
/home/dcrosta/.../go/src/encoding/binary/binary.go:76 +0x55
aqwari.net/net/styx.(*Session).handleTread.func1.1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/proto.go:454 +0x87
Goroutine 7 (running) created at:
aqwari.net/net/styx.(*Server).Serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/server.go:129 +0x4a8
main.main()
/home/dcrosta/.../go/src/test/main.go:130 +0x22b
Goroutine 10 (finished) created at:
aqwari.net/net/styx.(*Session).handleTread.func1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/session.go:312 +0x1fc
==================
==================
WARNING: DATA RACE
Write at 0x00c0000b8013 by goroutine 7:
syscall.Read()
/home/dcrosta/.../go/src/internal/race/race.go:49 +0x9b
internal/poll.(*FD).Read()
/home/dcrosta/.../go/src/internal/poll/fd_unix.go:165 +0x1a5
net.(*netFD).Read()
/home/dcrosta/.../go/src/net/fd_unix.go:202 +0x65
net.(*conn).Read()
/home/dcrosta/.../go/src/net/net.go:177 +0xa1
net.(*UnixConn).Read()
<autogenerated>:1 +0x69
bufio.(*Reader).fill()
/home/dcrosta/.../go/src/bufio/bufio.go:100 +0x199
bufio.(*Reader).Peek()
/home/dcrosta/.../go/src/bufio/bufio.go:138 +0x94
aqwari.net/net/styx/styxproto.(*Decoder).fill()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:195 +0x108
aqwari.net/net/styx/styxproto.(*Decoder).growdot()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:183 +0x9e
aqwari.net/net/styx/styxproto.(*Decoder).fetchMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/parse.go:46 +0x5a
aqwari.net/net/styx/styxproto.(*Decoder).Next()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/decoder.go:129 +0x135
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:185 +0xaf
Previous read at 0x00c0000b8013 by goroutine 9:
encoding/binary.littleEndian.Uint32-fm()
/home/dcrosta/.../go/src/encoding/binary/binary.go:64 +0x63
aqwari.net/net/styx.(*Session).handleTread.func1()
/home/dcrosta/.../go/src/aqwari.net/net/styx/styxproto/proto.go:459 +0x9b
Goroutine 7 (running) created at:
aqwari.net/net/styx.(*Server).Serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/server.go:129 +0x4a8
main.main()
/home/dcrosta/.../go/src/test/main.go:130 +0x22b
Goroutine 9 (finished) created at:
aqwari.net/net/styx.(*Session).handleTread()
/home/dcrosta/.../go/src/aqwari.net/net/styx/session.go:299 +0x3ca
aqwari.net/net/styx.(*conn).handleFcall()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:403 +0xb70
aqwari.net/net/styx.(*conn).handleMessage()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:212 +0x91f
aqwari.net/net/styx.(*conn).serve()
/home/dcrosta/.../go/src/aqwari.net/net/styx/conn.go:186 +0x119
==================
styx.Twalk: path is '/hello.txt', fileInfo is {hello.txt 14 420 {13788149847203171246 7125125153 0x7fc520}}
styx.Tstat: path is '/hello.txt', fileInfo is {hello.txt 14 420 {13788149847203342114 7125296012 0x7fc520}}
styx.Tstat: path is '/hello.txt', fileInfo is {hello.txt 14 420 {13788149847203482304 7125436176 0x7fc520}}
If I uncomment the line that turns on TraceLog, there is no race detected. I believe this is because https://github.com/droyo/styx/blob/master/internal/tracing/trace.go#L22-L34 copies data out of the buffer when tracing is enabled, and passes that copy (via the pipe) to the main styx server, but I haven't looked very deeply at this or thought about it very extensively.
droyo commented
Thank you for the reproduction. I was able to reproduce the issue.
After reviewing the code, the issue is that handleTread does not wait for the Rread message to be filled out before returning. As a result, execution continues and the styxproto.Decoder.Next method is called. This overwrites the msg variable being accessed from the goroutine spawned in handleTread.
A simple fix would be to have handleTread pass a copy of the Tread message to the goroutine it spawns. The only other places we spawn goroutines for command processing is ifor Tattach and Tauth messages, so those should be reviewed as well.
In hindsight, I skipped too many steps and made too many assumptions about performance when deciding to use a single shared, mutable buffer in the styxproto.Decoder method.