Redirect of panic (via unix.Dup2) is not working reliably

[powellnorma]

Go version

go version go1.21.4 linux/amd64

What operating system and processor architecture are you using (go env)?

GO111MODULE=''
GOARCH='amd64'
GOBIN=''
GOCACHE='/home/user/.cache/go-build'
GOENV='/home/user/.config/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='amd64'
GOHOSTOS='linux'
GOINSECURE=''
GOMODCACHE='/home/user/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='linux'
GOPATH='/home/user/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/usr/local/go'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/usr/local/go/pkg/tool/linux_amd64'
GOVCS=''
GOVERSION='go1.21.4'
GCCGO='gccgo'
GOAMD64='v1'
AR='ar'
CC='gcc'
CXX='g++'
CGO_ENABLED='1'
GOMOD='/dev/null'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -m64 -pthread -Wl,--no-gc-sections -fmessage-length=0 -ffile-prefix-map=/tmp/go-build3489998959=/tmp/go-build -gno-record-gcc-switches'

What did you do?

I found a weird bug: When executing the following program on linux with both also-redirect-log (log.SetOutput) and DoT (NewDoTResolver), the panic is not logged to the file. It seems to work fine on darwin (see ncruces/go-dns#13).

main.go:

package main

import (
	"fmt"
	"log"
	"net"
	"os"

	dns "github.com/ncruces/go-dns"
	"golang.org/x/sys/unix"
)

func hasArg(val string) bool {
	for _, argI := range os.Args[1:] {
		if val == argI {
			return true
		}
	}
	return false
}

func LogStderrToFile(dstFile string) {
	f, err := os.OpenFile(dstFile, os.O_WRONLY|os.O_CREATE|os.O_TRUNC, 0666)
	if err != nil {
		log.Fatalf("OpenFile failed: %v", err)
	}

	err = unix.Dup2(int(f.Fd()), int(os.Stderr.Fd()))
	if err != nil {
		log.Fatalf("Dup2 failed: %v", err)
	}

	os.Stderr = f

	if hasArg("also-redirect-log") {
		log.SetOutput(f)
	}
}

func main() {
	path := "/tmp/test.log"
	fmt.Printf("redirect stderr to: %s\n", path)
	LogStderrToFile(path)

	if hasArg("DoT") {
		resolver, err := dns.NewDoTResolver("cloudflare-dns.com", dns.DoTAddresses("1.1.1.1", "1.0.0.1"), dns.DoTCache())
		if err != nil {
			panic(err)
		}
		net.DefaultResolver = resolver
	}

	addrs, _ := net.LookupHost("www.wikipedia.org")
	fmt.Printf("addrs: %v\n", addrs)

	panic("test")
}

What did you expect to see?

The panic should have been logged into /tmp/test.log:

$ go run main.go also-redirect-log DoT; echo --; cat /tmp/test.log 
redirect stderr to: /tmp/test.log
addrs: [2a02:ec80:300:ed1a::1 185.15.59.224]
exit status 2
--
panic: test

goroutine 1 [running]:
main.main()
	/src/main.go:56 +0x1a5

What did you see instead?

$ go run main.go also-redirect-log DoT; echo --; cat /tmp/test.log 
redirect stderr to: /tmp/test.log
addrs: [2a02:ec80:300:ed1a::1 185.15.59.224]
exit status 2
--

Other combination (either only also-redirect-log / DoT or none) work fine:

$ go run main.go; echo --; cat /tmp/test.log 
redirect stderr to: /tmp/test.log
addrs: [2a02:ec80:300:ed1a::1 185.15.59.224]
exit status 2
--
panic: test

goroutine 1 [running]:
main.main()
	/src/main.go:56 +0x1a5

$ go run main.go also-redirect-log; echo --; cat /tmp/test.log 
redirect stderr to: /tmp/test.log
addrs: [2a02:ec80:300:ed1a::1 185.15.59.224]
exit status 2
--
panic: test

goroutine 1 [running]:
main.main()
	/src/main.go:56 +0x1a5

$ go run main.go DoT; echo --; cat /tmp/test.log 
redirect stderr to: /tmp/test.log
addrs: [2a02:ec80:300:ed1a::1 185.15.59.224]
exit status 2
--
panic: test

goroutine 1 [running]:
main.main()
	/src/main.go:56 +0x1a5

[prattmic]

os.Stderr is originally an os.File that refers to FD 2. After you reassign os.Stderr, the original os.File is unreachable. I bet a GC is running, causing the finalizer to run and close FD 2.

[powellnorma]

Ah, You are right - When I assign the old os.File to a global variable this is not happening.

Hm, probably one doesn't even need to re-assign os.Stderr or use log.SetOutput - Since the underlying file descriptor already points to the file?

[prattmic]

Hm, probably one doesn't even need to re-assign os.Stderr or use log.SetOutput - Since the underlying file descriptor already points to the file?

Yes, I agree. An os.File is really just a wrapper around an FD and you aren't changing the FD, just where the OS directs writes.

[prattmic]

Also FYI: #42888 is an accepted (but not yet implemented) proposal for an explicit API to redirect crash output.