Debugging golang programs

I’ve been writing a lot of golang lately. I’ve hit painful problems in the past. Here are some debugging tips. Hopefully they help you out. I bet you don’t know #2.

#0 Use log.Printf:

This should go without saying, but I’m ashamed to say it’s what I use the most. We’ve only been C programming for 44+ years, and it’s still what is most useful!

#1 Use go run -race:

Since many problems are caused by random races, ensuring you use the built-in tools will help you catch some problems. One of these is a race detector. You can use it by adding the -race flag to the go run, go build or go test commands. In practice, it only ever caught beginner issues, and it hasn’t set off any alarms since. Maybe I need to write more test cases! Maybe you need to write more test cases!

#2 Use Control+Backslash:

Say what? If you press control+backslash, you will cause a core dump. Example:

james@computer:/tmp$ sleep 42h
^\Quit (core dumped)

Obviously there are nicer ways to kill a process (I for one, welcome our robotic overlords) but in times of emergency, use what you’ve got. The interesting thing, is that when you do this to a golang program, you’ll get much more interesting output:

james@computer:~/code/mgmt$ ./mgmt run --file examples/graph0.yaml 
16:19:26 main.go:65: This is: mgmt, version: 0.0.2-6-g6e68d6d
16:19:26 main.go:66: Main: Start: 1455571166809588335
16:19:26 main.go:196: Main: Running...
16:19:26 main.go:106: Etcd: Starting...
16:19:26 etcd.go:132: Etcd: Watching...
16:19:26 configwatch.go:54: Watching: examples/graph0.yaml
16:19:26 etcd.go:159: Etcd: Waiting 1000 ms for connection...
16:19:26 main.go:149: Graph: Vertices(2), Edges(1)
16:19:26 main.go:152: Graphviz: No filename given!
16:19:26 main.go:163: State: graphNil -> graphStarting
16:19:26 main.go:165: State: graphStarting -> graphStarted
16:19:26 file.go:340: File[file1]: Apply
^\SIGQUIT: quit
PC=0x482a53 m=2

goroutine 0 [idle]:
runtime.futex(0xecae00, 0x0, 0x7f6f5dd8fde8, 0x0, 0x0, 0x4828ac, 0x3c, 0x0, 0x43392b, 0xecae00, ...)
    /usr/lib/golang/src/runtime/sys_linux_amd64.s:289 +0x23
runtime.futexsleep(0xecae00, 0x0, 0xdf8475800)
    /usr/lib/golang/src/runtime/os1_linux.go:56 +0xf0
runtime.notetsleep_internal(0xecae00, 0xdf8475800, 0xc820000900)
    /usr/lib/golang/src/runtime/lock_futex.go:171 +0x12b
runtime.notetsleep(0xecae00, 0xdf8475800, 0x0)
    /usr/lib/golang/src/runtime/lock_futex.go:191 +0x6b
    /usr/lib/golang/src/runtime/proc1.go:3022 +0x4aa
    /usr/lib/golang/src/runtime/proc1.go:715 +0xe8
    /usr/lib/golang/src/runtime/proc1.go:685 +0x72

goroutine 1 [select]:
    /home/james/code/mgmt/main.go:48 +0x5da
    /home/james/code/mgmt/main.go:198 +0x779, 0x3, 0x0, 0x0, 0xc8200799d0, 0x1, 0x1, 0xb4e9d8, 0x3, 0x0, ...)
    /home/james/code/src/gopath/src/ +0x1052*App).Run(0xc8200a8500, 0xc820074100, 0x4, 0x4, 0x0, 0x0)
    /home/james/code/src/gopath/src/ +0xc2f
    /home/james/code/mgmt/main.go:283 +0xced

goroutine 17 [syscall, locked to thread]:
    /usr/lib/golang/src/runtime/asm_amd64.s:1721 +0x1

goroutine 21 [syscall]:
    /usr/lib/golang/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
    /usr/lib/golang/src/os/signal/signal_unix.go:28 +0x37

goroutine 22 [select]:, 0xc820122040, 0xc82011a5d0, 0xc82011e130, 0x5, 0xc820076360, 0xc82011e010)
    /home/james/code/mgmt/main.go:110 +0x1061
created by
    /home/james/code/mgmt/main.go:168 +0x60c

goroutine 23 [select, locked to thread]:
runtime.gopark(0xc8a258, 0xc82002e728, 0xb4ec08, 0x6, 0x18, 0x2)
    /usr/lib/golang/src/runtime/proc.go:185 +0x163
runtime.selectgoImpl(0xc82002e728, 0x0, 0x18)
    /usr/lib/golang/src/runtime/select.go:392 +0xa64
    /usr/lib/golang/src/runtime/select.go:212 +0x12
    /usr/lib/golang/src/runtime/signal1_unix.go:227 +0x353
    /usr/lib/golang/src/runtime/asm_amd64.s:1721 +0x1

goroutine 7 [select]:
    /home/james/code/mgmt/file.go:156 +0x15f4
main.(*Graph).Start.func1(0xc82011e010, 0xc820010b80)
    /home/james/code/mgmt/pgraph.go:558 +0x7e
