0

I'm working on a slack bot as my first golang project and while the functionality of this specific bot command works great, it can randomly panic and throw an error.

I was able to determine that I have data races going on, specifically with my two go routines. However I am having difficulty determining how to patch them, or whether doing a mutex lock is a proper way to handle shared variables.

I'm trying to figure out if the issue is my result variable, which is split into channels that are each handled by the go routine, or if it is my buffer variable used by the os.exec package to run a command that both stdout and stderr modify.

Here is the code, and data race examples below.

package reboot

import (

    "bytes"
    "encoding/json"
    "fmt"
    "io/ioutil"
    "log"
    "os/exec"
    "regexp"
)

// to handle json keys
type rebootObject struct {
    Name    string
    Command string
}

var (
    fileNotFound = "config file not found"
    cmdNotFound  = "Error finding command argument"
)

// *bot.Cmd is the first arg to be passed to the bot
// bot.CmdResultV3 wants message from go routine and done = true
func Reboot(command *bot.Cmd) (result bot.CmdResultV3, err error) {
    result = bot.CmdResultV3{Message: make(chan string), Done: make(chan bool, 1)}

    // load json config file with names/commands
    filePath := "./plugins/reboot/config.json"
    file, err1 := ioutil.ReadFile(filePath)
    if err1 != nil {
        bot.Reply(command.Channel, fileNotFound, command.User)
    }

    var scriptParse []rebootObject
    //userinput := "box4535345346" // faking user input
    userinput := command.Args[0] // real one
    err2 := json.Unmarshal(file, &scriptParse)
    if err2 != nil {
        fmt.Println("error:", err2)
        bot.Reply(command.Channel, fileNotFound, command.User)
    }
    //strip numbers off input to match json key
    reg, err := regexp.Compile("[^a-zA-Z]+")
    if err != nil {
        log.Fatal(err)
    }
    // loop through json file to find the match of user input to json name key
    cmdFound := false
    for k := range scriptParse {
        newinput := reg.ReplaceAllString(userinput, "")
        // keep running for loop until names do match
        if scriptParse[k].Name != newinput {
            continue
        }
        cmdFound = true

        cmd := exec.Command("/bin/bash", "-c", scriptParse[k].Command)
        var b bytes.Buffer
        cmd.Stdout = &b
        cmd.Stderr = &b
        err = cmd.Start()
        if err != nil {
            return
        }
        done := false
        go func() {
            cmd.Wait()
            done = true
            result.Done <- true
        }()
        go func() {
            for {
                line, _ := b.ReadString('\n')
                if line != "" {
                    result.Message <- line
                }
                if done {
                    close(result.Message)
                    break
                }

            }
        }()
    }
    if cmdFound == false {
        result.Done <- true
        bot.Reply(command.Channel, cmdNotFound, command.User)
    }
    return result, nil
}

Data races:

==================
WARNING: DATA RACE
Read at 0x00c420582558 by goroutine 37:
  bytes.(*Buffer).readSlice()
      /usr/local/go/src/bytes/buffer.go:421 +0x48
  bytes.(*Buffer).ReadString()
      /usr/local/go/src/bytes/buffer.go:440 +0x45
  github.com/owner/gobot/plugins/reboot.Reboot.func2()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:79 +0x41

Previous write at 0x00c420582558 by goroutine 35:
  bytes.(*Buffer).ReadFrom()
      /usr/local/go/src/bytes/buffer.go:92 +0x608
  io.copyBuffer()
      /usr/local/go/src/io/io.go:386 +0x348
  io.Copy()
      /usr/local/go/src/io/io.go:362 +0x7e
  os/exec.(*Cmd).writerDescriptor.func1()
      /usr/local/go/src/os/exec/exec.go:264 +0x68
  os/exec.(*Cmd).Start.func1()
      /usr/local/go/src/os/exec/exec.go:380 +0x34

Goroutine 37 (running) created at:
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:77 +0x885
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0

Goroutine 35 (running) created at:
  os/exec.(*Cmd).Start()
      /usr/local/go/src/os/exec/exec.go:379 +0xa6b
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:67 +0x7c8
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0
==================
==================
WARNING: DATA RACE
Read at 0x00c420582540 by goroutine 37:
  bytes.(*Buffer).readSlice()
      /usr/local/go/src/bytes/buffer.go:421 +0x62
  bytes.(*Buffer).ReadString()
      /usr/local/go/src/bytes/buffer.go:440 +0x45
  github.com/owner/gobot/plugins/reboot.Reboot.func2()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:79 +0x41

