x/playground,internal/poll: timeout or long run time when using httptest.NewServer

[rogpeppe]

What version of Go are you using (go version)?

go1.20 as reported by the playground.

Does this issue reproduce with the latest release?

Yes

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

N/A

What did you do?

https://go.dev/play/p/Pc_vys_LNVG

What did you expect to see?

It should run and terminate very quickly.

What did you see instead?

0s request send
2009/11/10 23:00:30 Do: Post "http://127.0.0.1:16324": dial tcp 127.0.0.1:16324: i/o timeout

The same code (or very similar, modulo playground result caching) sometimes terminates immediately,
and sometimes prints:

0s request send
30s request sent

When instrumented to print the goroutine stack traces on timeout, we see this set of stacks:

goroutine profile: total 5
1 @ 0x42dcf6 0x461105 0x661dd5 0x661bed 0x65e96b 0x66b6ae 0x466bc1
#	0x461104	runtime/pprof.runtime_goroutineProfileWithLabels+0x24	/usr/local/go-faketime/src/runtime/mprof.go:844
#	0x661dd4	runtime/pprof.writeRuntimeProfile+0xb4			/usr/local/go-faketime/src/runtime/pprof/pprof.go:734
#	0x661bec	runtime/pprof.writeGoroutine+0x4c			/usr/local/go-faketime/src/runtime/pprof/pprof.go:694
#	0x65e96a	runtime/pprof.(*Profile).WriteTo+0x14a			/usr/local/go-faketime/src/runtime/pprof/pprof.go:329
#	0x66b6ad	main.main.func1+0x4d					/tmp/sandbox3803422248/prog.go:15

1 @ 0x438776 0x4311d7 0x461529 0x4a9352 0x4aab3d 0x4aab2b 0x557315 0x568685 0x5678dd 0x636245 0x65b26a 0x466bc1
#	0x461528	internal/poll.runtime_pollWait+0x88		/usr/local/go-faketime/src/runtime/netpoll.go:306
#	0x4a9351	internal/poll.(*pollDesc).wait+0x31		/usr/local/go-faketime/src/internal/poll/fd_poll_runtime.go:84
#	0x4aab3c	internal/poll.(*pollDesc).waitRead+0x2bc	/usr/local/go-faketime/src/internal/poll/fd_poll_runtime.go:89
#	0x4aab2a	internal/poll.(*FD).Accept+0x2aa		/usr/local/go-faketime/src/internal/poll/fd_unix.go:614
#	0x557314	net.(*netFD).accept+0x34			/usr/local/go-faketime/src/net/fd_unix.go:172
#	0x568684	net.(*TCPListener).accept+0x24			/usr/local/go-faketime/src/net/tcpsock_posix.go:148
#	0x5678dc	net.(*TCPListener).Accept+0x3c			/usr/local/go-faketime/src/net/tcpsock.go:297
#	0x636244	net/http.(*Server).Serve+0x384			/usr/local/go-faketime/src/net/http/server.go:3059
#	0x65b269	net/http/httptest.(*Server).goServe.func1+0x69	/usr/local/go-faketime/src/net/http/httptest/server.go:310

1 @ 0x438776 0x4311d7 0x461529 0x4a9352 0x556bb9 0x556b9d 0x556bc1 0x5658e5 0x565412 0x55e718 0x5681ef 0x568089 0x54e6f2 0x54e045 0x54d6b3 0x54d0cc 0x643ea7 0x646dac 0x6457f0 0x466bc1
#	0x461528	internal/poll.runtime_pollWait+0x88		/usr/local/go-faketime/src/runtime/netpoll.go:306
#	0x4a9351	internal/poll.(*pollDesc).wait+0x31		/usr/local/go-faketime/src/internal/poll/fd_poll_runtime.go:84
#	0x556bb8	internal/poll.(*pollDesc).waitWrite+0x798	/usr/local/go-faketime/src/internal/poll/fd_poll_runtime.go:93
#	0x556b9c	internal/poll.(*FD).WaitWrite+0x77c		/usr/local/go-faketime/src/internal/poll/fd_unix.go:741
#	0x556bc0	net.(*netFD).connect+0x7a0			/usr/local/go-faketime/src/net/fd_unix.go:141
#	0x5658e4	net.(*netFD).dial+0x3c4				/usr/local/go-faketime/src/net/sock_posix.go:151
#	0x565411	net.socket+0x2d1				/usr/local/go-faketime/src/net/sock_posix.go:70
#	0x55e717	net.internetSocket+0xf7				/usr/local/go-faketime/src/net/ipsock_posix.go:142
#	0x5681ee	net.(*sysDialer).doDialTCP+0xee			/usr/local/go-faketime/src/net/tcpsock_posix.go:74
#	0x568088	net.(*sysDialer).dialTCP+0x68			/usr/local/go-faketime/src/net/tcpsock_posix.go:64
#	0x54e6f1	net.(*sysDialer).dialSingle+0x1f1		/usr/local/go-faketime/src/net/dial.go:580
#	0x54e044	net.(*sysDialer).dialSerial+0x244		/usr/local/go-faketime/src/net/dial.go:548
#	0x54d6b2	net.(*sysDialer).dialParallel+0x412		/usr/local/go-faketime/src/net/dial.go:449
#	0x54d0cb	net.(*Dialer).DialContext+0x70b			/usr/local/go-faketime/src/net/dial.go:440
#	0x643ea6	net/http.(*Transport).dial+0xe6			/usr/local/go-faketime/src/net/http/transport.go:1176
#	0x646dab	net/http.(*Transport).dialConn+0x82b		/usr/local/go-faketime/src/net/http/transport.go:1614
#	0x6457ef	net/http.(*Transport).dialConnFor+0xaf		/usr/local/go-faketime/src/net/http/transport.go:1456

