Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

debug: fix and expand extension logging for dlv-dap and process teardown #1410

Closed
polinasok opened this issue Apr 9, 2021 · 6 comments
Closed

debug: fix and expand extension logging for dlv-dap and process teardown #1410

polinasok opened this issue Apr 9, 2021 · 6 comments
Labels
Debug Issues related to the debugging functionality of the extension. FrozenDueToAge
Milestone
v0.25.0

Comments

@polinasok
Copy link
Contributor

polinasok commented Apr 9, 2021 •
edited
Loading

When the dlv-dap server is started by the extension, the extension manages its lifecycle. For troubleshooting sticky situations and identifying issues, it would be great if it logged when the server is being shutdown from the extension side. We do have shutdown logging in dlv-dap, but that assumes that dlv-dap is shutting down cleanly and that dlv-dap chatty logging is on. That won't help us with cases where dlv is unresponsive or has crashed (potentially with the child process still lingering), so the extension needs to be doing some force-cleanup.

We already print at start-up

Running: /Users/polina/go/bin/dlv-dap dap ...etc...

And sometimes I see this, but it seems very inconsistent:

Process exited normally: false

It would be great if there was a reliable message at the end, whether things exited normally or not, both on the process and the debugger side. We could print something short by default and have additional details if "trace" attribute is on.
@polinasok polinasok added Debug Issues related to the debugging functionality of the extension. DlvDAP labels Apr 9, 2021
@polinasok polinasok changed the title debug: extension logging for dlv-dap teardown debug: fix and expand extension logging for dlv-dap and process teardown Apr 9, 2021
@polinasok
Copy link
Contributor Author

polinasok commented Apr 9, 2021 •
edited
Loading

Playing with Process exited normally: false a bit more. Something is not right.

            "name": "Launch file",
            "type": "go",
            "request": "launch",
            "mode": "debug",
            "program": "${file}",
            "debugAdapter": "dlv-dap",
            "showLog": true,

package main

func main() {
	return
}

Debug session 1 outputs:

Running: /Users/polina/go/bin/dlv-dap dap --listen=127.0.0.1:63496 --log=trueDAP server listening at: 127.0.0.1:63496
2021-04-08T17:28:27-07:00 info layer=debugger launching process with args: [/Users/polina/go/src/__debug_bin]
2021-04-08T17:28:27-07:00 debug layer=debugger continuing

Debug session 2 outputs:

Running: /Users/polina/go/bin/dlv-dap dap --listen=127.0.0.1:63541 --log=trueDAP server listening at: 127.0.0.1:63541
2021-04-08T17:29:20-07:00 info layer=debugger launching process with args: [/Users/polina/go/src/__debug_bin]
2021-04-08T17:29:20-07:00 debug layer=debugger continuing
2021-04-08T17:29:20-07:00 debug layer=debugger halting
2021-04-08T17:29:20-07:00 debug layer=debugger detaching
2021-04-08T17:29:20-07:00 debug layer=debugger detaching
Process exited normally: false

@hyangah
Copy link
Contributor

hyangah commented Apr 9, 2021 •
edited
Loading

Please follow the troubleshooting guide and include the dlv-dap's version information.

Edit: the log message in the original report is from

vscode-go/src/goDebugFactory.ts

Line 356 in 92cdf32

log(`Process exited normally: ${p.killed}`);
which was now removed at master because I thought it's misleading. (here, 'false' was a good thing meaning not killed)

But I see the value of showing the program exit status - let's place back a log.

And inconsistent logging - we need the dlv-dap version. I suggest to check this issue after go-delve/delve#2414 is merged.

@polinasok
Copy link
Contributor Author 

$ go version -m  /Users/polina/go/bin/dlv-dap
/Users/polina/go/bin/dlv-dap: go1.14.3
	path	github.com/go-delve/delve/cmd/dlv
	mod	github.com/go-delve/delve	v1.6.1-0.20210407080014-c4b9c8584309	h1:gaXLIMtjalnxdCfPK6Tyh5fTFMN4e8t5WQ+nZOgnw84=
	dep	github.com/cosiner/argv	v0.1.0	h1:BVDiEL32lwHukgJKP87btEPenzrrHUjajs/8yzaqcXg=
	dep	github.com/cpuguy83/go-md2man	v1.0.10	h1:BSKMNlYxDvnunlTymqtgONjNnaRV1sTpcovwwjF22jk=
	dep	github.com/google/go-dap	v0.4.0	h1:bWSjcM9zp/jEFD4YbWERcHSed8vHbEdk0rmTvqgXDAs=
	dep	github.com/hashicorp/golang-lru	v0.5.4	h1:YDjusn29QI/Das2iO9M0BHnIbxPeyuCHsjMW+lJfyTc=
	dep	github.com/mattn/go-isatty	v0.0.3	h1:ns/ykhmWi7G9O+8a448SecJU3nSMBXJfqQkl0upE1jI=
	dep	github.com/peterh/liner	v0.0.0-20170317030525-88609521dc4b	h1:8uaXtUkxiy+T/zdLWuxa/PG4so0TPZDZfafFNNSaptE=
	dep	github.com/russross/blackfriday	v1.5.2	h1:HyvC0ARfnZBqnXwABFeSZHpKvJHJJfPz81GNueLj0oo=
	dep	github.com/sirupsen/logrus	v1.6.0	h1:UBcNElsrwanuuMsnGSlYmtmgbb23qDR5dG+6X6Oo89I=
	dep	github.com/spf13/cobra	v0.0.0-20170417170307-b6cb39589372	h1:eRfW1vRS4th8IX2iQeyqQ8cOUNOySvAYJ0IUvTXGoYA=
	dep	github.com/spf13/pflag	v0.0.0-20170417173400-9e4c21054fa1	h1:7bozMfSdo41n2NOc0GsVTTVUiA+Ncaj6pXNpm4UHKys=
	dep	go.starlark.net	v0.0.0-20200821142938-949cc6f4b097	h1:YiRMXXgG+Pg26t1fjq+iAjaauKWMC9cmGFrtOEuwDDg=
	dep	golang.org/x/arch	v0.0.0-20190927153633-4e8777c89be4	h1:QlVATYS7JBoZMVaf+cNjb90WD/beKVHnIxFKT4QaHVI=
	dep	golang.org/x/sys	v0.0.0-20200625212154-ddb9806d33ae	h1:Ih9Yo4hSPImZOpfGuA4bR/ORKTAbhZo2AbWNRCnevdo=
	dep	gopkg.in/yaml.v2	v2.2.1	h1:mUhvW9EsL+naU5Q3cakzfE91YhliOondGd6ZrsDBHQE=

