Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

FormatLogRecord formatCache doesn't seem thread-safe #20

Open
ipsoft-rmcevoy opened this issue Jan 6, 2020 · 0 comments
Open

FormatLogRecord formatCache doesn't seem thread-safe #20

ipsoft-rmcevoy opened this issue Jan 6, 2020 · 0 comments

Comments

@ipsoft-rmcevoy
Copy link

ipsoft-rmcevoy commented Jan 6, 2020 •
edited
Loading 

func FormatLogRecord(format string, rec *LogRecord) string {
	if rec == nil {
		return "<nil>"
	}
	if len(format) == 0 {
		return ""
	}

	out := bytes.NewBuffer(make([]byte, 0, 64))
	secs := rec.Created.UnixNano() / 1e9

	cache := *formatCache
	if cache.LastUpdateSeconds != secs {
		month, day, year := rec.Created.Month(), rec.Created.Day(), rec.Created.Year()
		hour, minute, second := rec.Created.Hour(), rec.Created.Minute(), rec.Created.Second()
		zone, _ := rec.Created.Zone()
		updated := &formatCacheType{
			LastUpdateSeconds: secs,
			shortTime:         fmt.Sprintf("%02d:%02d", hour, minute),
			shortDate:         fmt.Sprintf("%02d/%02d/%02d", day, month, year%100),
			longTime:          fmt.Sprintf("%02d:%02d:%02d %s", hour, minute, second, zone),
			longDate:          fmt.Sprintf("%04d/%02d/%02d", year, month, day),
		}
		cache = *updated
		formatCache = updated

	}

If i create a NewFileLogWriter and don't close the global default logger, I can easily create a race condition when FormatLogRecord modifies the formatCache. Multiple go routines invoke this function without any locking around this resource.

This is semi-related to this issue #13 which is also a data race condition created in this same function - since the LogRecord is being passed by reference in multiple go routines and rec.Created is modified.

Here is the output when using https://golang.org/doc/articles/race_detector.html

==================
WARNING: DATA RACE
Read at 0x00c0000fc148 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:46 +0xf9
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x00c0000fc148 by main goroutine:
  my.company/my-service/logger.(*CustomLogWriter).LogWrite()
      /Users/me/Development/my-service/logger/CustomLogWriter.go:22 +0x105
[22:36:34 UTC 2020/01/06] [DEFAULT] [INFO] (main.main:55) test
  github.com/jeanphorn/log4go.(*Filter).intLogf()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/category.go:69 +0x37f
  github.com/jeanphorn/log4go.(*Filter).Info()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/category.go:252 +0x1e3
  main.main()
      /Users/me/Development/my-service/main.go:55 +0x9ef

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41
==================
==================
WARNING: DATA RACE
Read at 0x000001dda710 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:48 +0x182
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x000001dda710 by goroutine 11:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:61 +0x11cb
  github.com/jeanphorn/log4go.NewFileLogWriter.func1()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:119 +0x2d8

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41

Goroutine 11 (running) created at:
  github.com/jeanphorn/log4go.NewFileLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:83 +0x3ac
  main.main()
      /Users/me/Development/my-service/main.go:45 +0x747
==================
==================
WARNING: DATA RACE
Read at 0x00c000190050 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:48 +0x1a5
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x00c000190050 by goroutine 11:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:54 +0x104b
  github.com/jeanphorn/log4go.NewFileLogWriter.func1()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:119 +0x2d8

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41

Goroutine 11 (running) created at:
  github.com/jeanphorn/log4go.NewFileLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:83 +0x3ac
  main.main()
      /Users/me/Development/my-service/main.go:45 +0x747
==================
==================
WARNING: DATA RACE
Read at 0x00c000190058 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:48 +0x1a5
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x00c000190058 by goroutine 11:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:55 +0x1073
  github.com/jeanphorn/log4go.NewFileLogWriter.func1()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:119 +0x2d8

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41

Goroutine 11 (running) created at:
  github.com/jeanphorn/log4go.NewFileLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:83 +0x3ac
  main.main()
      /Users/me/Development/my-service/main.go:45 +0x747
==================
==================
WARNING: DATA RACE
Read at 0x00c000190068 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:48 +0x1a5
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x00c000190068 by goroutine 11:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:56 +0x10b5
  github.com/jeanphorn/log4go.NewFileLogWriter.func1()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:119 +0x2d8

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41

Goroutine 11 (running) created at:
  github.com/jeanphorn/log4go.NewFileLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:83 +0x3ac
  main.main()
      /Users/me/Development/my-service/main.go:45 +0x747
==================
==================
WARNING: DATA RACE
Read at 0x00c000190078 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:48 +0x1a5
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x00c000190078 by goroutine 11:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:57 +0x10f7
  github.com/jeanphorn/log4go.NewFileLogWriter.func1()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:119 +0x2d8

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41

Goroutine 11 (running) created at:
  github.com/jeanphorn/log4go.NewFileLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:83 +0x3ac
  main.main()
      /Users/me/Development/my-service/main.go:45 +0x747
==================
==================
WARNING: DATA RACE
Read at 0x00c000190088 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:48 +0x1a5
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x00c000190088 by goroutine 11:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:58 +0x1139
  github.com/jeanphorn/log4go.NewFileLogWriter.func1()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:119 +0x2d8

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41

Goroutine 11 (running) created at:
  github.com/jeanphorn/log4go.NewFileLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/filelog.go:83 +0x3ac
  main.main()
      /Users/me/Development/my-service/main.go:45 +0x747
==================
==================
WARNING: DATA RACE
Read at 0x00c0000fc170 by goroutine 8:
  github.com/jeanphorn/log4go.FormatLogRecord()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/pattlog.go:89 +0x62d
  github.com/jeanphorn/log4go.(*ConsoleLogWriter).run()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:34 +0xa3

Previous write at 0x00c0000fc170 by main goroutine:
  my.company/my-service/logger.(*CustomLogWriter).LogWrite()
      /Users/me/Development/my-service/logger/CustomLogWriter.go:23 +0x1dc
  github.com/jeanphorn/log4go.(*Filter).intLogf()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/category.go:69 +0x37f
  github.com/jeanphorn/log4go.(*Filter).Info()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/category.go:252 +0x1e3
  main.main()
      /Users/me/Development/my-service/main.go:55 +0x9ef

Goroutine 8 (running) created at:
  github.com/jeanphorn/log4go.NewConsoleLogWriter()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/termlog.go:26 +0x11e
  github.com/jeanphorn/log4go.init.0()
      /Users/me/go/pkg/mod/github.com/jeanphorn/[email protected]/log4go.go:160 +0x41
==================
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@ipsoft-rmcevoy