Skip to content
This repository has been archived by the owner on Jul 15, 2023. It is now read-only.

With 0.6.85, delve does not properly close or restart. 0.6.84 Works fine. #1814

Closed
antihax opened this issue Jul 29, 2018 · 41 comments
Closed
Labels

Comments

@antihax
Copy link

antihax commented Jul 29, 2018

Having issues on Ubuntu with Go extension 0.6.85 and delve debugger on multiple projects. Looks related to #438. This started after upgrading to 0.6.85 and works fine when downgrading to 0.6.84.

Issues:

  1. Have to hit stop twice to stop debugging, on occasion the process keeps running anyway but vscode says it is not.
  2. Hitting restart does nothing, process keeps running and logging to the window.
  3. If the code will not build, resolving the build then trying to launch the debugger results in an error: There is already a debug configuration "Launch" running. when there is nothing running. Have to restart vscode to fix.

launch.json

{
    "version": "0.2.0",
    "configurations": [
        {
            "name": "Launch",
            "type": "go",
            "request": "launch",
            "mode": "debug",
            "remotePath": "",
            "port": 2345,
            "host": "127.0.0.1",
            "cwd": "${workspaceRoot}",
            "program": "${workspaceRoot}/cmd/main.go",
            "args": [],
        },
    ]
}

debug.log (DisconnectRequest appears after first stop request, nothing after second)

11:52:55 AM, 7/29/2018
InitializeRequest
InitializeResponse
Using GOPATH: /home/antihax/go
Running: /home/antihax/go/bin/dlv debug github.com/antihax/eve-marketwatch/cmd --headless=true --listen=127.0.0.1:2345 --log=true --wd=/home/antihax/go/src/github.com/antihax/eve-marketwatch --
API server listening at: 127.0.0.1:2345
time="2018-07-29T11:52:56-07:00" level=info msg="launching process with args: [/home/antihax/go/src/github.com/antihax/eve-marketwatch/cmd/debug]" layer=debugger
InitializeEvent
ConfigurationDoneRequest
ContinueRequest
ContinueResponse
ThreadsRequest
time="2018-07-29T11:52:56-07:00" level=debug msg=continuing layer=debugger
DisconnectRequest

Both delve and debugged process are still running.

@antihax antihax changed the title Latest version delve does not properly close or restart. 0.6.84 Works fine. With 0.6.85, delve does not properly close or restart. 0.6.84 Works fine. Jul 29, 2018
@cpwc
Copy link

cpwc commented Jul 30, 2018

Same issue here on macOS with 0.6.85 had to downgrade to 0.6.84 for debugger work correctly.

@mmwtsn
Copy link

mmwtsn commented Jul 30, 2018

Downgrading to 0.6.84 worked for me as well.

To do that download the 0.6.84 release and run the following:

$ code --uninstall-extension ms-vscode.Go
$ code --install-extension $PATH_TO_YOUR_DOWNLOAD/Go-0.6.84.vsix

You may want to add "extensions.autoUpdate": false, to your settings for now as well.

To use the extension run Reload Window in the command pallet.

@mvrhov
Copy link

mvrhov commented Jul 31, 2018

There is probably more of them like that:

  • if the build fails you cannot start again. you get that the Debug process is already running error.
  • the restart is now sometimes so slow, that process restart manages to launch multiple instances.
  • you have to press stop button multiple times for it to register the stop or to stop debug process I dno't know which one is true

@ramya-rao-a
Copy link
Contributor

Can someone here share a small sample code where I can try and get a repro of this?

@antihax
Copy link
Author

antihax commented Aug 1, 2018

This appears to cause some of the issues mentioned above.

package main

import (
	"sync"
	"time"
)

func main() {
	wg := sync.WaitGroup{}
	wg.Add(1)
	go func() {
		for {
			time.Sleep(time.Second)
		}
	}()
	wg.Wait()
}

Side note: code listening on a tcp socket with a fixed port appears to make this worse as it is occasionally trying to launch two copies and one fails as the port is in use.

@gencer
Copy link

gencer commented Aug 1, 2018

I'm on windows and this happens.

@ramya-rao-a
Copy link
Contributor

ramya-rao-a commented Aug 1, 2018

@antihax I tried your code on Windows. On ending the debug session using the stop button, debugging stops as expected.

All,

Whats changed between 0.6.84 and 0.6.85 is the below:

  • In 0.6.84 when you stop the debugging session, we forcefully killed the debug process that was spawned for delve and all its children.
  • In 0.6.85 when you stop the debugging session, instead of the force kill, we send a detach request to delve. Delve then kills all processes. Once delve gets back to us saying that detach is complete, we (the Go extension) then request VS Code to disconnect which is when the debug tool bar goes away

