sirupsen / logrus

Structured, pluggable logging for Go.
MIT License
24.75k stars 2.27k forks source link

When modifying hook concurrently, there is an exception in map processing #1272

Closed lwydyby closed 3 years ago

lwydyby commented 3 years ago

gist: https://gist.github.com/lwydyby/58700d6ea1082d25ecc46049633243c7 error log:

2021-08-11 10:13:18 [19 ] [info ] [1233] :0 test why 2
2021-08-11 10:13:18 [18 ] [info ] [123] :0 test why 
2021-08-11 10:13:18 [19 ] [info ] [1233] :0 test why 2
2021-08-11 10:13:18 [18 ] [info ] [123] :0 test why 
2021-08-11 10:13:18 [19 ] [info ] [1233] :0 test why 2
2021-08-11 10:13:18 [18 ] [info ] [123] :0 test why 
fatal error: concurrent map iteration and map write

goroutine 19 [running]:
runtime.throw(0x10e42bf, 0x26)
        /usr/local/go/src/runtime/panic.go:1117 +0x72 fp=0xc0001b9b80 sp=0xc0001b9b50 pc=0x10334b2
runtime.mapiternext(0xc0001b9cb0)
        /usr/local/go/src/runtime/map.go:858 +0x54c fp=0xc0001b9c00 sp=0xc0001b9b80 pc=0x100f64c
github.com/sirupsen/logrus.(*Entry).fireHooks(0xc00019e2a0)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/entry.go:267 +0x148 fp=0xc0001b9e10 sp=0xc0001b9c00 pc=0x10ae268
github.com/sirupsen/logrus.(*Entry).log(0xc00019e070, 0x4, 0xc00019a100, 0xa)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/entry.go:241 +0x119 fp=0xc0001b9e80 sp=0xc0001b9e10 pc=0x10adf39
github.com/sirupsen/logrus.(*Entry).Log(0xc00019e070, 0x4, 0xc0001b9ef0, 0x1, 0x1)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/entry.go:293 +0x86 fp=0xc0001b9eb8 sp=0xc0001b9e80 pc=0x10ae726
github.com/sirupsen/logrus.(*Entry).Logf(0xc00019e070, 0xc000000004, 0x10deedb, 0xa, 0x0, 0x0, 0x0)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/entry.go:338 +0xe5 fp=0xc0001b9f10 sp=0xc0001b9eb8 pc=0x10ae825
github.com/sirupsen/logrus.(*Logger).Logf(0xc00019e000, 0x4, 0x10deedb, 0xa, 0x0, 0x0, 0x0)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/logger.go:151 +0x95 fp=0xc0001b9f60 sp=0xc0001b9f10 pc=0x10af615
github.com/sirupsen/logrus.(*Logger).Infof(...)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/logger.go:165
github.com/sirupsen/logrus.Infof(...)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/exported.go:199
main.main.func2.1()
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:41 +0xc5 fp=0xc0001b9fd0 sp=0xc0001b9f60 pc=0x10b4565
main.main.func2()
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:42 +0x25 fp=0xc0001b9fe0 sp=0xc0001b9fd0 pc=0x10b45e5
runtime.goexit()
        /usr/local/go/src/runtime/asm_amd64.s:1371 +0x1 fp=0xc0001b9fe8 sp=0xc0001b9fe0 pc=0x1065381
created by main.main
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:31 +0x7d

goroutine 1 [chan receive]:
main.main()
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:46 +0xad

goroutine 18 [runnable]:
sync.runtime_nanotime(0x4)
        /usr/local/go/src/runtime/sema.go:615 +0x3d
sync.(*Mutex).lockSlow(0xc00019e030)
        /usr/local/go/src/sync/mutex.go:136 +0x1ca
sync.(*Mutex).Lock(...)
        /usr/local/go/src/sync/mutex.go:81
github.com/sirupsen/logrus.(*MutexWrap).Lock(...)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/logger.go:58
github.com/sirupsen/logrus.(*Logger).ReplaceHooks(0xc00019e000, 0xc000180060, 0x5)
        /Users/liwei/GolandProjects/pkg/mod/github.com/sirupsen/logrus@v1.8.1/logger.go:399 +0x98
main.RemoveTraceHook(0x1101590, 0xc000090030)
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:78 +0x376
main.main.func1.1()
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:28 +0xe5
main.main.func1()
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:28 +0x25
created by main.main
        /Users/liwei/GolandProjects/gostack/engine/test/main.go:17 +0x65

Process finished with the exit code 2
github-actions[bot] commented 3 years ago

This issue is stale because it has been open for 30 days with no activity.

dgsb commented 3 years ago

I've seen your PR, you should always use ReplaceHooks to remove a specific hook instead of modifying the Hooks directly.

lwydyby commented 3 years ago
// ReplaceHooks replaces the logger hooks and returns the old ones
func (logger *Logger) ReplaceHooks(hooks LevelHooks) LevelHooks {
    logger.mu.Lock()
    oldHooks := logger.Hooks
    logger.Hooks = hooks
    logger.mu.Unlock()
    return oldHooks
}

type LevelHooks map[Level][]Hook

image I have used ReplaceHooks ,But this method cannot replace a specific hook. I can only traverse to remove the previously registered hook separately, and then call ReplaceHooks ,If the lock is not provided, is there any other way to get LevelHooks

lwydyby commented 3 years ago

you mean is to pass an empty map first, get the old map, then traverse the old map, and then replace the map after the modification is completed ? But this will cause the log to not trigger the correct hook for a period of time

github-actions[bot] commented 3 years ago

This issue is stale because it has been open for 30 days with no activity.

github-actions[bot] commented 3 years ago

This issue was closed because it has been inactive for 14 days since being marked as stale.