search

droyo / styx

Go library for the 9P filesystem protocol
MIT License
64 stars 18 forks source link

Go detects a data race only when TraceLog is not in use #16

Closed dcrosta closed 4 years ago

dcrosta commented 5 years ago

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 4 years ago

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.

droyo commented 4 years ago

I'm unable to reproduce with the change in #22