From the descriptions in this issue, it looks like the detach by delve is not getting completed. I have added a few more logs to the code to confirm this. Can folks here try the below?

  • Download https://github.com/Microsoft/vscode-go/blob/master/Go-latest.vsix
  • Run code --install-extension Go-latest.vsix
  • If the above fails with Error: end of central directory record signature not found, then clone this repo and use the Go-latest.vsix file from the cloned repo
  • Reload VS Code
  • Add "trace": "verbose" to your debug configuration in the launch.json file.
  • Try to repro the issue

Look for "HaltRequest", "DetachRequest", "DetachResponse" and "DisconnectRequest to parent" in the logs and share what you find here.

@antihax
Copy link
Author

antihax commented Aug 1, 2018

With above code and Go-latest.vsix from cloned repo.
First stop press DisconnectRequest appears below. 30 seconds pass. Second press, nothing additional. Debugger controls disappear but process appears to still be running.

Verbose logs are written to:
/tmp/vscode-go-debug.txt
2:46:03 PM, 8/1/2018
InitializeRequest
InitializeResponse
Using GOPATH: /home/antihax/go
Running: /home/antihax/go/bin/dlv debug github.com/antihax/test --headless=true --listen=127.0.0.1:2345 --log=true --
API server listening at: 127.0.0.1:2345
time="2018-08-01T14:46:03-07:00" level=info msg="launching process with args: [/home/antihax/go/src/github.com/antihax/test/debug]" layer=debugger
InitializeEvent
ConfigurationDoneRequest
ContinueRequest
ContinueResponse
ThreadsRequest
time="2018-08-01T14:46:04-07:00" level=debug msg=continuing layer=debugger
DisconnectRequest

@ramya-rao-a
Copy link
Contributor

@antihax We also send a Halt request before trying to Detach for which I forgot to add logs earlier. Can you try the instructions at #1814 (comment) again?

@antihax
Copy link
Author

antihax commented Aug 1, 2018

On first stop.

DisconnectRequest
HaltRequest

On second, no change to log but the controls go away. Both debug and dlv are still running.

 98102 tty2     Sl+    0:00 /home/antihax/go/bin/dlv debug github.com/antihax/test --headless=true --listen=127.0.0.1:2345 --log=true --
 98188 tty2     Sl     0:00 /home/antihax/go/src/github.com/antihax/test/debug

@ramya-rao-a
Copy link
Contributor

This shows that the halt request is not getting completed by delve. I still cant repro this, so not sure what the next steps would be

@aarzilli any thoughts on why the Halt request made to delve would not complete and call the given callback?

@aarzilli
Copy link

aarzilli commented Aug 2, 2018

I'd like to see the output of --log --log-output=rpc.

@rain2fog
Copy link

rain2fog commented Aug 2, 2018

same problem with me
environment: ubuntu 16.04 / vscode 1.25.1 / vscode-go 0.6.85
I have to downgrade to 0.6.84, then it worked.

@ramya-rao-a
Copy link
Contributor

@antihax I've updated the Go-latest.vsix to have the ability to configure the --log-output. Can you re-do the steps from #1814 (comment), add "logOutput": "rpc" to your debug configuration in launch.json file and the share the logs so that @aarzilli can take a look?

@antihax
Copy link
Author

antihax commented Aug 2, 2018

Hitting stop; DisconnectRequest and HaltRequest appear, but no additional RPC to dlv. Hitting second time, nothing additional.

Verbose logs are written to:
/tmp/vscode-go-debug.txt
3:18:37 PM, 8/2/2018
InitializeRequest
InitializeResponse
Using GOPATH: /home/antihax/go
Running: /home/antihax/go/bin/dlv debug github.com/antihax/test --headless=true --listen=127.0.0.1:2345 --log=true --log-output=rpc --
time="2018-08-02T15:18:37-07:00" level=info msg="Using API v1" layer=rpc
API server listening at: 127.0.0.1:2345
InitializeEvent
time="2018-08-02T15:18:38-07:00" level=debug msg="<- RPCServer.GetVersion(api.GetVersionIn{})" layer=rpc
time="2018-08-02T15:18:38-07:00" level=debug msg="-> *api.GetVersionOut{\"DelveVersion\":\"Version: 1.0.0\\nBuild: $Id: c98a142125d0b17bb11ec0513bde346229b5f533 $\",\"APIVersion\":1} error: \"\"" layer=rpc
ConfigurationDoneRequest
ContinueRequest
ContinueResponse
ThreadsRequest
time="2018-08-02T15:18:38-07:00" level=debug msg="(async 2) <- RPCServer.Command(*api.DebuggerCommand{\"name\":\"continue\",\"ReturnInfoLoadConfig\":null})" layer=rpc
time="2018-08-02T15:18:38-07:00" level=debug msg="<- RPCServer.ListGoroutines(<nil>null)" layer=rpc
DisconnectRequest
HaltRequest

