search

solo-io / squash

The debugger for microservices
https://squash.solo.io
Apache License 2.0
1.74k stars 102 forks source link

Delve panics on some executables - return proper error? #38

Open pavius opened 6 years ago

pavius commented 6 years ago

Attaching to nuclio/nuclio-playground:0.2.4-amd64 which is compiled as such:

GOOS=linux GOARCH=amd64 CGO_ENABLED=0 go build -a -installsuffix cgo -ldflags="-s -w" -o playground cmd/playground/main.go

So optimization and inlining are on. On attach, client logs showed:

2018/01/28 22:47:24 server.go:73: Using API v1
2018/01/28 22:47:24 debugger.go:69: attaching to pid 8606
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0xf0 pc=0x628174]

goroutine 1 [running]:
github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf.(*Reader).Seek(0xc420142360, 0xc400000000)
    /gopath/src/github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf/entry.go:308 +0x354
github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf.(*Data).Reader(0x0, 0xc4201236d8)
    /gopath/src/github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf/entry.go:291 +0x5f
github.com/derekparker/delve/pkg/dwarf/reader.New(0x0, 0x9e1098)
    /gopath/src/github.com/derekparker/delve/pkg/dwarf/reader/reader.go:18 +0x2f
github.com/derekparker/delve/pkg/proc.(*BinaryInfo).DwarfReader(0xc420144000, 0x1)
    /gopath/src/github.com/derekparker/delve/pkg/proc/bininfo.go:83 +0x2f
github.com/derekparker/delve/pkg/proc.(*EvalScope).DwarfReader(0xc42011adb0, 0x1a9f73bb951)
    /gopath/src/github.com/derekparker/delve/pkg/proc/variables.go:325 +0x2f
github.com/derekparker/delve/pkg/proc.(*EvalScope).packageVarAddr(0xc42011adb0, 0xa02f3f, 0x14, 0x7f0c4a2a1fc0, 0xc420054870, 0x21cf)
    /gopath/src/github.com/derekparker/delve/pkg/proc/variables.go:649 +0x40
github.com/derekparker/delve/pkg/proc.GetGoInformation(0xc76840, 0xc420144000, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /gopath/src/github.com/derekparker/delve/pkg/proc/proc.go:406 +0x178
github.com/derekparker/delve/pkg/proc/native.initializeDebugProcess(0xc420144000, 0x0, 0x0, 0x1, 0x40, 0xcb29e0, 0xc62fdb)
    /gopath/src/github.com/derekparker/delve/pkg/proc/native/proc.go:404 +0x10a
github.com/derekparker/delve/pkg/proc/native.Attach(0x219e, 0x7, 0x9f9050, 0x7)
    /gopath/src/github.com/derekparker/delve/pkg/proc/native/proc_linux.go:81 +0x50
github.com/derekparker/delve/service/debugger.(*Debugger).Attach(0xc420128600, 0x219e, 0x0, 0x0, 0x1, 0x4105b2, 0xc420123ad0, 0x48)
    /gopath/src/github.com/derekparker/delve/service/debugger/debugger.go:150 +0x19d
github.com/derekparker/delve/service/debugger.New(0xc420118500, 0xc420118500, 0xc420123b18, 0x410e08)
    /gopath/src/github.com/derekparker/delve/service/debugger/debugger.go:74 +0x74e
github.com/derekparker/delve/service/rpccommon.(*ServerImpl).Run(0xc4201184b0, 0xc42013c101, 0xc4201184b0)
    /gopath/src/github.com/derekparker/delve/service/rpccommon/server.go:119 +0x12d
github.com/derekparker/delve/cmd/dlv/cmds.execute(0x219e, 0xc420118420, 0x0, 0x4, 0x0, 0x0, 0x0, 0x2, 0x0)
    /gopath/src/github.com/derekparker/delve/cmd/dlv/cmds/commands.go:476 +0x2bd
github.com/derekparker/delve/cmd/dlv/cmds.attachCmd(0xc42013a240, 0xc420118410, 0x1, 0x5)
    /gopath/src/github.com/derekparker/delve/cmd/dlv/cmds/commands.go:397 +0xd7
github.com/derekparker/delve/vendor/github.com/spf13/cobra.(*Command).execute(0xc42013a240, 0xc420118280, 0x5, 0x5, 0xc42013a240, 0xc420118280)
    /gopath/src/github.com/derekparker/delve/vendor/github.com/spf13/cobra/command.go:647 +0x234
github.com/derekparker/delve/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xc42013a000, 0xc42013a6c0, 0xc42013a480, 0xc42013a240)
    /gopath/src/github.com/derekparker/delve/vendor/github.com/spf13/cobra/command.go:733 +0x339