1 @ 0x438776 0x447ebe 0x5570a6 0x466bc1
#	0x5570a5	net.(*netFD).connect.func2+0x85	/usr/local/go-faketime/src/net/fd_unix.go:118

1 @ 0x438776 0x447ebe 0x644b66 0x640c7e 0x62b299 0x5f49b7 0x5f423b 0x5f645b 0x66b5ae 0x66b59d 0x438338 0x466bc1
#	0x644b65	net/http.(*Transport).getConn+0x5c5	/usr/local/go-faketime/src/net/http/transport.go:1382
#	0x640c7d	net/http.(*Transport).roundTrip+0x79d	/usr/local/go-faketime/src/net/http/transport.go:590
#	0x62b298	net/http.(*Transport).RoundTrip+0x18	/usr/local/go-faketime/src/net/http/roundtrip.go:17
#	0x5f49b6	net/http.send+0x5f6			/usr/local/go-faketime/src/net/http/client.go:252
#	0x5f423a	net/http.(*Client).send+0x9a		/usr/local/go-faketime/src/net/http/client.go:176
#	0x5f645a	net/http.(*Client).do+0x8fa		/usr/local/go-faketime/src/net/http/client.go:716
#	0x66b5ad	net/http.(*Client).Do+0xed		/usr/local/go-faketime/src/net/http/client.go:582
#	0x66b59c	main.main+0xdc				/tmp/sandbox3803422248/prog.go:23
#	0x438337	runtime.main+0x1f7			/usr/local/go-faketime/src/runtime/proc.go:250

The program to produce that output is here: https://go.dev/play/p/7t5iObMhESj

Note the sleep just before the request sent is printed. Without that, the goroutine stack trace is aborted half way: it seems that the fact that the goroutine woke up triggered the runtime to run the other goroutines which should have been running anyway.

[bcmills]

This is definitely related to the faketime patch — it reproduces locally using go run -tags faketime all the way back to go1.14, which was the first release with a platform-independent faketime implementation (https://go.dev/cl/192740).

[gopherbot]

Change https://go.dev/cl/497618 mentions this issue: runtime/testdata/unfaketime: add a filtering binary for faketime output

[gopherbot]

Change https://go.dev/cl/497619 mentions this issue: cmd/go: add a regression test for #60356

[bcmills]

I couldn't help but investigate a bit, and got as far as writing a proof-of-concept regression test. 😅

I don't plan to work on this further, but if someone wants to take it from here they're welcome to build on my WIP CLs.

[bcmills]

(@ianlancetaylor, this seems to be an interaction between the runtime and poller when built with -tags=faketime.)

[ianlancetaylor]

If I build the test case with -tags faketime,netgo it seems to work fine. So I'm not sure it's the poller as such; I think it's cgo.

I don't understand this line in checkdead:

	if !iscgo && cgoHasExtraM && extraMLength.Load() > 0 {

Why is it testing !iscgo? Why shouldn't we instead write,

	run := mcount() - sched.nmidle - sched.nmidlelocked - sched.nmsys - int32(extraMLength.Load())
	if run > 0 {
		return
	}

That is, account for all of extraMLength rather than just treating it as a value of 1 only if !iscgo. There might be some race conditions, but all the tests pass with that change.

CC @golang/runtime

[prattmic]

We can't simply write that because then this program fails checkdead and claims to be deadlocked:

// Copyright 2015 The Go Authors. All rights reserved.
// Use of this source code is governed by a BSD-style
// license that can be found in the LICENSE file.

//go:build !plan9 && !windows
// +build !plan9,!windows

package main

/*
#include <unistd.h>
#include <pthread.h>

void go_callback();

static void *thr(void *arg) {
    sleep(1);
    go_callback();
    return 0;
}

static void foo() {
    pthread_t th;
    pthread_attr_t attr;
    pthread_attr_init(&attr);
    pthread_attr_setstacksize(&attr, 256 << 10);
    pthread_create(&th, &attr, thr, 0);
    //pthread_join(th, 0);
}
*/
import "C"

import (
        "os"
)

//export go_callback
func go_callback() {
        os.Exit(0)
}

func main() {
        C.foo()
        select {}
}

That is, we use extraMLength > 0 as an indication that we might get a callback from C, though admittedly this might not be the best way to represent this.

I haven't actually looked at the faketime issue yet, that's next.