search

sirupsen / logrus

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

[DATA RACE] Uniqueness of hook event for each HTTP request #1367

Closed bentcoder closed 1 year ago

bentcoder commented 1 year ago

Hi,

I haven't seen a clear note on this in the doc so need a clarification please.

As seen below I have a custom hook which aims to add:

  1. static fields (always same value for all HTTP requests) to all logs
  2. context fields (always different value for each HTTP requests) to all logs when WithContext(r.Context()) is used

When we update e.Data in Fire function, is this mutation always unique to each HTTP requests? I am asking this because I want to make sure that the point 2 above is valid.

Client 1: { ... "app":"tetris", "ver":"v0.0.1", "request_id": "UUID-1", "trace_id": "TRACE-1"}
Client 2: { ... "app":"tetris", "ver":"v0.0.1", "request_id": "UUID-2", "trace_id": "TRACE-2"}
Client 3: { ... "app":"tetris", "ver":"v0.0.1", "request_id": "UUID-3", "trace_id": "TRACE-3"}
...
Client 9: { ... "app":"tetris", "ver":"v0.0.1", "request_id": "UUID-2", "trace_id": "TRACE-2"}  <- Must not happen

Thanks

logrus.AddHook(Hook{
    StaticFields:  map[string]interface{}{"app":"tetris", "ver":"v0.0.1"},
    ContextFields: []string{"request_id", "trace_id"}
})
type Hook struct {
    StaticFields  map[string]interface{}
    ContextFields []string
}

func (h Hook) Levels() []logrus.Level {
    return logrus.AllLevels
}

func (h Hook) Fire(e *logrus.Entry) error {
    e.Data = h.StaticFields

    if e.Context == nil {
        return nil
    }

    for _, name := range h.ContextFields {
        if val := e.Context.Value(name); val != nil {
            e.Data[name] = val
        }
    }

    return nil
}

UPDATE

See post below to reproduce the behaviour in a loop rarher than a HTTP version (just to keep it short).

bentcoder commented 1 year ago

Looks like Fire is not unique for each log call as it causes data race. See example simulator below.

# logger.go

package logger

import (
    "github.com/sirupsen/logrus"
)

type Hook struct {
    StaticFields  map[string]any
    ContextFields map[string]any
}

func Setup(hook Hook) {
    logrus.AddHook(hook)
}

func (h Hook) Levels() []logrus.Level {
    return logrus.AllLevels
}

func (h Hook) Fire(e *logrus.Entry) error {
    e.Data = h.StaticFields

    if e.Context == nil {
        return nil
    }

    for name, key := range h.ContextFields {
        if val := e.Context.Value(key); val != nil {
            e.Data[name] = val
        }
    }

    return nil
}
# main.go

package main

import (
    "context"
    "loog/logger"
    "time"

    "github.com/sirupsen/logrus"
)

func main() {
    logger.Setup(logger.Hook{
        StaticFields:  map[string]any{"ver": "v1.0.0"},
        ContextFields: map[string]any{string(CtxRequestIDKey): CtxRequestIDKey},
    })

    for i := 1; i <= 100; i++ {
        go log(i)
    }

    time.Sleep(10)
}

func log(i int) {
    ctx := context.WithValue(context.Background(), CtxRequestIDKey, i)

    logrus.WithContext(ctx).Info(i)
}

type ctxRequestID string

const CtxRequestIDKey = ctxRequestID("request_id")
$ go run -race main.go 
==================
WARNING: DATA RACE
Write at 0x00c000126210 by goroutine 9:
  runtime.mapaccess2_faststr()
      /usr/local/go/src/runtime/map_faststr.go:108 +0x43c
  loog/logger.Hook.Fire()
      /Users/you/dev/playground/loog/logger/logger.go:29 +0x184
  loog/logger.(*Hook).Fire()
      <autogenerated>:1 +0x50
  github.com/sirupsen/logrus.LevelHooks.Fire()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/hooks.go:28 +0xb0
  github.com/sirupsen/logrus.(*Entry).fireHooks()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:280 +0x234
  github.com/sirupsen/logrus.(*Entry).log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:242 +0x620
  github.com/sirupsen/logrus.(*Entry).Log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x80
  github.com/sirupsen/logrus.(*Entry).Info()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:321 +0xd4
  main.log()
      /Users/you/dev/playground/loog/main.go:27 +0xa4
  main.main.func1()
      /Users/you/dev/playground/loog/main.go:18 +0x34

