Govips panics on shutdown

[tonimelisma]

There's a randomly appearing bug where Govips appears to try to call a Go callback on shutdown() even after the Go runtime has already exited. I've also reported it to the golang tracker and it seems it might be a bug in the macOS implementation of go:

golang/go#42465

It's annoying and unprofessional, to get a stack trace when your program exits. None the less it's not strictly breaking anything.

Is there anything we might do in Govips to prevent this behaviour? Are there any callbacks registered to be run on exit? It's causing our CI tests to fail for macOS at the moment for both macOS versions:

https://github.com/davidbyttow/govips/runs/1565811797

https://github.com/davidbyttow/govips/runs/1565999906

1727

1728
goroutine 1 [running, locked to thread]:
1729
runtime.throw(0x42d46ca, 0x2d)
1730
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/panic.go:1116 +0x72 fp=0xc000105da0 sp=0xc000105d70 pc=0x403b212
1731
runtime.exitsyscall()
1732
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/proc.go:3239 +0x22c fp=0xc000105dd0 sp=0xc000105da0 pc=0x406d94c
1733
runtime.cgocallbackg(0x0)
1734
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/cgocall.go:202 +0xa5 fp=0xc000105e38 sp=0xc000105dd0 pc=0x4008185
1735
runtime.cgocallback_gofunc(0x405a74c, 0x40738e0, 0xc000105eb8, 0x43138b0)
1736
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/asm_amd64.s:794 +0x9b fp=0xc000105e58 sp=0xc000105e38 pc=0x4071ffb
1737
runtime.asmcgocall(0x40738e0, 0xc000105eb8)
1738
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/asm_amd64.s:641 +0x42 fp=0xc000105e60 sp=0xc000105e58 pc=0x4071e82
1739
runtime.libcCall(0x40738e0, 0xc000105eb8, 0x431dcc0)
1740
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/sys_darwin.go:46 +0x6c fp=0xc000105e90 sp=0xc000105e60 pc=0x405a74c
1741
runtime.exit(0x0)
1742
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/sys_darwin.go:256 +0x31 fp=0xc000105eb8 sp=0xc000105e90 pc=0x406f1d1
1743
syscall.Exit(0x0)
1744
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/runtime.go:64 +0x1b fp=0xc000105ed0 sp=0xc000105eb8 pc=0x406dd1b
1745
os.Exit(0x0)
1746
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/os/proc.go:67 +0x30 fp=0xc000105ee8 sp=0xc000105ed0 pc=0x409bfd0
1747
main.main()
1748
	_testmain.go:339 +0x1d3 fp=0xc000105f88 sp=0xc000105ee8 pc=0x4249213
1749
runtime.main()
1750
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/proc.go:204 +0x209 fp=0xc000105fe0 sp=0xc000105f88 pc=0x403da89
1751
runtime.goexit()
1752
	/Users/runner/hostedtoolcache/go/1.15.6/x64/src/runtime/asm_amd64.s:1374 +0x1 fp=0xc000105fe8 sp=0xc000105fe0 pc=0x4072281
1753

1754
goroutine 31 [select]:
1755
github.com/davidbyttow/govips/v2/vips.collectStats.func1(0xc000016e28, 0xc0000205a0)
1756
	/Users/runner/work/govips/govips/vips/stats.go:28 +0xd9
1757
created by github.com/davidbyttow/govips/v2/vips.collectStats
1758
	/Users/runner/work/govips/govips/vips/stats.go:26 +0xbd
1759

[tonimelisma]

@davidbyttow any thoughts? Any callbacks at exit related to the stats collection perhaps?

[davidbyttow]

Oh interesting. Well, stat collector shouldn't be started unless it is specified to be. But, that may be a red herring because there are no callbacks there. This seems possibly like vips itself is calling into something on shutdown? In any case, I haven't looked too closely, but need to spend some time on this in the next day or two to understand/debug.

[tonimelisma]

I tried scanning the Libvips sources and for sure there's an atexit() routine there but it's just C stuff to clean up the cache etc. According to the stack trace it's trying to call Go code after exit, so it's not Libvips, it needs to be something in Govips.

[davidbyttow]

Well, are we sure? Couldn't it just be the logging handler? If libvips is logging something after Go has shutdown due to atexit, that would cause the bad stackframe error, no?

[tonimelisma]

You're a genius @davidbyttow. That must be it. I'll try a patch as soon as I have 15min.

[davidbyttow]

The fix wasn't immediately obvious to me, but I was able to reproduce locally and so here's a fix: https://github.com/davidbyttow/govips/compare/fix-%23144?expand=1

[tonimelisma]

Fixed with latest commit. Upstream will also fix Go runtime bug in Go 1.16