Has anyone noticed unreliable Delve debugger output or is there a problem between keyboard and chair?

I kind of feel like I’m taking crazy pills and missing something extremely obvious here. I’ve reported a Delve bug before only for it to end up getting rerouted as a Go bug instead, and this time I want to check if anyone else has seen this or knows of it as a known issue (or user error of course, which is the most likely scenario).

I have a more detailed version below, but the tl;dr is:

I am seeing variables being reported as nil, as default-value structs, and as empty strings in the debugger. A variable will look right on one line and turn empty or nil the next. Has anybody seen this?

This is Go 1.11 rc1, GoLand 2018.2.1 and…whatever version of Delve 2018.2.1 ships with.

I’ve done a bit of searching through Delve issues and have run across some issues with local variables missing, but it seemed specific to VS Code and I am not sure it’s relevant here. Maybe I missed an existing issue for this already though?

The situation is: I am starting a test on my client, which spins up a new server. I am then attaching to the server process and stepping through the server-side breakpoints. I am running go build and go install between runs so the server binary I’m running should ™ be in sync with the source I’m stepping through.

Edit: I should note that I have also tried building without compiler optimization and inlining via -gcflags '-N -l' - maybe I missed some other flags needed here? I have also checked that there are no multiple versions of my server on the system (so the client shouldn’t be using some old outdated server binary)


Here is the longer version with code and screenshots to hopefully help another set of eyes spot any problems between keyboard and chair:

I am retrieving a custom request struct from a *http.Request. This works fine. The struct is defined as follows:

type JarReq struct {
	request
	Jar          domain.Jar `json:"jar"`
	AuthProvider string     `json:"authProvider"`
}

So in function A I’m running jarReq, err := getJarReq(r), which does this:

func getJarReq(r *http.Request) (restapi.JarReq, error) {
	var jar restapi.JarReq
	body, err := ioutil.ReadAll(io.LimitReader(r.Body, 1048576))
	if err != nil {
		return jar, err
	}

	defer r.Body.Close()

	if err := json.Unmarshal(body, &jar); err != nil {
		return jar, err
	}
	return jar, nil
}

Then in function A I call this error handling function:

func HandleReqErr(err error, w http.ResponseWriter) {
	if err == nil {
		return
	}
	util.HandleErr(err, "CreateUserErr")
	w.Header().Set("Content-Type", "application/json; charset=UTF-8")
	w.WriteHeader(422) // unprocessable entity
	if err := json.NewEncoder(w).Encode(err); err != nil {
		util.HandleErr(err, "CreateUserErr")
	}
}

All it does is return because err is nil.

I then pass jarReq to another function: jarRes, err := createJar(jarReq)

Which is defined as follows:

func createJar(jarReq restapi.JarReq) (jarRes restapi.ExportedJarRes, err error) {
	jar := jarReq.Jar
	repo, err := domain.NewJarRepo(env.App.Database)
	eRes := restapi.ExportedJarRes{}
	res, err := handlers.CreateModel(repo, &jar, &eRes)
	return *res.(*restapi.ExportedJarRes), err
}

But as soon as I step into createJar, jarReq is nil in the debugger.

In attempts to debug this I have printed out jarReq in createJar(), like so:

func createJar(jarReq restapi.JarReq) (jarRes restapi.ExportedJarRes, err error) {
	msg := fmt.Sprintf("%v", jarReq)
	fmt.Println(msg)
	jar := jarReq.Jar
	repo, err := domain.NewJarRepo(env.App.Database)
	eRes := restapi.ExportedJarRes{}
	res, err := handlers.CreateModel(repo, &jar, &eRes)
	return *res.(*restapi.ExportedJarRes), err
}