@ramya-rao-a
Copy link
Contributor

I am able to get logs after the HaltRequest

screen shot 2018-08-02 at 4 54 45 pm

@aarzilli I log the text HaltRequest just before sending the halt command to delve, as you can see in my screenshot above. In @antihax's case, delve doesn't return any logs after the attempt to halt. In my case, you can see the logs form delve after the attempt to halt

@antihax Do you have the latest dlv? Can you update it just to be sure? You can run Go: Install/Update Tools and select dlv to update it.

@antihax
Copy link
Author

antihax commented Aug 3, 2018

Delve Debugger
Version: 1.0.0
Build: $Id: c98a142125d0b17bb11ec0513bde346229b5f533 $

Same thing after running the update above.

@ramya-rao-a
Copy link
Contributor

ramya-rao-a commented Aug 3, 2018

@antihax And you are trying this with the sample code from #1814 (comment) correct? What's the version Go and VS Code you are using? And what OS?

@antihax
Copy link
Author

antihax commented Aug 3, 2018

I am using the code above.

go version go1.10.3 linux/amd64 on Ubuntu 18.04.1 LTS

VS Code is:

Version: 1.25.1
Commit: 1dfc5e557209371715f655691b1235b6b26a06be
Date: 2018-07-11T15:40:20.190Z
Electron: 1.7.12
Chrome: 58.0.3029.110
Node.js: 7.9.0
V8: 5.8.283.38
Architecture: x64

@ramya-rao-a
Copy link
Contributor

ramya-rao-a commented Aug 3, 2018

@antihax I am able to repro your case if there are no breakpoints in the file. Can you try adding a breakpoint and then see if you are able to stop the debugging session properly?

@aarzilli
Copy link

aarzilli commented Aug 3, 2018

In @antihax logs I see that VSCode is sending a ListGoroutines request right after the continue command, that request is synchronous and can't be executed until continue terminates and will also block any other command from going through (including halt commands).

@Tusharsb
Copy link

Tusharsb commented Aug 3, 2018

@ramya-rao-a

Can you try adding a breakpoint and then see if you are able to stop the debugging session properly?

I am able to reproduce the issue even with breakpoints ON. I am using a different code as follows

package main

import (
	"fmt"
	"log"
	"net/http"

	"github.com/gorilla/mux"
)

// our main function
func main() {
	router := mux.NewRouter()
	router.HandleFunc("/", IncomingMessage).Methods("POST")
	log.Fatal(http.ListenAndServe(":8002", router))
}

func IncomingMessage(w http.ResponseWriter, r *http.Request) {
	fmt.Println("hello world")
}

with breakpoint set on second last line

go version go1.10.3 linux/amd64

@imkos
Copy link

imkos commented Aug 4, 2018

reproduce the issue:

  1. to start debugging on no "main" package, This will certainly fail to start.
  2. After to start debugging "main" package, There is already a debug configuration "Launch" running.

@moitias
Copy link

moitias commented Aug 4, 2018

Seeing this on Windows too, and it seems to be related to how build failures are handled at least on my configuration. The basic steps to reproduce are:

  1. (optional) Run code succesfully, debug succesfully
  2. Try to run unbuildable code
  3. Expect to be able to run/debug again.

Tested on the latest release Code and the go-latest.vsix (commit b4c4698) from the repo - doesn't work - and with 0.6.84 linked above - works fine.

Logs from both a succesful run and the logs after running unbuildable code from both versions below. No RPC logging on the 0.6.84 as the launch configuration flag doesn't work in the older plugin.

Code to run:

package main

import (
	"fmt"
)

func main() {
	fmt.Println("HELLO")
	// uncomment this line and f5 to break debugging
}

Runs and debugs fine, repeatedly. Logs on a succesful session are as follows:

Verbose logs are written to:
C:\Users\matias\AppData\Local\Temp\vscode-go-debug.txt
19:40:30, 2018-8-4
InitializeRequest
InitializeResponse
Using GOPATH: c:\users\matias\code\worldo
Running: c:\users\matias\code\worldo\bin\dlv.exe debug cmd\test --headless=true --listen=127.0.0.1:2345 --log=true --log-output=rpc --
time="2018-08-04T19:40:31+03:00" level=info msg="Using API v1" layer=rpc
API server listening at: 127.0.0.1:2345
InitializeEvent
ConfigurationDoneRequest
ContinueRequest
ContinueResponse
ThreadsRequest
time="2018-08-04T19:40:31+03:00" level=debug msg="<- RPCServer.GetVersion(api.GetVersionIn{})" layer=rpc
time="2018-08-04T19:40:31+03:00" level=debug msg="-> *api.GetVersionOut{\"DelveVersion\":\"Version: 1.0.0\\nBuild: $Id: c98a142125d0b17bb11ec0513bde346229b5f533 $\",\"APIVersion\":1} error: \"\"" layer=rpc
time="2018-08-04T19:40:31+03:00" level=debug msg="(async 2) <- RPCServer.Command(*api.DebuggerCommand{\"name\":\"continue\",\"ReturnInfoLoadConfig\":null})" layer=rpc
time="2018-08-04T19:40:31+03:00" level=debug msg="<- RPCServer.ListGoroutines(<nil>null)" layer=rpc
time="2018-08-04T19:40:31+03:00" level=debug msg="-> *[]*api.Goroutine[] error: \"\"" layer=rpc
HELLO
time="2018-08-04T19:40:31+03:00" level=debug msg="(async 2) -> *api.DebuggerState{\"Running\":false,\"Threads\":null,\"NextInProgress\":false,\"exited\":true,\"exitStatus\":0,\"When\":\"\"} error: \"\"" layer=rpc
continue state {"Running":false,"Threads":null,"NextInProgress":false,"exited":true,"exitStatus":0,"When":""}
TerminatedEvent
DisconnectRequest
HaltRequest
time="2018-08-04T19:40:31+03:00" level=debug msg="(async 4) <- RPCServer.Command(*api.DebuggerCommand{\"name\":\"halt\",\"ReturnInfoLoadConfig\":null})" layer=rpc
time="2018-08-04T19:40:31+03:00" level=debug msg="(async 4) -> *api.DebuggerStatenull error: \"Process 27040 has exited with status 0\"" layer=rpc
HaltResponse
DetachRequest
time="2018-08-04T19:40:31+03:00" level=debug msg="<- RPCServer.Detach(booltrue)" layer=rpc
DetachResponse
DisconnectRequest to parent

The same (build success) on 0.6.84:

Verbose logs are written to:
C:\Users\matias\AppData\Local\Temp\vscode-go-debug.txt
19:49:57, 2018-8-4
InitializeRequest
InitializeResponse
Using GOPATH: c:\users\matias\code\worldo
Running: c:\users\matias\code\worldo\bin\dlv.exe debug cmd\test --headless=true --listen=127.0.0.1:2345 --log=true --
API server listening at: 127.0.0.1:2345
time="2018-08-04T19:49:57+03:00" level=info msg="launching process with args: [c:\\Users\\matias\\code\\worldo\\src\\cmd\\test\\debug]" layer=debugger
InitializeEvent
ConfigurationDoneRequest
ContinueRequest
ContinueResponse
ThreadsRequest
time="2018-08-04T19:49:58+03:00" level=debug msg=continuing layer=debugger
HELLO
continue state {"Running":false,"Threads":null,"NextInProgress":false,"exited":true,"exitStatus":0,"When":""}
TerminatedEvent
DisconnectRequest

After uncommenting the commented line - causing an error ('unexpected to at end of statement') while building - it is impossible to re-run the debugger.

F5 seems to be completely ignored, while running from the Debug pane results in an 'There is already a debug configuration running' error message. Stop debugging is active, but does not result in anything while restarting results in the same error. Trying to terminate/stop/anything from command palette does not help either - the only workarounds seem to be a complete restart after each build failure (which is pretty much unusable) or downgrading to 0.6.84.

Logs from build failure are as follows:

Verbose logs are written to:
C:\Users\matias\AppData\Local\Temp\vscode-go-debug.txt
19:41:01, 2018-8-4
InitializeRequest
InitializeResponse
Using GOPATH: c:\users\matias\code\worldo
Running: c:\users\matias\code\worldo\bin\dlv.exe debug cmd\test --headless=true --listen=127.0.0.1:2345 --log=true --log-output=rpc --
# cmd/test
.\main.go:9:12: syntax error: unexpected to at end of statement
exit status 2
Process exiting with code: 1
Delve is closed
DisconnectRequest
HaltRequest