github.com/derekparker/delve/vendor/github.com/spf13/cobra.(*Command).Execute(0xc42013a000, 0xc4200001a0, 0xc4200001a0)
    /gopath/src/github.com/derekparker/delve/vendor/github.com/spf13/cobra/command.go:692 +0x2b
main.main()
    /gopath/src/github.com/derekparker/delve/cmd/dlv/main.go:13 +0x55
time="2018-01-28T22:47:26Z" level=debug msg="got netlink msg" msg="{{92 2 0 2 4065} [254 255 255 255 72 0 0 0 20 0 1 3 2 0 0 0 0 0 0 0 2 6 0 0 0 4 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]}"
time="2018-01-28T22:47:26Z" level=warning msg="Netlink error " errval=4294967294
time="2018-01-28T22:47:26Z" level=warning msg="GetListeningSocketsFor: Can't get listening sockets with netlink" err="netlink error: 2" pid=8809
time="2018-01-28T22:47:26Z" level=debug msg="GetSocketInodesFor: got listeningsokcets" inoddedPorts="[{3046465 41531}]" pid=8809
time="2018-01-28T22:47:26Z" level=debug msg="GetSocketInodesFor: got sockets for pid" pid=8809 sockets="[]"
time="2018-01-28T22:47:26Z" level=error msg="can't get port for pid" err="<nil>" pid=8809 ports="[]"
time="2018-01-28T22:47:26Z" level=error msg="can't get headless dlv port" err="Number of ports is zero"
time="2018-01-28T22:47:26Z" level=error msg="Starting debug server error" err="Number of ports is zero"

I guess a nicer way of handling this is reporting that executable can't be debugged by dlv, and to disable optimizations.

yuval-k commented 6 years ago

a bug in the debugger - feels like inception. I'm investigating.

pavius commented 6 years ago

Yep, just realized that it's not optimizations/inline related - rather the fact that debug symbols are being stripped from the executable (we do this to keep sizes down by about 20%-ish if i recall).

kidlj commented 6 years ago

I had the similar problem while following the squash-vscode tutorial.

