debug: "Pause on breakpoint" is shown when pausing with "Pause (F6)"

[polinasok]

What version of Go, VS Code & VS Code Go extension are you using?

• Run go version to get version of Go
  • go version go1.14.1 darwin/amd64
• Run code -v or code-insiders -v to get version of VS Code or VS Code Insiders
  • Version: 1.43.2
• Check your installed extensions to get the version of the VS Code Go extension
  • 0.13.1
• Run go env GOOS GOARCH to get the operating system and processor architecture details
  • darwin
  • amd64

Describe the bug

When pausing the program with no breakpoints set with Pause F6, I see the UI say "paused on breakpoint" some of the times. I expect to see "paused on pause".

Steps to reproduce the behavior:

1. Use a simple program like this:

func main() {
	time.Sleep(10 * time.Second)
}

2. Set no breakpoints.
3. Launch with stop-on-entry enabled.
4. Once the program stops on entry, hit Continue (F5), then click Pause (F6).
5. The Call Stack will show the first thread as "paused on breakpoint" or "paused on pause", depending on the internal timing, so you might have to try this more than once to observe the behavior.

Screenshots or recordings

This is what I am observing:

This is what expect:

Looking in the log I see the following:

[19:14:54.848 UTC] ContinueRequest
[19:14:54.850 UTC] ContinueResponse
[19:14:55.487 UTC] PauseRequest
[19:14:55.488 UTC] PauseResponse
[19:14:55.512 UTC] pause state {"Running":false,"currentThread":{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},"Threads":[{"id":15757817,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757818,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757819,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757816,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}
[19:14:55.512 UTC] continue state {"Running":false,"currentThread":{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},"Threads":[{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757816,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757817,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757818,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757819,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}
[19:14:55.570 UTC] StoppedEvent("pause")
[19:14:55.575 UTC] ThreadsRequest
[19:14:55.591 UTC] StoppedEvent("breakpoint")
[19:14:55.609 UTC] ThreadsResponse [{"id":1,"name":"time.Sleep"},{"id":2,"name":"runtime.gopark"},{"id":3,"name":"runtime.gopark"},{"id":4,"name":"runtime.gopark"},{"id":17,"name":"runtime.gopark"}]
[19:14:55.797 UTC] ThreadsRequest
[19:14:55.797 UTC] ThreadsRequest
[19:14:55.798 UTC] StackTraceRequest
[19:14:55.822 UTC] ThreadsResponse [{"id":1,"name":"time.Sleep"},{"id":2,"name":"runtime.gopark"},{"id":3,"name":"runtime.gopark"},{"id":4,"name":"runtime.gopark"},{"id":17,"name":"runtime.gopark"}]
[19:14:55.829 UTC] StackTraceRequest
[19:14:55.853 UTC] ThreadsResponse [{"id":1,"name":"time.Sleep"},{"id":2,"name":"runtime.gopark"},{"id":3,"name":"runtime.gopark"},{"id":4,"name":"runtime.gopark"},{"id":17,"name":"runtime.gopark"}]
[19:14:55.950 UTC] StackTraceResponse
[19:14:56.142 UTC] StackTraceResponse
[19:14:58.742 UTC] ScopesRequest
[19:14:58.790 UTC] ScopesResponse
[19:15:02.365 UTC] ScopesRequest
[19:15:02.442 UTC] ScopesResponse
[19:39:03.982 UTC] VariablesRequest
[19:39:03.986 UTC] VariablesResponse [
[19:39:03.991 UTC] VariablesRequest
[19:39:03.991 UTC] VariablesResponse [

When continue request is served, an async continue rpc is issued:

2020-04-07T12:14:54-07:00 debug layer=rpc (async 6) <- RPCServer.Command(api.DebuggerCommand{"name":"continue","ReturnInfoLoadConfig":null})
When pause request is served, an async halt rpc is issued:
2020-04-07T12:14:55-07:00 debug layer=rpc (async 7) <- RPCServer.Command(api.DebuggerCommand{"name":"halt","ReturnInfoLoadConfig":null})

When halt returns, so does continue.

2020-04-07T12:14:55-07:00 debug layer=rpc (async 6) -> rpc2.CommandOut{"State":{"Running":false,"currentThread":{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},"Threads":[{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757816,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757817,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757818,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757819,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}} error: ""
2020-04-07T12:14:55-07:00 debug layer=rpc (async 7) -> rpc2.CommandOut{"State":{"Running":false,"currentThread":{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},"Threads":[{"id":15757817,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757818,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757819,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757816,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}} error: ""

Both Pause and Continue callbacks get called - see "pause state" and "continue state" logging lines above.

[19:14:55.512 UTC] pause state {"Running":false,"currentThread":{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},"Threads":[{"id":15757817,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757818,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757819,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757816,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}
[19:14:55.512 UTC] continue state {"Running":false,"currentThread":{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},"Threads":[{"id":15757782,"pc":140735314958218,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757816,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757817,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757818,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null},{"id":15757819,"pc":140735314946150,"file":"","line":0,"goroutineID":0,"ReturnValues":null}],"NextInProgress":false,"exited":false,"exitStatus":0,"When":""}

Each of those callbacks calls handleReenterDebug, pauseRequest - with "pause" reason and continue one with "breakpoint" reason. These two callbacks compete to issue stopped events. Whoever gets to send a stopped event last, is the one that gets displayed in the UI. Then in response to both events and some thread events as well (which will now be removed with #3145), a number of duplicate threads, stacktrace, etc, requests is called, all returning the same results. All of this activity for just one pause.

[polinasok]

For background, the handling for pause requests was introduced in #2126.

[hyangah]

@polinasok Thanks for the detailed report! Let's follow up in golang/vscode-go#172 as we are moving.