sometime caller is nil

[HarryWang29]

I found panic, but I don't know why:

github.com/CardInfoLink/angrycard/internal/log.(*Formatter).Format(0xc4201bf7b8, 0xc420da44e0, 0xc4200740f0, 0x4, 0xc420da44e0, 0xc42041db68, 0x102afae)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/internal/log/log.go:96 +0x27d
github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus.(*Entry).write(0xc420da44e0)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus/entry.go:243 +0x93
github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus.Entry.log(0xc4200740c0, 0xc420238210, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus/entry.go:219 +0x173
github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus.(*Entry).Log(0xc420d5c060, 0xc400000004, 0xc42041dc98, 0x1, 0x1)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus/entry.go:256 +0xc6
github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus.(*Entry).Logf(0xc420d5c060, 0xc400000004, 0x19c62d6, 0x1c, 0xc42041de10, 0x1, 0x1)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus/entry.go:301 +0xe9
github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus.(*Logger).Logf(0xc4200740c0, 0x4, 0x19c62d6, 0x1c, 0xc42041de10, 0x1, 0x1)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus/logger.go:137 +0xa8
github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus.(*Logger).Infof(0xc4200740c0, 0x19c62d6, 0x1c, 0xc42041de10, 0x1, 0x1)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus/logger.go:151 +0x65
github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus.Infof(0x19c62d6, 0x1c, 0xc42041de10, 0x1, 0x1)
	/Users/harry/app/go/src/github.com/CardInfoLink/angrycard/vendor/github.com/sirupsen/logrus/exported.go:148 +0x5f

I write my own Formatter, and rewrite Format. But sometime caller will be nil
My Format is like this:

func (f *Formatter) Format(entry *logrus.Entry) ([]byte, error) {
	fmt.Printf("%+v\n", entry)  //this is for test
	levelText := strings.ToUpper(entry.Level.String())[0:4]
	buf := bytes.NewBuffer(make([]byte, 0, 32))
	if (f.forceColors || isTerminal) && runtime.GOOS != "windows" {
		color := colorNoColor
		switch entry.Level {
		case logrus.DebugLevel:
			color = colorCyan
		case logrus.InfoLevel:
			color = colorGreen
		case logrus.WarnLevel:
			color = colorYellow
		case logrus.ErrorLevel:
			color = colorMagenta
		case logrus.PanicLevel, logrus.FatalLevel:
			color = colorRed
		}
		buf.WriteString(color)
	}
	//time
	buf.WriteString("[")
	buf.WriteString(entry.Time.Format(timeFormat))
	buf.WriteString("] ")

	//level
	buf.WriteString("[")
	buf.WriteString(levelText)
	buf.WriteString("] ")

	//func
	buf.WriteString("[func=")
	buf.WriteString(getLastN(entry.Caller.Function, 1))
	buf.WriteString("] ")

	//file
	buf.WriteString("[source=")
	buf.WriteString(getLastN(entry.Caller.File, 2))
	buf.WriteString(":")
	buf.WriteString(strconv.Itoa(entry.Caller.Line))
	buf.WriteString("] ")

	//goroutineID  
	if f.isShowID {
		buf.WriteString("[")
		buf.WriteString(strconv.FormatInt(tls.ID(), 10))
		buf.WriteString("] ")
	}

	//message
	buf.WriteString(entry.Message)
	if (f.forceColors || isTerminal) && runtime.GOOS != "windows" {
		buf.WriteString(colorNoColor)
	}
	buf.WriteString("\n")
	return buf.Bytes(), nil
}

When I do go run, console will print these message:

&{Logger:0xc4200740c0 Data:map[] Time:2019-02-11 14:15:03.854001 +0800 CST Level:debug Caller:0xc4203be780 Message:ClientID is the default of 'sarama', you should consider setting it to something application-specific. Buffer: err:}
&{Logger:0xc4200740c0 Data:map[] Time:2019-02-11 14:15:03.866369 +0800 CST Level:debug Caller:0xc4203be980 Message:xxxxxxxx
 Buffer: err:}
&{Logger:0xc4200740c0 Data:map[] Time:2019-02-11 14:15:03.875587 +0800 CST Level:debug Caller:0xc420d61040 Message:xxxxxxxxxx
 Buffer: err:}
&{Logger:0xc4200740c0 Data:map[] Time:2019-02-11 14:15:03.891444 +0800 CST Level:debug Caller:0xc420d61240 Message:xxxxxxxxxxxxx
 Buffer: err:}
&{Logger:0xc4200740c0 Data:map[] Time:2019-02-11 14:15:03.891491 +0800 CST Level:info Caller:<nil> Message:xxxxxxxxxx Buffer: err:}

then it panic.

I will use entry.HasCaller() to check entry, but why it is nil

---

I do another shot.
I do not use Formatter of mine. I do not call logrus.SetFormatter.

It play very good.
There are func and file in log file.

---

Now I think there is something wrong in my code, but I don't know where and why.

Sorry that my English is not good, I hope I make oneself clear.
Help~~~
If I miss something, please let me know

[dgsb]

wouldn't be your getLastN function which somehow returns nil ?

[HarryWang29]

it don't enter getLastN func. There is the code:

func getLastN(base string, m int) string {
	n := 0
	for i := len(base) - 1; i > 0; i-- {
		if base[i] == '/' {
			n += 1
			if n >= m {
				base = base[i+1:]
				break
			}
		}
	}
	return base
}

There is the location of nil.

[dgsb]

Can you provide a code sample in a pr, gist or your own repository with an associated test which exhibits the issue ?
Because it's quite hard to guess what's going on here.

[HarryWang29]

hi, I did some more tests recently.
I found when I use tls.ID(), sometime caller will be nil.
I create a gist of test

[dgsb]

Hello @harry890829, go routine id is something which is not officially supported by the language even if they are various implementations out there.
I suspect tls package is somehow messing up with the program or stack which raises the problem you're (and I've also reproduced it).
I've opened a ticket at the go-tls repository for them to investigate the problem.

[huandu]

@harry890829 I cannot reproduce the panic on my machine with your gist.

go version go1.12.1 darwin/amd64

Can you please update your dependency package github.com/huandu/go-tls to the latest version and try again?

[dgsb]

@huandu to reproduce the issue you need to change the activation flag in the formatter to true at line 67
The issue is then quite immediate.

[huandu]

@dgsb I did change the flag. What's your go version?

[huandu]

@dgsb OK. I just understand what's the "activation flag" correctly. It's the f := &Formatter{true}. I can reproduce it. I'll take a look at it.

[huandu]

If tls is enabled on a goroutine, the hack in tls will make the most bottom call stack frame invisible. It's by-design, but of coz annoying. I'll try to figure out whether there is any way to fix it.

For more details, see func gentraceback in src/runtime/traceback.go inside go source files.

func gentraceback(pc0, sp0, lr0 uintptr, gp *g, skip int, pcbuf *uintptr, max int, callback func(*stkframe, unsafe.Pointer) bool, v unsafe.Pointer, flags uint) int {
    // ...

    for n < max {
        f = frame.fn
        if f.pcsp == 0 { // Package `tls` set `f.pcsp` of the hacked `goexit` to 0.
            // The most bottom call stack frame is skipped by this break.
            break
        }

        // ...
    }

    // ...
}

[HarryWang29]

@dgsb @huandu thank you all.
Because I just need goroutineID to track log, I change tls to gls. It works well.

Thanks again

[huandu]

@harry890829 That's OK. Package gls is another relatively safe approach to get goid.

[dgsb]

@harry890829 can we close this issue then ?

[HarryWang29]

@dgsb yes, thanks