Previous write at 0x00c000126210 by goroutine 20:
  runtime.mapaccess2_faststr()
      /usr/local/go/src/runtime/map_faststr.go:108 +0x43c
  loog/logger.Hook.Fire()
      /Users/you/dev/playground/loog/logger/logger.go:29 +0x184
  loog/logger.(*Hook).Fire()
      <autogenerated>:1 +0x50
  github.com/sirupsen/logrus.LevelHooks.Fire()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/hooks.go:28 +0xb0
  github.com/sirupsen/logrus.(*Entry).fireHooks()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:280 +0x234
  github.com/sirupsen/logrus.(*Entry).log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:242 +0x620
  github.com/sirupsen/logrus.(*Entry).Log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x80
  github.com/sirupsen/logrus.(*Entry).Info()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:321 +0xd4
  main.log()
      /Users/you/dev/playground/loog/main.go:27 +0xa4
  main.main.func1()
      /Users/you/dev/playground/loog/main.go:18 +0x34

Goroutine 9 (running) created at:
  main.main()
      /Users/you/dev/playground/loog/main.go:18 +0x194

Goroutine 20 (running) created at:
  main.main()
      /Users/you/dev/playground/loog/main.go:18 +0x194
==================
==================
WARNING: DATA RACE
Write at 0x00c00014c098 by goroutine 7:
  loog/logger.Hook.Fire()
      /Users/you/dev/playground/loog/logger/logger.go:29 +0x190
  loog/logger.(*Hook).Fire()
      <autogenerated>:1 +0x50
  github.com/sirupsen/logrus.LevelHooks.Fire()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/hooks.go:28 +0xb0
  github.com/sirupsen/logrus.(*Entry).fireHooks()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:280 +0x234
  github.com/sirupsen/logrus.(*Entry).log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:242 +0x620
  github.com/sirupsen/logrus.(*Entry).Log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x80
  github.com/sirupsen/logrus.(*Entry).Info()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:321 +0xd4
  main.log()
      /Users/you/dev/playground/loog/main.go:27 +0xa4
  main.main.func1()
      /Users/you/dev/playground/loog/main.go:18 +0x34

Previous write at 0x00c00014c098 by goroutine 20:
  loog/logger.Hook.Fire()
      /Users/you/dev/playground/loog/logger/logger.go:29 +0x190
  loog/logger.(*Hook).Fire()
      <autogenerated>:1 +0x50
  github.com/sirupsen/logrus.LevelHooks.Fire()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/hooks.go:28 +0xb0
  github.com/sirupsen/logrus.(*Entry).fireHooks()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:280 +0x234
  github.com/sirupsen/logrus.(*Entry).log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:242 +0x620
  github.com/sirupsen/logrus.(*Entry).Log()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:304 +0x80
  github.com/sirupsen/logrus.(*Entry).Info()
      /Users/you/go/pkg/mod/github.com/sirupsen/logrus@v1.9.0/entry.go:321 +0xd4
  main.log()
      /Users/you/dev/playground/loog/main.go:27 +0xa4
  main.main.func1()
      /Users/you/dev/playground/loog/main.go:18 +0x34

Goroutine 7 (running) created at:
  main.main()
      /Users/you/dev/playground/loog/main.go:18 +0x194

Goroutine 20 (running) created at:
  main.main()
      /Users/you/dev/playground/loog/main.go:18 +0x194
==================
...
...
INFO[0000] 2                                             request_id=51 ver=v1.0.0
INFO[0000] 98                                            request_id=51 ver=v1.0.0
INFO[0000] 99                                            request_id=51 ver=v1.0.0
INFO[0000] 51                                            request_id=51 ver=v1.0.0
Found 2 data race(s)
exit status 66
github-actions[bot] commented 1 year ago

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

github-actions[bot] commented 1 year ago

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