Debugging : Failure in getting CheckedEntry from the core pool

[abhinavsingh-swiggy]

Hello,

One of our logging attempts failed to get a CheckedEntry from the Pool.
Here's the panic logs:

panic(0x106c040, 0xc00388a540)
2022-07-31 11:02:23	
	/usr/local/go/src/runtime/panic.go:969 +0x166 fp=0xc002691398 sp=0xc0026912e0 pc=0x436606
2022-07-31 11:02:23	
runtime.panicdottypeE(0xc000a5eb60, 0x10a6980, 0x10254c0)
2022-07-31 11:02:23	
	/usr/local/go/src/runtime/iface.go:260 +0xb2 fp=0xc0026913b8 sp=0xc002691398 pc=0x40be82
2022-07-31 11:02:23	
go.uber.org/zap/zapcore.getCheckedEntry(0xc00018f9f8)
2022-07-31 11:02:23	
	/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:46 +0x7f fp=0xc0026913e8 sp=0xc0026913b8 pc=0x88943f
2022-07-31 11:02:23	
go.uber.org/zap/zapcore.(*CheckedEntry).AddCore(...)
2022-07-31 11:02:23	
	/go/pkg/mod/go.uber.org/[email protected]/zapcore/entry.go:247
2022-07-31 11:02:23	
go.uber.org/zap/zapcore.(*ioCore).Check(0xc000325bf0, 0x0, 0xc0b1a2d9d156533c, 0x1bf3358d6008b, 0x1ca6920, 0x0, 0x0, 0x11cdca3, 0x19, 0x0, ...)
2022-07-31 11:02:23	
	/go/pkg/mod/go.uber.org/[email protected]/zapcore/core.go:80 +0x18f fp=0xc0026914d0 sp=0xc0026913e8 pc=0x887a3f
2022-07-31 11:02:23	
go.uber.org/zap.(*Logger).check(0xc00090b0e0, 0x100, 0x11cdca3, 0x19, 0xc002fc4000)
2022-07-31 11:02:23	
	/go/pkg/mod/go.uber.org/[email protected]/logger.go:277 +0x16a fp=0xc002691918 sp=0xc0026914d0 pc=0x8a40ba

We later recover() this panic and try to log it, but that threw another panic.
We get a zap.Field using:

v := v.(type)
if e, ok := v.(error); ok {
	return zap.String("Error", e.Error())
}

and then log it using https://github.com/uber-go/zap/blob/master/logger.go#L227
Here's the panic logs:

2022-07-31 11:02:23	
runtime: nameOff 0x5 base 0xc000a5eb60 not in ranges:
2022-07-31 11:02:23	
	types 0xf37000 etypes 0x14f2fb5
2022-07-31 11:02:23	
fatal error: runtime: name offset base pointer out of range
2022-07-31 11:02:23	

2022-07-31 11:02:23	
goroutine 156981135 [running]:
2022-07-31 11:02:23	
runtime.throw(0x11e98c2, 0x2e)
2022-07-31 11:02:23	
	/usr/local/go/src/runtime/panic.go:1116 +0x72 fp=0xc002690c48 sp=0xc002690c18 pc=0x436cf2
2022-07-31 11:02:23	
runtime.resolveNameOff(0xc000a5eb60, 0x5, 0x15)
2022-07-31 11:02:23	
	/usr/local/go/src/runtime/type.go:210 +0x23e fp=0xc002690cb0 sp=0xc002690c48 pc=0x460a9e
2022-07-31 11:02:23	
runtime.(*_type).nameOff(...)
2022-07-31 11:02:23	
	/usr/local/go/src/runtime/type.go:216
2022-07-31 11:02:23	
runtime.(*_type).string(0xc000a5eb60, 0xf69dab, 0x15)
2022-07-31 11:02:23	
	/usr/local/go/src/runtime/type.go:51 +0x36 fp=0xc002690cd8 sp=0xc002690cb0 pc=0x460616
2022-07-31 11:02:23	
runtime.(*TypeAssertionError).Error(0xc00388a540, 0x106c040, 0xc00388a540)
2022-07-31 11:02:23	
	/usr/local/go/src/runtime/error.go:39 +0xa1 fp=0xc002690df0 sp=0xc002690cd8 pc=0x409531

I searched the Discussions for this issue, but could not find anything on this.
The Pool's Get method mentions that: If Get would otherwise return nil and p.New is non-nil, Get returns the result of calling p.New., how the first panic was because the returned values was tried to be converted to CheckedEntry but failed due to TypeAssertionError? What to look for in debugging this further, please help.

The zap version is: v1.16.0
The Go version is: 1.14

[sywhang]

Hey @abhinavsingh-swiggy,

Just from reading the logs it's a bit difficult to move forward. The only info we can get is what you already concluded - the returned value from Pool.New wasn't able to be converted into a CheckedEntry but that sounds pretty strange since this is what we do when Get returns nil:

        _cePool = sync.Pool{New: func() interface{} {
                // Pre-allocate some space for cores.
                return &CheckedEntry{
                        cores: make([]Core, 4),
                }
        }}

Do you have a repro for this? I can help debug the issue if you have a small repro for this issue.

[abhinavsingh-swiggy]

@sywhang
Yes, p.New is called when Get is trying to return nil, but is it possible that the x returned in the Get method can be of a different type?
I am actually not sure how to reproduce this:
Should I make the system replicate the conditions of the system when this panic suddenly had occurred: I will look into this further if the system was in an unusual state, although it doesn't look like it.
Or Could it depend on what was tried being logged: Don't think this either, and anyway, nothing tried being logged than the usual.

I will look into how this can be reproduced. But we have seen this happen 3 times in the last 3 weeks.