Logrus: Data Race in entry.go:128

[cosminilie]

There seems to be a data race between github.com/Sirupsen/logrus.(*Entry).Info() at line 128 and the github.com/Sirupsen/logrus.SetLevel() method. I guess this applies to all methods on the Entry (Info, Warn, Error, Debug) at the if statement "if entry.Logger.Level >= InfoLevel {....."

This happens to me, because i want to update the loglevel externally (http endpoint).

Ex:

go func() {
        for {
            level := <-logLevel
            log.SetLevel(level)
        }
}()

//Business domain
    go func() {
        log.WithFields(log.Fields{
            "File":   "main.go",
            "Action": "BussinessLogicInit",
        }).Info("Started Main Bussiness Unit")
   ......
}()

[sirupsen]

Patch very welcome :+1:

[cosminilie]

Will try to send a patch. Thank you

[ash2k]

Same thing about all the other fields - Formatter, Hooks, Out.
e.g. log.SetFormatter(...) accesses field Formatter of the global instance while holding the mutex, but code in entry.go is reading from the field not holding the mutex.

[dryaf]

yep, server down

panic: sync: WaitGroup is reused before previous Wait has returned

goroutine 97 [running]:
panic(0x739d80, 0xc848524040)
    /usr/local/go/src/runtime/panic.go:481 +0x3e6
sync.(*WaitGroup).Wait(0xc8202ee968)
    /usr/local/go/src/sync/waitgroup.go:129 +0x114
vendor/github.com/gemnasium/logrus-graylog-hook.(*GraylogHook).Flush(0xc8202ee940)
    vendor/github.com/gemnasium/logrus-graylog-hook/graylog_hook.go:91 +0x2d
vendor/github.com/gemnasium/logrus-graylog-hook.(*GraylogHook).Fire(0xc8202ee940, 0xc8470a2f00, 0x0, 0x0)
    vendor/github.com/gemnasium/logrus-graylog-hook/graylog_hook.go:84 +0xf2
vendor/github.com/Sirupsen/logrus.LevelHooks.Fire(0xc8202f4420, 0xc816a31a02, 0xc8470a2f00, 0x0, 0x0)
    /vendor/github.com/Sirupsen/logrus/hooks.go:28 +0x106
github.com/Sirupsen/logrus.Entry.log(0xc8202ee8c0, 0xc8484b5bc0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x1300002, 0xc84851c360, ...)
vendor/github.com/Sirupsen/logrus/entry.go:88 +0x119
vendor/github.com/Sirupsen/logrus.(*Entry).Error(0xc8470a2ec0, 0xc846b2d9a8, 0x1, 0x1)
vendor/github.com/Sirupsen/logrus/entry.go:145 +0x8c

[ash2k]

Ideally logging framework should not be thread-safe by default and provide means to wrap logger instance with a synchronizing wrapper. Take a look at math/rand package and how global rand is using a wrapped Source to add locking with mutex.
Global instance may be thread safe, but IMHO it should not be necessary unless user wants to do logger configuration concurrently with a running program. Most users probably configure logger at startup and do not touch it after so locking is pure overhead.
It may not be possible to retrofit such change without breaking the current API of course.

[talbright]

+1

We need to make sure the library is thread safe...

[dryaf]

i ended up using this (github.com/robertkowalski/graylog-golang) to send a marshalled json to the logserver and thats it :), survives the loadtest, keep it simple and stupid

[klizhentas]

@Sirupsen can you please take a look:

https://github.com/Sirupsen/logrus/pull/374

[sherryCP]

I am getting this race condition error. can you guys please guide me.

fatal error: concurrent map read and map write

goroutine 9654 [running]:
runtime.throw(0x2496232, 0x21)
/var/jenkins_home/tools/org.jenkinsci.plugins.golang.GolangInstallation/Go_v1.7/src/runtime/panic.go:566 +0x95 fp=0xc420eec678 sp=0xc420eec658
runtime.mapaccess1_faststr(0x21136e0, 0xc420b16960, 0x244ce0d, 0x5, 0xc420eec868)
/var/jenkins_home/tools/org.jenkinsci.plugins.golang.GolangInstallation/Go_v1.7/src/runtime/hashmap_fast.go:201 +0x4f3 fp=0xc420eec6d8 sp=0xc420eec678
cluster-manager/vendor/github.com/sirupsen/logrus.(TextFormatter).printColored(0xc420779800, 0xc42040c070, 0xc420f26140, 0xc420f220c0, 0x3, 0x3, 0x24802da, 0x19)
/var/jenkins_home/workspace/cluster-manager-node-level/cluster-apps/src/cluster-manager/vendor/github.com/sirupsen/logrus/text_formatter.go:137 +0x31f fp=0xc420eec8b8 sp=0xc420eec6d8
cluster-manager/vendor/github.com/sirupsen/logrus.(TextFormatter).Format(0xc420779800, 0xc420f26140, 0x8, 0x4, 0x8, 0x410ba6, 0xc420eecaa0)
/var/jenkins_home/workspace/cluster-manager-node-level/cluster-apps/src/cluster-manager/vendor/github.com/sirupsen/logrus/text_formatter.go:96 +0x79d fp=0xc420eeca60 sp=0xc420eec8b8
cluster-manager/vendor/github.com/sirupsen/logrus.(Entry).write(0xc420f26140)
/var/jenkins_home/workspace/cluster-manager-node-level/cluster-apps/src/cluster-manager/vendor/github.com/sirupsen/logrus/entry.go:128 +0x61 fp=0xc420eecb08 sp=0xc420eeca60
cluster-manager/vendor/github.com/sirupsen/logrus.Entry.log(0xc4203e89b0, 0xc420b16960, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x4, ...)
/var/jenkins_home/workspace/cluster-manager-node-level/cluster-apps/src/cluster-manager/vendor/github.com/sirupsen/logrus/entry.go:104 +0x196 fp=0xc420eecb70 sp=0xc420eecb08
cluster-manager/vendor/github.com/sirupsen/logrus.(Entry).Info(0xc420d63d10, 0xc420eece30, 0x2, 0x2)
/var/jenkins_home/workspace/cluster-manager-node-level/cluster-apps/src/cluster-manager/vendor/github.com/sirupsen/logrus/entry.go:153 +0xb6 fp=0xc420eecbe0 sp=0xc420eecb70
cluster-manager/deploymentmanager.(*Deployer).StartStopServices.func2(0x244c86c, 0x4, 0xc420d63d10, 0xc420f10b00, 0xc420d63e00, 0x35a1560, 0xc420b16990, 0xc42075a920, 0x18, 0xc420dccfc0, ...)

[sherryCP]

I just can't understand that

serialized, err := entry.Logger.Formatter.Format(entry)

is before

entry.Logger.mu.Lock()

in the following function

func (entry *Entry) write() {
serialized, err := entry.Logger.Formatter.Format(entry)
entry.Logger.mu.Lock()
defer entry.Logger.mu.Unlock()
if err != nil {
fmt.Fprintf(os.Stderr, "Failed to obtain reader, %v\n", err)
} else {
_, err = entry.Logger.Out.Write(serialized)
if err != nil {
fmt.Fprintf(os.Stderr, "Failed to write to log, %v\n", err)
}
}
}

[nianglao]

@sherryCP Maybe your problem relates to https://github.com/sirupsen/logrus/issues?utf8=%E2%9C%93&q=Concurrent+map

Please paste more detail info about how to reproduce this case.

[dgsb]

Fixed in #695