I can see that when I set msg, the value looks correct. But in the debugger jarReq is still nil. Then when I take one step forward, a new variable appears in the debugger: r·4 - which is also nil, and which is of type JarRepo (which as you can see I’m retrieving in the next line, only this appears at a breakpoint on the jar := jarReq.Jar line before I ever get to domain.NewJarRepo()

Then, msg turns into an empty string - before I make any other calls or get a chance to modify that value in any way (that I can see!) Here are a couple of screenshots. Note normal looking msg, as if Sprintf clearly got something from jarReq, but a nil jarReq. Also note that jarReq shows nil before I assign anything to msg.

Now note one line forward - this is breaking on the fmt.Println(msg) line. msg is now an empty string and jarReq remains nil:

Also note that if I step through to and past jar := jarReq.Jar I do not get a nil pointer dereference panic and jar looks like it should, so it obviously got a value. Like so:

But if I take one more step forward, jar turns into a default empty struct.

Since the vars in the debugger keep turning to default structs, empty strings, and nils, I went down the chain and printed some of these things like in the examples above - the values do look correct (at least the ones I’ve checked), until the strings turn to empty strings when I step through to the next line. Has anybody encountered this? Am I missing some stupid obvious thing here?

Thanks (and sorry about the length)

Hi Liza,

I am not a delve user so I cannot help much. One of the causes could be a concurrency problem, or the fact that Delve cannot properly stop the program during network operations.

Could you please link the bug report you made to Delve?

Also, is your program race free?

Hi,

I haven’t bugged this to Delve yet, I was talking about filing a different bug on Delve earlier that ended up turning into this Go issue. Before filing another bug on Delve I wanted to make sure this wasn’t some obvious user error. I’m still suspicious of compiler optimizations here, although I’ve disabled them in theory with the aforementioned flags.

Yes, the program is race free to the extent that I can see (I run all tests with race detector on and I’m not doing any fancy goroutine concurrency stuff here).

I see. As you correctly debugged, it is because you use the plugin package (thus, dynamic SO loading.)

That’s fairly new to Go and can cause issues like the one you have.

Not sure if there is any solution for now: maybe reimplement your plugins using github.com/natefitch/pie and multiple processes…

I think we’re misunderstanding each other. The original issue I filed has nothing to do with this issue - we can just pretend the other issue doesn’t even exist in relation to this particular thread. I am not using a plugin. I only mentioned the original issue because it was an example of an issue I mistakenly attributed to Delve, so before mistakenly attributing another issue to Delve I wanted to check here if anyone has encountered this or has any other ideas. The two are completely independent of each other.

Oh yes, sorry, I have misread your answer.

I don’t know how to help, maybe it’s worth opening another bug against Delve.

PS: I assume the ignored errors in createJar above are just for brevity, right?

Thanks for taking a look, anyway :slight_smile: I did end up filing a bug on Delve and as suspected this did end up being an issue with compiler optimizations - I was using the wrong flags after all and only disabling optimizations for the main package. Apparently what I should be using is -gcflags='all=-N -l', not -gcflags '-N -l'.

Unfortunately even after fixing the above I am seeing the same issue. I still suspect optimizations are not fully disabled. The binary size is identical with and without the above flags, I’d expect the unoptimized binary to be larger…maybe I’m missing something else here. Anyway, here is the issue on Delve and any followup discussion will probably be there (it mentions GoLand handling optimized function warnings from Delve a bit better as well, vs just showing misleading nil/zero-value variables to the user): https://github.com/derekparker/delve/issues/1320

The ignored errors are not for brevity, this is a prototype with a lot of work to do so there is a lot of error handling and other issues to finish and resolve.

This issue was solved by

  • rebooting my machine
  • installing Go 1.11 (previously was on rc1), and most importantly:
  • using the correct command to disable optimizations: -gcflags='all=-N -l'.

For some reason c) on its own was not enough. I’m not sure what the root of the rest of the problems was, but the debugger is now behaving as it should.

For the future, this command was helpful to confirm whether my binary was compiled with optimizations or not: objdump --dwarf executable | grep DW_AT_producer (thanks to Alessandro Arzilli of Delve). After doing the above steps I could see -N -l output at the end of each line (the binary was also larger in size as expected).

1 Like

This topic was automatically closed 90 days after the last reply. New replies are no longer allowed.