time="2018-10-04T14:14:04Z" level=debug msg="Removing attachment" attachment.Name=n6iXAnV0mB
time="2018-10-04T14:14:04Z" level=debug msg="Notifying server of attachment to debug config object" DebugAttachmentID=77rUpTDb4S patchDebugAttachment="&{0xc000536320 0xc000070f60 0xc000536360}"
time="2018-10-04T14:14:04Z" level=info msg="debug attachment notified of attachment!"
time="2018-10-04T14:14:04Z" level=debug msg="watchForAttached - calling GetDebugAttachments" params="(*debugattachment.GetDebugAttachmentsParams)(0xc000552d80)({\n XTimeout: (*float64)(<nil>),\n IfNoneMatch: (*string)(0xc0005205d0)((len=2) \"21\"),\n Names: ([]string) <nil>,\n Node: (*string)(0xc0004b4f60)((len=4) \"kube\"),\n State: (*string)(<nil>),\n States: ([]string) <nil>,\n Wait: (*bool)(0xc00024098d)(true),\n timeout: (time.Duration) 30s,\n Context: (context.Context) <nil>,\n HTTPClient: (*http.Client)(<nil>)\n})\n"
time="2018-10-04T14:14:04Z" level=debug msg="Cri GetPid called" attachment="map[namespace:default pod:example-microservice-rc-mcsl8 container:example-microservice]"
time="2018-10-04T14:14:04Z" level=debug msg="Cri GetPid ListPodSandbox" inpod="(*v1alpha2.PodSandboxFilter)(0xc000536d60)(&PodSandboxFilter{Id:,State:&PodSandboxStateValue{State:SANDBOX_READY,},LabelSelector:map[string]string{io.kubernetes.pod.name: example-microservice-rc-mcsl8,io.kubernetes.pod.namespace: default,},})\n"
time="2018-10-04T14:14:04Z" level=debug msg="getUpdatedSnapshots - filtering new attachments" attachments="(models.GetDebugAttachmentsOKBody) (len=1 cap=4) {\n (*models.DebugAttachment)(0xc000537560)({\n  Metadata: (*models.ObjectMeta)(0xc000537580)({\n   Name: (string) (len=10) \"77rUpTDb4S\",\n   Version: (string) \"\"\n  }),\n  Spec: (*models.DebugAttachmentSpec)(0xc0004f4360)({\n   Attachment: (map[string]interface {}) (len=3) {\n    (string) (len=9) \"namespace\": (string) (len=7) \"default\",\n    (string) (len=3) \"pod\": (string) (len=29) \"example-microservice-rc-mcsl8\",\n    (string) (len=9) \"container\": (string) (len=20) \"example-microservice\"\n   },\n   Debugger: (string) (len=3) \"dlv\",\n   Image: (string) (len=22) \"kidlj/microservice:0.1\",\n   MatchRequest: (bool) false,\n   Node: (string) (len=4) \"kube\",\n   ProcessName: (string) \"\"\n  }),\n  Status: (*models.DebugAttachmentStatus)(0xc0005375a0)({\n   DebugServerAddress: (string) \"\",\n   State: (string) (len=9) \"attaching\"\n  })\n })\n}\n"
time="2018-10-04T14:14:04Z" level=info msg="watchForAttached - got debug attachment!" deletedAttachments="([]*models.DebugAttachment) <nil>\n" newattachments="([]*models.DebugAttachment) <nil>\n"
time="2018-10-04T14:14:04Z" level=debug msg="watchForAttached - calling GetDebugAttachments" params="(*debugattachment.GetDebugAttachmentsParams)(0xc000553780)({\n XTimeout: (*float64)(<nil>),\n IfNoneMatch: (*string)(0xc000521710)((len=2) \"22\"),\n Names: ([]string) <nil>,\n Node: (*string)(0xc0004b5a30)((len=4) \"kube\"),\n State: (*string)(<nil>),\n States: ([]string) <nil>,\n Wait: (*bool)(0xc000241f0b)(true),\n timeout: (time.Duration) 30s,\n Context: (context.Context) <nil>,\n HTTPClient: (*http.Client)(<nil>)\n})\n"
time="2018-10-04T14:14:04Z" level=debug msg="Cri GetPid ListContainers" incont="(*v1alpha2.ContainerFilter)(0xc000521e30)(&ContainerFilter{Id:,State:nil,PodSandboxId:760727258f30d01c77096bd9f709fd8db38919be3a184d762c911eca1a34e8ba,LabelSelector:map[string]string{io.kubernetes.container.name:
example-microservice,},})\n"
time="2018-10-04T14:14:04Z" level=debug msg="Cri GetPid ListContainers - got response" respcont="([]*v1alpha2.Container) (len=1 cap=1) {\n (*v1alpha2.Container)(0xc0004f48a0)(&Container{Id:b02a68700ba308b1485be478470047fbeda1e4ae0c668208ac3b23bd63e996a7,PodSandboxId:760727258f30d01c77096bd9f709fd8db38919be3a184d762c911eca1a34e8ba,Metadata:&ContainerMetadata{Name:example-microservice,Attempt:0,},Image:&ImageSpec{Image:sha256:a690e53f33c1d56f5a59911bdb33b4ad7387a562529f79b209c842d028ffa7f4,},ImageRef:sha256:a690e53f33c1d56f5a59911bdb33b4ad7387a562529f79b209c842d028ffa7f4,State:CONTAINER_RUNNING,CreatedAt:1538662417000000000,Labels:map[string]string{io.kubernetes.container.name: example-microservice,io.kubernetes.pod.name: example-microservice-rc-mcsl8,io.kubernetes.pod.namespace: default,io.kubernetes.pod.uid: aebbcb06-c7df-11e8-8150-0800275f82b1,},Annotations:map[string]string{io.kubernetes.container.hash: 41be2205,io.kubernetes.container.ports: [{\"containerPort\":8080,\"protocol\":\"TCP\"}],io.kubernetes.container.restartCount: 0,io.kubernetes.container.terminationMessagePath: /dev/termination-log,io.kubernetes.container.terminationMessagePolicy: File,io.kubernetes.pod.terminationGracePeriod: 30,},})\n}\n"
time="2018-10-04T14:14:04Z" level=debug msg="Cri GetPid ListContainers - filtered response" containers="([]*v1alpha2.Container) (len=1 cap=1) {\n (*v1alpha2.Container)(0xc0004f48a0)(&Container{Id:b02a68700ba308b1485be478470047fbeda1e4ae0c668208ac3b23bd63e996a7,PodSandboxId:760727258f30d01c77096bd9f709fd8db38919be3a184d762c911eca1a34e8ba,Metadata:&ContainerMetadata{Name:example-microservice,Attempt:0,},Image:&ImageSpec{Image:sha256:a690e53f33c1d56f5a59911bdb33b4ad7387a562529f79b209c842d028ffa7f4,},ImageRef:sha256:a690e53f33c1d56f5a59911bdb33b4ad7387a562529f79b209c842d028ffa7f4,State:CONTAINER_RUNNING,CreatedAt:1538662417000000000,Labels:map[string]string{io.kubernetes.container.name: example-microservice,io.kubernetes.pod.name: example-microservice-rc-mcsl8,io.kubernetes.pod.namespace: default,io.kubernetes.pod.uid: aebbcb06-c7df-11e8-8150-0800275f82b1,},Annotations:map[string]string{io.kubernetes.container.hash: 41be2205,io.kubernetes.container.ports: [{\"containerPort\":8080,\"protocol\":\"TCP\"}],io.kubernetes.container.restartCount: 0,io.kubernetes.container.terminationMessagePath: /dev/termination-log,io.kubernetes.container.terminationMessagePolicy: File,io.kubernetes.pod.terminationGracePeriod: 30,},})\n}\n"
time="2018-10-04T14:14:04Z" level=info msg="found some pids" potentialpids="[30579]"
time="2018-10-04T14:14:04Z" level=debug msg="Finding process to debug" processName=
time="2018-10-04T14:14:04Z" level=debug msg=checking currentProcessName=microservice pid=30579
time="2018-10-04T14:14:04Z" level=info msg="Attaching to live session" app="&{0xc000536320 0xc000070f60 0xc000536360}"
time="2018-10-04T14:14:04Z" level=info msg="starting to debug" pid=30579
time="2018-10-04T14:14:04Z" level=info msg="start debug called"
time="2018-10-04T14:14:04Z" level=info msg="start debug params" curdebugger=dlv
time="2018-10-04T14:14:04Z" level=info msg="starting debug server" pid=30579
time="2018-10-04T14:14:04Z" level=debug msg="StartDebugServer called" pid=30579
time="2018-10-04T14:14:04Z" level=debug msg="dlv command" args="[dlv attach 30579 --listen=127.0.0.1:0 --accept-multiclient=true --headless --log]" cmd="&{/gopath/bin/dlv [dlv attach 30579 --listen=127.0.0.1:0 --accept-multiclient=true --headless --log] []  <nil> 0xc00000c020 0xc00000c028 []
<nil> <nil> <nil> <nil> <nil> false [] [] [] [] <nil> <nil>}"
time="2018-10-04T14:14:04Z" level=debug msg="starting headless dlv for user started, trying to get port"
2018/10/04 14:14:04 server.go:73: Using API v1
2018/10/04 14:14:04 debugger.go:69: attaching to pid 30579
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0xf0 pc=0x628174]