@polinasok
Copy link
Contributor Author

polinasok commented Apr 9, 2021 •
edited
Loading

I am not worried about inconsistent logging from the delve side. I only included it to show that perhaps the timing of how delve exited impacted the status logging from the extension side. The above log only included debugger logging. If you turn on dap logging as well, you will see that after continue, there are the following things happening:

2021-04-08T22:35:46-07:00 debug layer=dap [-> to client]{"seq":0,"type":"event","event":"terminated","body":{}}
2021-04-08T22:35:46-07:00 debug layer=dap [<- from client]{"seq":5,"type":"request","command":"threads"}
2021-04-08T22:35:46-07:00 debug layer=dap [-> to client]{"seq":0,"type":"response","request_seq":5,"success":true,"command":"threads","body":{"threads":null}}
2021-04-08T22:35:46-07:00 debug layer=dap [<- from client]{"seq":6,"type":"request","command":"disconnect","arguments":{}}
2021-04-08T22:35:46-07:00 debug layer=dap [-> to client]{"seq":0,"type":"response","request_seq":6,"success":true,"command":"disconnect"}

And sometimes the log ends there. Other times you get some or all of these

2021-04-08T22:49:11-07:00 debug layer=debugger halting
2021-04-08T22:49:11-07:00 debug layer=dap Process 50461 has exited with status 0
2021-04-08T22:49:11-07:00 debug layer=debugger detaching
2021-04-08T22:49:11-07:00 debug layer=debugger detaching
Process exited normally: false

The disconnect handler right now uses fire-and-forget approach: the disconnect response is sent first, and then the rest of the teardown happens. So if the client gets the disconnect response before all the halting and detaching, it will disconnect. Or maybe ​the last couple of logging messages don't get flushed in time. This reminds me though that I have been meaning to move the disconnect response to after we detached. That should bring more consistency here and we could even sent back errors.

But in either case, we would not know any of this, unless dlv-dap logging was on. So we really do need the extension to tell us from its end if things have exited and with what status. This was also the reason why "process has exited with status" message was error-logged from delve, so we get it no matter what, but that was changed in go-delve/delve#2412. Perhaps we should consider bringing it back.

@polinasok polinasok mentioned this issue Apr 9, 2021
Merged
@stamblerre stamblerre added this to the Untriaged milestone Apr 9, 2021
@hyangah hyangah modified the milestones: Untriaged, Backlog Apr 14, 2021
@gopherbot
Copy link
Collaborator

Change https://golang.org/cl/310751 mentions this issue: src/goDebugFactory: send teardown log to Go Debug channel

@gopherbot
Copy link
Collaborator

Change https://golang.org/cl/310750 mentions this issue: src/goDebugFactory: add GoDebugAdapterTrackerFactory

gopherbot pushed a commit that referenced this issue Apr 19, 2021
@hyangah
src/goDebugFactory: add GoDebugAdapterTrackerFactory
cfc787e 
And create a `Go Debug` output channel that can be used
to output all logging and traces from debug extension
activity.

Logging level of individual debug session is controlled
by launch configuration's `trace` attribute.

Manually tested.

Update #1410

Change-Id: Ib87d014ec6114581af78bdcdd74b190b14552ce6
Reviewed-on: https://go-review.googlesource.com/c/vscode-go/+/310750
Trust: Hyang-Ah Hana Kim <hyangah@gmail.com>
Run-TryBot: Hyang-Ah Hana Kim <hyangah@gmail.com>
TryBot-Result: kokoro <noreply+kokoro@google.com>
Reviewed-by: Suzy Mueller <suzmue@golang.org>
@hyangah hyangah modified the milestones: Backlog, v0.25.0 Apr 19, 2021
@golang golang locked and limited conversation to collaborators Apr 19, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
Debug Issues related to the debugging functionality of the extension. FrozenDueToAge
Projects
None yet
Milestone
v0.25.0
Development

No branches or pull requests
4 participants
@hyangah @stamblerre @gopherbot @polinasok