race condition on data map

[dreyinger]

Hey, the following code produces a race condition in graylog_hook.go line 146 because there is a read access on the Data map outside the Hook interfaces Fire function.

package main

import (
    "time"

    "gopkg.in/gemnasium/logrus-graylog-hook.v1"

    "github.com/Sirupsen/logrus"
)

func main() {
    log := logrus.New()
    hook := graylog.NewAsyncGraylogHook("localhost:12201", "facility", map[string]interface{}{"this": "is logged every time"})
    defer hook.Flush()
    log.Hooks.Add(hook)

    go func() {
        log.WithFields(logrus.Fields{"msg": "test1"}).Info("test1")
    }()

    log.WithFields(logrus.Fields{"msg": "test2"}).Info("test2")

    ch := time.Tick(time.Second * 1)

    <-ch
}

[gravis]

Good catch, we need to fix that. Thanks

[gravis]

Could you check you are using the last version of this repo please? This should have been fixed in #6 This is running fine here:

package main

import (
        "time"

        "gopkg.in/gemnasium/logrus-graylog-hook.v1"

        "github.com/Sirupsen/logrus"
)

func main() {
        log := logrus.New()
        hook := graylog.NewAsyncGraylogHook("localhost:12201", "facility", map[string]interface{}{"this": "is logged every time"})
        defer hook.Flush()
        log.Hooks.Add(hook)

        go func() {
                for i := 0; i < 100; i++ {

                        log.WithFields(logrus.Fields{"msg": "test1"}).Info("test1")
                }
        }()

        for i := 0; i < 100; i++ {
                log.WithFields(logrus.Fields{"msg": "test2"}).Info("test2")
        }

        ch := time.Tick(time.Second * 1)

        <-ch
}

[ekle]

reproduced with the latest versions in a docker container: (does not happen always)

==================                                                                                     
WARNING: DATA RACE                                                                                     
Read by goroutine 9:                                                                                   
  runtime.mapiterinit()                                                                                
      /usr/lib/go-1.6/src/runtime/hashmap.go:607 +0x0                                                  
  gopkg.in/gemnasium/logrus-graylog-hook%2ev1.(*GraylogHook).sendEntry()                               
      /root/go/src/gopkg.in/gemnasium/logrus-graylog-hook.v1/graylog_hook.go:146 +0x5d8                
  gopkg.in/gemnasium/logrus-graylog-hook%2ev1.(*GraylogHook).fire()                                    
      /root/go/src/gopkg.in/gemnasium/logrus-graylog-hook.v1/graylog_hook.go:109 +0xbf                 

Previous write by goroutine 88:                                                                        
  runtime.mapassign1()                                                                                 
      /usr/lib/go-1.6/src/runtime/hashmap.go:429 +0x0                                                  
  github.com/Sirupsen/logrus.(*TextFormatter).Format()                                                 
      /root/go/src/github.com/Sirupsen/logrus/text_formatter.go:71 +0x56c                              
  github.com/Sirupsen/logrus.(*Entry).Reader()                                                         
      /root/go/src/github.com/Sirupsen/logrus/entry.go:44 +0xa1                                        
  github.com/Sirupsen/logrus.Entry.log()                                                               
      /root/go/src/github.com/Sirupsen/logrus/entry.go:94 +0x37a                                       
  github.com/Sirupsen/logrus.(*Entry).Info()                                                           
      /root/go/src/github.com/Sirupsen/logrus/entry.go:129 +0xe2                                       
  main.main.func1()                                                                                    
      /root/go/src/test/test.go:22 +0x251                                                              

Goroutine 9 (running) created at:                                                                      
  gopkg.in/gemnasium/logrus-graylog-hook%2ev1.NewAsyncGraylogHook()                                    
      /root/go/src/gopkg.in/gemnasium/logrus-graylog-hook.v1/graylog_hook.go:69 +0x342                 
  main.main()                                                                                          
      /root/go/src/test/test.go:14 +0x327                                                              

Goroutine 88 (running) created at:                                                                     
  main.main()                                                                                          
      /root/go/src/test/test.go:24 +0x41f                                                              
==================                                

package main

import (
        "runtime"
        "time"

        "github.com/Sirupsen/logrus"
        graylog "gopkg.in/gemnasium/logrus-graylog-hook.v1"
)

func main() {
        runtime.GOMAXPROCS(16)
        log := logrus.New()
        hook := graylog.NewAsyncGraylogHook("localhost:12201", "facility", map[string]interface{}{"this": "is logged every time"})
        defer hook.Flush()
        log.Hooks.Add(hook)
        x := make(chan bool)
        for i := 0; i < 160; i++ {
                go func() {
                        <-x
                        for i := 0; i < 10000; i++ {
                                log.WithFields(logrus.Fields{"msg": "test1"}).Info("test1")
                        }
                }()
        }
        close(x)

        ch := time.Tick(time.Second * 5)

        <-ch
}

FROM ubuntu:16.04
RUN echo https://github.com/gemnasium/logrus-graylog-hook/issues/8
RUN apt-get update
RUN apt-get install -y golang git
ADD test.go /root/go/src/test/test.go
RUN cd /root/go/src/test ; GOPATH=/root/go go get -v
RUN cd /root/go/src/test ; GOPATH=/root/go go run --race test.go

[dreyinger]

Yes I think I am using the latest version of this repo. The problem is that logrus prefixes log fields msg, level and time with "fields." to prevent them from being overwritten. When you are putting the entry onto the buffer you are not making a deep copy of the "Data" map which leads to this race condition. You should probably add something like this to the "Fire" function to do a deep copy:

newData := make(map[string]interface{})
for k, v := range entry.Data {
    newData[k] = v
}

newEntry := &logrus.Entry{entry.Logger, newData, entry.Time, entry.Level,  entry.Message}
gEntry := graylogEntry{newEntry, file, line}

[gravis]

Thanks! I will take a look today