goroutine 1 [running]:
github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf.(*Reader).Seek(0xc4200945a0, 0xc400000000)
        /gopath/src/github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf/entry.go:308 +0x354
github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf.(*Data).Reader(0x0, 0xc42010f6d8)
        /gopath/src/github.com/derekparker/delve/vendor/golang.org/x/debug/dwarf/entry.go:291 +0x5f
github.com/derekparker/delve/pkg/dwarf/reader.New(0x0, 0x9e1098)
        /gopath/src/github.com/derekparker/delve/pkg/dwarf/reader/reader.go:18 +0x2f
github.com/derekparker/delve/pkg/proc.(*BinaryInfo).DwarfReader(0xc4200729a0, 0x1)
        /gopath/src/github.com/derekparker/delve/pkg/proc/bininfo.go:83 +0x2f
github.com/derekparker/delve/pkg/proc.(*EvalScope).DwarfReader(0xc4201076b0, 0x1a9f73bb951)
        /gopath/src/github.com/derekparker/delve/pkg/proc/variables.go:325 +0x2f
github.com/derekparker/delve/pkg/proc.(*EvalScope).packageVarAddr(0xc4201076b0, 0xa02f3f, 0x14, 0x7fd87d7c2060, 0xc42004cf00, 0x7790)
        /gopath/src/github.com/derekparker/delve/pkg/proc/variables.go:649 +0x40