Previous write at 0x00c420582540 by goroutine 35:
  bytes.(*Buffer).ReadFrom()
      /usr/local/go/src/bytes/buffer.go:91 +0x5d0
  io.copyBuffer()
      /usr/local/go/src/io/io.go:386 +0x348
  io.Copy()
      /usr/local/go/src/io/io.go:362 +0x7e
  os/exec.(*Cmd).writerDescriptor.func1()
      /usr/local/go/src/os/exec/exec.go:264 +0x68
  os/exec.(*Cmd).Start.func1()
      /usr/local/go/src/os/exec/exec.go:380 +0x34

Goroutine 37 (running) created at:
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:77 +0x885
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0

Goroutine 35 (running) created at:
  os/exec.(*Cmd).Start()
      /usr/local/go/src/os/exec/exec.go:379 +0xa6b
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:67 +0x7c8
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0
==================
==================
WARNING: DATA RACE
Write at 0x00c420582560 by goroutine 37:
  bytes.(*Buffer).readSlice()
      /usr/local/go/src/bytes/buffer.go:429 +0x186
  bytes.(*Buffer).ReadString()
      /usr/local/go/src/bytes/buffer.go:440 +0x45
  github.com/owner/gobot/plugins/reboot.Reboot.func2()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:79 +0x41

Previous write at 0x00c420582560 by goroutine 35:
  bytes.(*Buffer).ReadFrom()
      /usr/local/go/src/bytes/buffer.go:191 +0x5f
  io.copyBuffer()
      /usr/local/go/src/io/io.go:386 +0x348
  io.Copy()
      /usr/local/go/src/io/io.go:362 +0x7e
  os/exec.(*Cmd).writerDescriptor.func1()
      /usr/local/go/src/os/exec/exec.go:264 +0x68
  os/exec.(*Cmd).Start.func1()
      /usr/local/go/src/os/exec/exec.go:380 +0x34

Goroutine 37 (running) created at:
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:77 +0x885
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0

Goroutine 35 (running) created at:
  os/exec.(*Cmd).Start()
      /usr/local/go/src/os/exec/exec.go:379 +0xa6b
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:67 +0x7c8
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0
==================
==================
WARNING: DATA RACE
Read at 0x00c42014cc00 by goroutine 37:
  runtime.slicebytetostring()
      /usr/local/go/src/runtime/string.go:72 +0x0
  bytes.(*Buffer).ReadString()
      /usr/local/go/src/bytes/buffer.go:441 +0x84
  github.com/owner/gobot/plugins/reboot.Reboot.func2()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:79 +0x41

Previous write at 0x00c42014cc00 by goroutine 35:
  internal/race.WriteRange()
      /usr/local/go/src/internal/race/race.go:49 +0x42
  syscall.Read()
      /usr/local/go/src/syscall/syscall_unix.go:165 +0x9a
  internal/poll.(*FD).Read()
      /usr/local/go/src/internal/poll/fd_unix.go:122 +0x1a0
  os.(*File).read()
      /usr/local/go/src/os/file_unix.go:216 +0x70
  os.(*File).Read()
      /usr/local/go/src/os/file.go:103 +0x8e
  bytes.(*Buffer).ReadFrom()
      /usr/local/go/src/bytes/buffer.go:209 +0x1dd
  io.copyBuffer()
      /usr/local/go/src/io/io.go:386 +0x348
  io.Copy()
      /usr/local/go/src/io/io.go:362 +0x7e
  os/exec.(*Cmd).writerDescriptor.func1()
      /usr/local/go/src/os/exec/exec.go:264 +0x68
  os/exec.(*Cmd).Start.func1()
      /usr/local/go/src/os/exec/exec.go:380 +0x34

Goroutine 37 (running) created at:
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:77 +0x885
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0

Goroutine 35 (running) created at:
  os/exec.(*Cmd).Start()
      /usr/local/go/src/os/exec/exec.go:379 +0xa6b
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:67 +0x7c8
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0
==================
==================
WARNING: DATA RACE
Read at 0x00c4202d2600 by goroutine 37:
  runtime.slicebytetostring()
      /usr/local/go/src/runtime/string.go:72 +0x0
  bytes.(*Buffer).ReadString()
      /usr/local/go/src/bytes/buffer.go:441 +0x84
  github.com/owner/gobot/plugins/reboot.Reboot.func2()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:79 +0x41