created by main.(*Graph).Start
    /home/james/code/mgmt/pgraph.go:560 +0x171

goroutine 25 [select]:
main.ConfigWatch.func1(0xc82009db40, 0x14, 0xc820076660)
    /home/james/code/mgmt/configwatch.go:74 +0x13c8
created by main.ConfigWatch
    /home/james/code/mgmt/configwatch.go:153 +0x67

goroutine 26 [sleep]:
    /usr/lib/golang/src/runtime/time.go:59 +0xf9
main.(*EtcdWObject).EtcdWatch.func1(0x7f6f5c512c20, 0xc82009db80, 0xc820122040, 0xffffffffffffffff, 0xc820076360, 0xc820072af0)
    /home/james/code/mgmt/etcd.go:160 +0x7db
created by main.(*EtcdWObject).EtcdWatch
    /home/james/code/mgmt/etcd.go:205 +0xc2

goroutine 27 [chan send]:
main.(*EtcdWObject).EtcdChannelWatch.func1(0x7f6f5c512c78, 0xc820122140, 0x7f6f5c512ca0, 0xc8200786d0, 0xc8200766c0)
    /home/james/code/mgmt/etcd.go:109 +0xd9
created by main.(*EtcdWObject).EtcdChannelWatch
    /home/james/code/mgmt/etcd.go:111 +0x7b

goroutine 34 [syscall]:
syscall.Syscall6(0xe8, 0x4, 0xc82018dc24, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x0, 0x0, 0x0)
    /usr/lib/golang/src/syscall/asm_linux_amd64.s:44 +0x5
syscall.EpollWait(0x4, 0xc82018dc24, 0x7, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0x0)
    /usr/lib/golang/src/syscall/zsyscall_linux_amd64.go:365 +0x89*fdPoller).wait(0xc820146000, 0xc89a00, 0x0, 0x0)
    /home/james/code/src/gopath/src/ +0xbc*Watcher).readEvents(0xc820158000)
    /home/james/code/src/gopath/src/ +0x1af
created by
    /home/james/code/src/gopath/src/ +0x315

goroutine 8 [select]:
    /home/james/code/mgmt/types.go:362 +0x31a
main.(*Graph).Start.func1(0xc82011e010, 0xc820010b60)
    /home/james/code/mgmt/pgraph.go:558 +0x7e
created by main.(*Graph).Start
    /home/james/code/mgmt/pgraph.go:560 +0x171

goroutine 31 [syscall]:
syscall.Syscall6(0xe8, 0x9, 0xc8201f7c24, 0x7, 0xffffffffffffffff, 0x0, 0x0, 0xc82017c440, 0xc82017c420, 0x15)
    /usr/lib/golang/src/syscall/asm_linux_amd64.s:44 +0x5
syscall.EpollWait(0x9, 0xc8201f7c24, 0x7, 0x7, 0xffffffffffffffff, 0x1, 0x0, 0x0)
    /usr/lib/golang/src/syscall/zsyscall_linux_amd64.go:365 +0x89*fdPoller).wait(0xc82009dcc0, 0x8000, 0x0, 0x0)
    /home/james/code/src/gopath/src/ +0xbc*Watcher).readEvents(0xc820090cd0)
    /home/james/code/src/gopath/src/ +0x1af
created by
    /home/james/code/src/gopath/src/ +0x315

rax    0xfffffffffffffffc
rbx    0x7f6f5dd8fde8
rcx    0x482a53
rdx    0x0
rdi    0xecae00
rsi    0x0
rbp    0x0
rsp    0x7f6f5dd8fdb0
r8     0x0
r9     0x0
r10    0x7f6f5dd8fde8
r11    0x246
r12    0x7ffec7010a4f
r13    0x7f6f5dd90700
r14    0x800000
r15    0x0
rip    0x482a53
rflags 0x246
cs     0x33
fs     0x0
gs     0x0

I find this particularly useful when you have a “stuck” goroutine. Killing the program usually makes it easy to find where everyone was waiting. AFAIK, everything is ordered by most recently used at the top. You’re welcome!

#3 Use a real debugger:

There is a GDB like golang debugger called “delve”. It’s probably something I would use more often, except I haven’t needed that much power, and it still has a number of rough edges. I’m sure if you could help improve that, it would help out the project. There was a talk at FOSDEM about it. If we’re lucky, we’ll eventually get video. I’m “looking forward” to using it more in the future.

Hope this helped,

Happy Hacking!


PS: The “other” slash, isn’t called “forward slash”, it’s just called “slash”

PPS: Yes, I say “golang”, no “go”. I think it’s shitty that google basically ripped off the go! name. I guess David lost this one.

You can follow James on Mastodon for more frequent updates and other random thoughts.
You can follow James on Twitter for more frequent updates and other random thoughts.
You can support James on GitHub if you'd like to help sustain this kind of content.
You can support James on Patreon if you'd like to help sustain this kind of content.


Nothing yet.

Post a comment

(sorry but the spammers were getting too crazy!)

Thank you

Your comment has been submitted and will be published if it gets approved.

Click here to see the patch you generated.