github.com/derekparker/delve/pkg/proc.GetGoInformation(0xc76840, 0xc4200729a0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
        /gopath/src/github.com/derekparker/delve/pkg/proc/proc.go:406 +0x178
github.com/derekparker/delve/pkg/proc/native.initializeDebugProcess(0xc4200729a0, 0x0, 0x0, 0x1, 0x40, 0xcb29e0, 0xc62fdb)
        /gopath/src/github.com/derekparker/delve/pkg/proc/native/proc.go:404 +0x10a
github.com/derekparker/delve/pkg/proc/native.Attach(0x7773, 0x7, 0x9f9050, 0x7)
        /gopath/src/github.com/derekparker/delve/pkg/proc/native/proc_linux.go:81 +0x50
github.com/derekparker/delve/service/debugger.(*Debugger).Attach(0xc4200e1820, 0x7773, 0x0, 0x0, 0x1, 0x4105b2, 0xc42010fad0, 0x48)
        /gopath/src/github.com/derekparker/delve/service/debugger/debugger.go:150 +0x19d
github.com/derekparker/delve/service/debugger.New(0xc42004ceb0, 0xc42004ceb0, 0xc42010fb18, 0x410e08)
        /gopath/src/github.com/derekparker/delve/service/debugger/debugger.go:74 +0x74e
github.com/derekparker/delve/service/rpccommon.(*ServerImpl).Run(0xc42004ce60, 0xc420011501, 0xc42004ce60)
        /gopath/src/github.com/derekparker/delve/service/rpccommon/server.go:119 +0x12d
github.com/derekparker/delve/cmd/dlv/cmds.execute(0x7773, 0xc42004ce20, 0x0, 0x4, 0xc4200e12a0, 0x0, 0x0, 0x2, 0x0)
        /gopath/src/github.com/derekparker/delve/cmd/dlv/cmds/commands.go:476 +0x2bd
github.com/derekparker/delve/cmd/dlv/cmds.attachCmd(0xc420112000, 0xc42004ce10, 0x1, 0x5)
        /gopath/src/github.com/derekparker/delve/cmd/dlv/cmds/commands.go:397 +0xd7
github.com/derekparker/delve/vendor/github.com/spf13/cobra.(*Command).execute(0xc420112000, 0xc42004cc80, 0x5, 0x5, 0xc420112000, 0xc42004cc80)
        /gopath/src/github.com/derekparker/delve/vendor/github.com/spf13/cobra/command.go:647 +0x234
github.com/derekparker/delve/vendor/github.com/spf13/cobra.(*Command).ExecuteC(0xc4200a9d40, 0xc420112480, 0xc420112240, 0xc420112000)
        /gopath/src/github.com/derekparker/delve/vendor/github.com/spf13/cobra/command.go:733 +0x339
github.com/derekparker/delve/vendor/github.com/spf13/cobra.(*Command).Execute(0xc4200a9d40, 0xc4200001a0, 0xc4200001a0)
        /gopath/src/github.com/derekparker/delve/vendor/github.com/spf13/cobra/command.go:692 +0x2b
main.main()
        /gopath/src/github.com/derekparker/delve/cmd/dlv/main.go:13 +0x55
time="2018-10-04T14:14:06Z" level=debug msg="got netlink msg" msg="{{20 3 2 3 5625} [0 0 0 0]}"
time="2018-10-04T14:14:06Z" level=debug msg="GetSocketInodesFor: got listeningsokcets" inoddedPorts="[]" pid=30829
time="2018-10-04T14:14:06Z" level=debug msg="GetSocketInodesFor: got sockets for pid" pid=30829 sockets="[]"
time="2018-10-04T14:14:06Z" level=error msg="can't get port for pid" err="<nil>" pid=30829 ports="[]"
time="2018-10-04T14:14:06Z" level=error msg="can't get headless dlv port" err="Number of ports is zero"
time="2018-10-04T14:14:06Z" level=error msg="Starting debug server error" err="Number of ports is zero"
time="2018-10-04T14:14:06Z" level=debug msg="Notifying server of attachment to debug config object" DebugAttachmentID=77rUpTDb4S patchDebugAttachment="&{0xc000536320 0xc000070f60 0xc000536360}"
time="2018-10-04T14:14:06Z" level=info msg="debug attachment notified of attachment!"
time="2018-10-04T14:14:06Z" level=debug msg="getUpdatedSnapshots - filtering new attachments" attachments="(models.GetDebugAttachmentsOKBody) (len=1 cap=4) {\n (*models.DebugAttachment)(0xc00057a6a0)({\n  Metadata: (*models.ObjectMeta)(0xc00057a6c0)({\n   Name: (string) (len=10) \"77rUpTDb4S\",\n   Version: (string) \"\"\n  }),\n  Spec: (*models.DebugAttachmentSpec)(0xc0004f5f80)({\n   Attachment: (map[string]interface {}) (len=3) {\n    (string) (len=9) \"namespace\": (string) (len=7) \"default\",\n    (string) (len=3) \"pod\": (string) (len=29) \"example-microservice-rc-mcsl8\",\n    (string) (len=9) \"container\": (string) (len=20) \"example-microservice\"\n   },\n   Debugger: (string) (len=3) \"dlv\",\n   Image: (string) (len=22) \"kidlj/microservice:0.1\",\n   MatchRequest: (bool) false,\n   Node: (string) (len=4) \"kube\",\n   ProcessName: (string) \"\"\n  }),\n  Status: (*models.DebugAttachmentStatus)(0xc00057a6e0)({\n   DebugServerAddress: (string) \"\",\n   State: (string) (len=5) \"error\"\n  })\n })\n}\n"
time="2018-10-04T14:14:06Z" level=info msg="watchForAttached - got debug attachment!" deletedAttachments="([]*models.DebugAttachment) <nil>\n" newattachments="([]*models.DebugAttachment) <nil>\n"
time="2018-10-04T14:14:06Z" level=debug msg="watchForAttached - calling GetDebugAttachments" params="(*debugattachment.GetDebugAttachmentsParams)(0xc000580080)({\n XTimeout: (*float64)(<nil>),\n IfNoneMatch: (*string)(0xc0002ab7a0)((len=2) \"23\"),\n Names: ([]string) <nil>,\n Node: (*string)(0xc00042f190)((len=4) \"kube\"),\n State: (*string)(<nil>),\n States: ([]string) <nil>,\n Wait: (*bool)(0xc0004e53b3)(true),\n timeout: (time.Duration) 30s,\n Context: (context.Context) <nil>,\n HTTPClient: (*http.Client)(<nil>)\n})\n"