Previous write at 0x00c4202d2600 by goroutine 35:
  runtime.slicecopy()
      /usr/local/go/src/runtime/slice.go:160 +0x0
  bytes.(*Buffer).ReadFrom()
      /usr/local/go/src/bytes/buffer.go:205 +0x4b2
  io.copyBuffer()
      /usr/local/go/src/io/io.go:386 +0x348
  io.Copy()
      /usr/local/go/src/io/io.go:362 +0x7e
  os/exec.(*Cmd).writerDescriptor.func1()
      /usr/local/go/src/os/exec/exec.go:264 +0x68
  os/exec.(*Cmd).Start.func1()
      /usr/local/go/src/os/exec/exec.go:380 +0x34

Goroutine 37 (running) created at:
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:77 +0x885
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0

Goroutine 35 (running) created at:
  os/exec.(*Cmd).Start()
      /usr/local/go/src/os/exec/exec.go:379 +0xa6b
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:67 +0x7c8
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0
==================
==================
WARNING: DATA RACE
Write at 0x00c4202008c8 by goroutine 36:
  github.com/owner/gobot/plugins/reboot.Reboot.func1()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:74 +0x4d

Previous read at 0x00c4202008c8 by goroutine 37:
  github.com/owner/gobot/plugins/reboot.Reboot.func2()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:83 +0x61

Goroutine 36 (running) created at:
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:72 +0x846
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0

Goroutine 37 (running) created at:
  github.com/owner/gobot/plugins/reboot.Reboot()
      /Users/macowner/go/src/github.com/owner/gobot/plugins/reboot/reboot.go:77 +0x885
  github.com/owner/gobot/bot.(*Bot).handleCmd()
      /Users/macowner/go/src/github.com/owner/gobot/bot/cmd.go:240 +0x13b
  github.com/owner/gobot/bot.(*Bot).MessageReceived()
      /Users/macowner/go/src/github.com/owner/gobot/bot/bot.go:101 +0x5a8
  github.com/owner/gobot/bot.Run()
      /Users/macowner/go/src/github.com/owner/gobot/bot/reply.go:142 +0xdb3
  main.main()
      /Users/macowner/go/src/github.com/owner/gobot/main.go:46 +0x9b0
==================
Jonathan Hall
  • 75,165
  • 16
  • 143
  • 189
Blooze
  • 1,987
  • 4
  • 16
  • 19
  • 1
    Try using [cmd.StdoutPipe](https://golang.org/pkg/os/exec/#Cmd.StdoutPipe) (and same for stderr) rather than reading from a buffer at the same time it's being written to. – Marc Feb 13 '18 at 15:05
  • I don't know if we have the full context necessary to solve the problem, but I would say `select` is your friend. – trey-jones Feb 13 '18 at 15:20
  • @threeve - I think everything should be available to see the issue, the bot is decoupled from the commands so this package only pulls in a few things to communicate back. – Blooze Feb 13 '18 at 16:51

2 Answers2

0

The first goroutine, starting with cmd.Wait(), is writing to the buffer b while the other goroutine, starting with line, _ := b.ReadString('\n') is reading from it. That's why datarace happens. Modify the code in such a way that the result of execution is read only after completion of execution.

rabhis
  • 440
  • 2
  • 5
0

rabhis is correct, you could embed the buffer with a mutex something like:

https://gist.github.com/arkan/5924e155dbb4254b64614069ba0afd81

package safebuffer

import (
    "bytes"
    "sync"
)

// Buffer is a goroutine safe bytes.Buffer
type Buffer struct {
    buffer bytes.Buffer
    mutex  sync.Mutex
}

// Write appends the contents of p to the buffer, growing the buffer as needed. It returns
// the number of bytes written.
func (s *Buffer) Write(p []byte) (n int, err error) {
    s.mutex.Lock()
    defer s.mutex.Unlock()
    return s.buffer.Write(p)
}

// String returns the contents of the unread portion of the buffer
// as a string.  If the Buffer is a nil pointer, it returns "<nil>".
func (s *Buffer) String() string {
    s.mutex.Lock()
    defer s.mutex.Unlock()
    return s.buffer.String()
}
reedobrien
  • 116
  • 4