Deadlock when using WithField inside of hook

[andytsnowden]

This is most likely related to #807

When using a Hook to add file/line data to each log message we get a deadlock.

go version go1.12.6 windows/amd64
logrus v1.5.0

fatal error: all goroutines are asleep - deadlock!
	/go/src/github.com/EquityZen/zenbot/main.go:34 +0x59
	main.main()
		/go/src/github.com/EquityZen/zenbot/bot/init.go:72 +0xed
	github.com/EquityZen/zenbot/bot.Init(0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/logger.go:203
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.(*Logger).Debug(...)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/logger.go:193 +0x7d
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.(*Logger).Log(0xc00030b420, 0x5, 0xc0017a1018, 0x1, 0x1)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/entry.go:289 +0xeb
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.(*Entry).Log(0xc0001decb0, 0xc000000005, 0xc0017a1018, 0x1, 0x1)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/entry.go:253 +0x1c2
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.Entry.log(0xc00030b420, 0xc000432630, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/entry.go:277 +0x7c
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.(*Entry).write(0xc0001ded20)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/onrik/logrus/filename/filename.go:19 +0x184
	github.com/EquityZen/zenbot/vendor/github.com/onrik/logrus/filename.(*wrapper).Format(0xc000270fa0, 0xc0001ded20, 0xc0017a0d40, 0xa083bd, 0x1288fc0, 0xc000432660, 0xc0017a0d88)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/entry.go:120
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.(*Entry).WithField(...)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/entry.go:125 +0x66c
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.(*Entry).WithFields(0xc0001ded20, 0xc0017a0bc0, 0x0)
		/go/src/github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus/logger.go:53
	github.com/EquityZen/zenbot/vendor/github.com/sirupsen/logrus.(*MutexWrap).Lock(...)
		/usr/local/go/src/sync/mutex.go:81
	sync.(*Mutex).Lock(...)
		/usr/local/go/src/sync/mutex.go:138 +0xfc
	sync.(*Mutex).lockSlow(0xc00030b450)
		/usr/local/go/src/runtime/sema.go:71 +0x47
	sync.runtime_SemacquireMutex(0xc00030b454, 0x1fc2900, 0x1)
	goroutine 1 [semacquire]:

Relevant code block in question:

	// On debug log file names and line
	if logrus.GetLevel() == logrus.DebugLevel {
		filenameHook := filename.NewHook()
		filenameHook.Field = "fileline"
		logrus.AddHook(filenameHook)
	}

If I change my program options to skip this step, such as going to "info" log level it executes without a problem. Tested on both 1.12.6 macOS/Windows and 1.14 alpine.

Happy to provide a simplified code example if needed.

[markphelps]

@andytsnowden thanks for reporting! Yes would you please provide a full code example to reproduce the bug?

[andytsnowden]

@andytsnowden thanks for reporting! Yes would you please provide a full code example to reproduce the bug?

Sure, here's a small script

package main

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

func main() {
	filenamehook := filename.NewHook()
	filenamehook.Field = "fileline"
	logrus.AddHook(filenamehook)
	logrus.SetLevel(logrus.DebugLevel)
	logrus.Debug("hello there")
}

This could very well just be a problem with onrik/logrus/filename figured I would open it here first since I saw the related issue that wasn't using the same hook I was.

In terms of go versions I've tried 1.14.1, 1.13.9 and 1.12.17 none of which seem to behave differently.

[xialu4820723]

Maybe the problem is the same with #1122 (comment)
"github.com/onrik/logrus/filename" is invisible to me so the cause is unclear. You could try logrus v1.4.2 to see if the problem persist.

[markphelps]

Should be fixed by #1131

[dgsb]

@andytsnowden can you confirm the issue is fixed with the latest version v1.6.0 ?

[andytsnowden]

@dgsb Confirmed fixed in 1.6.0 TY