The same (build failure) on 0.6.84:

Verbose logs are written to:
C:\Users\matias\AppData\Local\Temp\vscode-go-debug.txt
19:50:40, 2018-8-4
InitializeRequest
InitializeResponse
Using GOPATH: c:\users\matias\code\worldo
Running: c:\users\matias\code\worldo\bin\dlv.exe debug cmd\test --headless=true --listen=127.0.0.1:2345 --log=true --
# cmd/test
.\main.go:9:12: syntax error: unexpected this at end of statement
exit status 2
Process exiting with code: 1
Delve is closed
DisconnectRequest

@ramya-rao-a
Copy link
Contributor

In @antihax logs I see that VSCode is sending a ListGoroutines request right after the continue command, that request is synchronous and can't be executed until continue terminates and will also block any other command from going through (including halt commands).

@aarzilli That explains why the halt command never makes it through. Any reason why continue wouldn't terminate?

@moitias Thanks for the detailed steps. The There is already a debug configuration running is related to the previous session not completing properly which is due to what @aarzilli mentioned above

@aarzilli
Copy link

aarzilli commented Aug 6, 2018

That explains why the halt command never makes it through. Any reason why continue wouldn't terminate?

The program in question is an infinite loop, if the halt doesn't make it through it will never terminate on its own.

@ramya-rao-a
Copy link
Contributor

if the halt doesn't make it through it will never terminate on its own.

@aarzilli You mean the program will not terminate on its own or the continue command? What is the suggested way to go about this for delve clients?

@aarzilli
Copy link

aarzilli commented Aug 6, 2018

@aarzilli You mean the program will not terminate on its own or the continue command?

I mean both, if the program doesn't stop somehow the continue doesn't return either.

What is the suggested way to go about this for delve clients?

Not sending requests while the target is running.

@gregmarr
Copy link

gregmarr commented Aug 6, 2018

I am on Mac OS and am also seeing all of the issues reported here: having to click twice to stop, processes sticking around that I have to kill on my own using Activity Monitor, and the error about debugging already running for which I have to restart VSCode. After I started seeing this I updated Delve and the Go tools, so they're current.

@ramya-rao-a
Copy link
Contributor

I'll look into that, thanks.

@vasmik
Copy link

vasmik commented Aug 8, 2018

Mac OS - same issue. Downgraded to 0.6.84 :(

@ramya-rao-a
Copy link
Contributor

ramya-rao-a commented Aug 8, 2018

Not sending requests while the target is running.

This doesn't seem trivial. There is no way way for the debug adapter to know if the target is still running.

Instead, I have brought back the code to kill the process manually, but only if we don't hear back from the halt request made to delve or if the detach request fails. @moitias This will fix your issue as well.

Everyone here, please try the below

@aarzilli
Copy link

aarzilli commented Aug 9, 2018

This doesn't seem trivial. There is no way way for the debug adapter to know if the target is still running.

The target is running from the time you make a Command request to the time you receive a response for it.

@ramya-rao-a
Copy link
Contributor

Thanks @aarzilli. I've included a check to not make the ListRoutines call if a previous continue request is pending. Regardless I'll keep the code to kill manually if halt doesnt return in time anyway. That should act as a catch all on other unforeseen issues.

All,
If you havent already, please update to the latest beta version by following the steps in #1814 (comment) and let me know if the issue has resolved for you.

@cpwc
Copy link

cpwc commented Aug 10, 2018

@ramya-rao-a the latest beta version works perfectly.

@antihax
Copy link
Author

antihax commented Aug 11, 2018

Working here too.

@ramya-rao-a
Copy link
Contributor

ramya-rao-a commented Aug 13, 2018

The fix is now available in the latest update (0.6.86) to the Go extension.

Thanks everyone for your patience.

@Evasion
Copy link

Evasion commented Aug 23, 2018

Appears to still be an issue in 0.6.88

@ramya-rao-a
Copy link
Contributor

@Evasion Please add "trace": "verbose" to your debug configuration, share the output logs and a sample code that I can use to repro

@Evasion
Copy link

Evasion commented Aug 24, 2018

I added verbose as advised but I have not been able to recreate since then. Will update once I am able to reproduce it.

@ramya-rao-a
Copy link
Contributor

@Evasion, if you do see it again, please log a new issue. This thread is already long :)

@vscodebot vscodebot bot locked and limited conversation to collaborators Sep 27, 2018
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
Projects
None yet
Development

No branches or pull requests