Add support to trace defer function calls under trace follow option (#3978)

Author: archanaravindar

Documentation/usage/dlv_trace.md

@@ -23,7 +23,7 @@ dlv trace [package] regexp [flags]
 ```
       --ebpf               Trace using eBPF (experimental).
   -e, --exec string        Binary file to exec and trace.
-      --follow-calls int   Trace all children of the function to the required depth
+      --follow-calls int   Trace all children of the function to the required depth. Trace also supports defer functions and cases where functions are dynamically returned and passed as parameters.
   -h, --help               help for trace
       --output string      Output path for the binary.
   -p, --pid int            Pid to attach to.

_fixtures/testtracefns.go

@@ -69,13 +69,88 @@ func F4() {
 	panic("blah")
 }
 
+var intc, intd int
+
+func swap() {
+	defer func() {
+		intc += 100
+	}()
+	temp := intc
+	intc = intd
+	intd = temp
+}
+
+func unnamedDefer() {
+	intc = -100
+	intd = 100
+	swap()
+	fmt.Println(intc, intd)
+}
+func formula(op string) func(int, int) int {
+	var calc func(int, int) int
+	if op == "add" {
+		calc = func(m int, n int) int {
+			res := m + n
+			return res
+		}
+	} else if op == "mul" {
+		calc = func(m int, n int) int {
+			res := m * n
+			return res
+		}
+	}
+	return calc
+}
+
+func op() int {
+	calc := formula("add")
+	res := calc(10, 20)
+	return res
+}
+
+func assign(bar func()) {
+	bar()
+}
+func testfunc() {
+	intc = 10
+	intd = 20
+}
+
+func dyn() {
+	intc = 0
+	intd = 0
+	assign(testfunc)
+}
+
+func outer() {
+	intc = 40
+        defer swap()
+}
+func nestDefer() {
+        defer outer()
+}
+
+func namedDeferLoop(n int) {
+        for i := 0; i < n; i++ {
+                defer testfunc()
+        }
+        temp := intc
+        intc = intd
+        intd = temp
+}
 func main() {
 	j := 0
 	j += A(2)
 
 	j += first(6)
 	j += callme(2)
 	fmt.Println(j)
+	unnamedDefer()
+	nestDefer()
+	namedDeferLoop(2)
 	F0()
+	ans := op()
+	fmt.Println(ans)
+	dyn()
 
 }

cmd/dlv/cmds/commands.go

@@ -369,7 +369,7 @@ only see the output of the trace operations you can redirect stdout.`,
 	must(traceCommand.RegisterFlagCompletionFunc("stack", cobra.NoFileCompletions))
 	traceCommand.Flags().String("output", "", "Output path for the binary.")
 	must(traceCommand.MarkFlagFilename("output"))
-	traceCommand.Flags().IntVarP(&traceFollowCalls, "follow-calls", "", 0, "Trace all children of the function to the required depth")
+	traceCommand.Flags().IntVarP(&traceFollowCalls, "follow-calls", "", 0, "Trace all children of the function to the required depth. Trace also supports defer functions and cases where functions are dynamically returned and passed as parameters.")
 	rootCommand.AddCommand(traceCommand)
 
 	coreCommand := &cobra.Command{

pkg/proc/breakpoints.go

@@ -113,6 +113,11 @@ type Breaklet struct {
 	watchpoint *Breakpoint
 }
 
+// SetCallback sets the call back field, this was primarily added to prevent exporting callback field
+func (b *Breaklet) SetCallback(callback func(th Thread, p *Target) (bool, error)) {
+	b.callback = callback
+}
+
 // BreakpointKind determines the behavior of delve when the
 // breakpoint is reached.
 type BreakpointKind uint16

service/debugger/debugger.go

@@ -409,13 +409,10 @@ func (d *Debugger) LastModified() time.Time {
 	return d.target.Selected.BinInfo().LastModified()
 }
 
-// FunctionReturnLocations returns all return locations
-// for the given function, a list of addresses corresponding
-// to 'ret' or 'call runtime.deferreturn'.
-func (d *Debugger) FunctionReturnLocations(fnName string) ([]uint64, error) {
-	d.targetMutex.Lock()
-	defer d.targetMutex.Unlock()
-
+// functionReturnLocationsInternal is same as FunctionReturnLocations
+// except that it does not have a lock and unlock as its called from
+// within the callback which has already acquired a lock.
+func (d *Debugger) functionReturnLocationsInternal(fnName string) ([]uint64, error) {
 	if len(d.target.Targets()) > 1 {
 		return nil, ErrNotImplementedWithMultitarget
 	}
@@ -454,6 +451,15 @@ func (d *Debugger) FunctionReturnLocations(fnName string) ([]uint64, error) {
 	return addrs, nil
 }
 
+// FunctionReturnLocations returns all return locations
+// for the given function, a list of addresses corresponding
+// to 'ret' or 'call runtime.deferreturn'.
+func (d *Debugger) FunctionReturnLocations(fnName string) ([]uint64, error) {
+	d.targetMutex.Lock()
+	defer d.targetMutex.Unlock()
+	return d.functionReturnLocationsInternal(fnName)
+}
+
 // Detach detaches from the target process.
 // If `kill` is true we will kill the process after
 // detaching.
@@ -1372,7 +1378,7 @@ func (d *Debugger) Functions(filter string, followCalls int) ([]string, error) {
 		for _, f := range t.BinInfo().Functions {
 			if regex.MatchString(f.Name) {
 				if followCalls > 0 {
-					newfuncs, err := traverse(t, &f, 1, followCalls)
+					newfuncs, err := d.traverse(t, &f, 1, followCalls, filter)
 					if err != nil {
 						return nil, fmt.Errorf("traverse failed with error %w", err)
 					}
@@ -1388,12 +1394,13 @@ func (d *Debugger) Functions(filter string, followCalls int) ([]string, error) {
 	return funcs, nil
 }
 
-func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int) ([]string, error) {
+func (d *Debugger) traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int, rootstr string) ([]string, error) {
 	type TraceFunc struct {
 		Func    *proc.Function
 		Depth   int
 		visited bool
 	}
+
 	type TraceFuncptr *TraceFunc
 
 	TraceMap := make(map[string]TraceFuncptr)
@@ -1409,7 +1416,7 @@ func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int)
 		parent := queue[0]
 		queue = queue[1:]
 		if parent == nil {
-			panic("attempting to open file Delve cannot parse")
+			panic("queue has a nil node, cannot traverse!")
 		}
 		if parent.Depth > followCalls {
 			continue
@@ -1427,10 +1434,89 @@ func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int)
 		}
 		f := parent.Func
 		text, err := proc.Disassemble(t.Memory(), nil, t.Breakpoints(), t.BinInfo(), f.Entry, f.End)
+
 		if err != nil {
 			return nil, fmt.Errorf("disassemble failed with error %w", err)
 		}
 		for _, instr := range text {
+			// Dynamic functions need to be handled specially as their destination location
+			// is not known statically, hence its required to put a breakpoint in order to
+			// acquire the address of the function at runtime and we do this via a
+			// call back mechanism
+			if instr.IsCall() && instr.DestLoc == nil {
+				dynbp, err := t.SetBreakpoint(0, instr.Loc.PC, proc.NextBreakpoint, nil)
+				if err != nil {
+					return nil, fmt.Errorf("error setting breakpoint inside deferreturn")
+				}
+				dynCallback := func(th proc.Thread, tgt *proc.Target) (bool, error) {
+					// TODO(optimization): Consider using an iterator to avoid materializing
+					// the full stack when we only need frames up to the root function
+					rawlocs, err := proc.ThreadStacktrace(tgt, tgt.CurrentThread(), followCalls+2)
+					if err != nil {
+						return false, fmt.Errorf("thread stack trace returned error")
+					}
+					// Since the dynamic function is known only at runtime, the depth is likewise
+					// calculated by referring to the stack and the mechanism is similar to that
+					// used in pkg/terminal/command.go:printTraceOutput
+					rootindex := -1
+					for i := len(rawlocs) - 1; i >= 0; i-- {
+						if rawlocs[i].Call.Fn.Name == rootstr {
+							if rootindex == -1 {
+								rootindex = i
+								break
+							}
+						}
+					}
+					sdepth := rootindex + 1
+
+					if sdepth+1 > followCalls {
+						return false, nil
+					}
+					regs, err := th.Registers()
+					if err != nil {
+						return false, fmt.Errorf("registers inside callback returned err")
+
+					}
+					// Disassemble the instruction at the current PC to get the call destination
+					pc := instr.Loc.PC
+					maxInstLen := uint64(tgt.BinInfo().Arch.MaxInstructionLength())
+					disasm, err := proc.Disassemble(t.Memory(), regs, t.Breakpoints(), tgt.BinInfo(), pc, pc+maxInstLen)
+					if err != nil {
+						return false, fmt.Errorf("failed to disassemble instruction: %w", err)
+					}
+
+					// Extract address from the decoded instruction's destination location
+					var addr uint64
+					if len(disasm) > 0 && disasm[0].DestLoc != nil {
+						addr = disasm[0].DestLoc.PC
+					} else {
+						return false, fmt.Errorf("failed to extract call destination from instruction at PC %#x", pc)
+					}
+					fn := tgt.BinInfo().PCToFunc(addr)
+					if fn == nil {
+						return false, fmt.Errorf("PCToFunc returned nil")
+					}
+					err = createFunctionTracepoints(d, fn.Name, rootstr, followCalls)
+					if err != nil {
+						return false, fmt.Errorf("error creating tracepoint in function %s", fn.Name)
+					}
+					dynchildren, err := d.traverse(t, fn, sdepth+1, followCalls, rootstr)
+					if err != nil {
+						return false, fmt.Errorf("error calling traverse on dynamic children")
+					}
+					for _, child := range dynchildren {
+						err := createFunctionTracepoints(d, child, rootstr, followCalls)
+						if err != nil {
+							return false, fmt.Errorf("error creating tracepoint in function %s", child)
+						}
+					}
+					return false, nil
+				}
+				for _, dynBrklet := range dynbp.Breaklets {
+					dynBrklet.SetCallback(dynCallback)
+				}
+			}
+
 			if instr.IsCall() && instr.DestLoc != nil && instr.DestLoc.Fn != nil {
 				cf := instr.DestLoc.Fn
 				if (strings.HasPrefix(cf.Name, "runtime.") || strings.HasPrefix(cf.Name, "runtime/internal")) && cf.Name != "runtime.deferreturn" && cf.Name != "runtime.gorecover" && cf.Name != "runtime.gopanic" {
@@ -1449,6 +1535,70 @@ func traverse(t proc.ValidTargets, f *proc.Function, depth int, followCalls int)
 	return funcs, nil
 }
 
+// createFunctionTracepoints is a way to create a trace point late in the cycle but just in time that
+// it can be included in the trace output as in the case of dynamic functions, we get to know the
+// functions that are being called from deferreturn quite late in execution. This might create multiple
+// tracepoints
+func createFunctionTracepoints(d *Debugger, fname string, rootstr string, followCalls int) error {
+
+	// Helper function to create breakpoints for tracepoints
+	// Ignore BreakpointExistsError since duplicate tracepoints
+	// are expected during dynamic function discovery
+	createBrkForTracepoint := func(lbp *proc.LogicalBreakpoint) error {
+		d.breakpointIDCounter++
+		lbp.LogicalID = d.breakpointIDCounter
+		lbp.HitCount = make(map[int64]uint64)
+		d.target.LogicalBreakpoints[lbp.LogicalID] = lbp
+		err := d.target.SetBreakpointEnabled(lbp, true)
+		if err != nil {
+			delete(d.target.LogicalBreakpoints, lbp.LogicalID)
+			// Silently ignore BreakpointExistsError - this is expected when
+			// creating tracepoints for functions that may already have them
+			if _, exists := err.(proc.BreakpointExistsError); exists {
+				return nil
+			}
+			return err
+		}
+		return nil
+	}
+
+	// Create tracepoint for function entry
+	lbp := &proc.LogicalBreakpoint{
+		Set: proc.SetBreakpoint{
+			FunctionName: fname,
+		},
+		Tracepoint:       true,
+		RootFuncName:     rootstr,
+		Stacktrace:       20,
+		TraceFollowCalls: followCalls,
+	}
+
+	err := createBrkForTracepoint(lbp)
+	if err != nil {
+		return fmt.Errorf("error creating breakpoint at function %s: %w", fname, err)
+	}
+
+	// Create tracepoints for function return locations
+	raddrs, _ := d.functionReturnLocationsInternal(fname)
+	for i := range raddrs {
+		retLbp := &proc.LogicalBreakpoint{
+			Set: proc.SetBreakpoint{
+				PidAddrs: []proc.PidAddr{{Pid: d.target.Selected.Pid(), Addr: raddrs[i]}},
+			},
+			TraceReturn:      true,
+			RootFuncName:     rootstr,
+			Stacktrace:       20,
+			TraceFollowCalls: followCalls,
+		}
+
+		err := createBrkForTracepoint(retLbp)
+		if err != nil {
+			return fmt.Errorf("error creating breakpoint at function return %s: %w", fname, err)
+		}
+	}
+	return nil
+}
+
 // Types returns all type information in the binary.
 func (d *Debugger) Types(filter string) ([]string, error) {
 	d.targetMutex.Lock()