Debugging Rust

name: inverse
layout: true
class: center, middle, inverse
---
background-image: url(bugs.jpg)

# Debugging & Rust

.left[.footnote[[*] bug screenshot courtesy of Assasin's Creed]]
???

---
layout: false

# Overview

* Printing and logging
* Panic and backtraces
* Symbols and debuggers
* Debugging in reverse

---
template: inverse
background-image: url(printing.jpg)

# Printing & Logging

---

# println!

Implement `Debug` trait on your types

```rust
// debug.rs
#[derive(Debug)]
struct Foo {
    x: i32, y: i32
}
fn main() {
    let foo = Foo { x: 1, y: 2 };
    //println!("{}, foo); // needs core::fmt::Display trait
    println!("{:?}", foo);
    println!("{:#?}", foo);
}
```

```bash
$ rustc -g debug.rs && ./debug
Foo { x: 1, y: 2 }
Foo {
    x: 1,
    y: 2
}
```

---

# Scaling up

* `println!` debugging doesn't scale
* Compile time slows iteration
* Time to trigger bug again slows iteration
* With many developers:
  * Starts to clutter code
  * Starts to impact performance
  * Too much noise

---

# Logging

* Log crate on [crates.io](https://crates.io/crates/log/)
* Now in Rust Nursery
* Provides logging macros `error!`, `warn!`, `info!`, `debug!` and `trace!`
* Can filter out noise
* Too much logging:
  * Code clutter
  * Performance impact?

---
template: inverse
background-image: url(dont-panic.jpg)

---

# panic! and assert!

* `panic!` and `assert!` for when unexpected conditions happen
* std libary functions may panic

```rust
// panic.rs
fn diverges() -> ! {
  panic!("This function never returns!");
}

fn main() {
  diverges()
}
```

```bash
$ rustc -g panic.rs && ./panic
thread '<main>' panicked at 'This function never returns!', panic.rs:2
```

---

# RUST_BACKTRACE=1

```bash
$ RUST_BACKTRACE=1 ./panic
thread '<main>' panicked at 'This function never returns!', panic.rs:2
stack backtrace:
   1:     0x5610c0a95f10 - sys::backtrace::tracing::imp::write::haa19c02b4de52f3bG0t
   2:     0x5610c0a98045 - panicking::log_panic::_<closure>::closure.41218
   3:     0x5610c0a97ac0 - panicking::log_panic::h527fe484e9de8fe1W7x
   4:     0x5610c0a92353 - sys_common::unwind::begin_unwind_inner::h51f64b1a34c60827fTs
   5:     0x5610c0a917b7 - sys_common::unwind::begin_unwind::begin_unwind::h13337723494083387990
                        at ../src/libstd/sys/common/unwind/mod.rs:237
   6:     0x5610c0a91739 - diverges::hef6e339f7749a66feaa
                        at /home/cam/<std macros>:3
   7:     0x5610c0a918e8 - main::h9f863a2aaf425a0fBaa
                        at /home/cam/panic.rs:5
   8:     0x5610c0a97864 - sys_common::unwind::try::try_fn::h11901883998771707766
   9:     0x5610c0a953b8 - __rust_try
  10:     0x5610c0a97506 - rt::lang_start::hc150f651dd2af18b44x
  11:     0x5610c0a91929 - main
  12:     0x7fd1e58d6a3f - __libc_start_main
  13:     0x5610c0a915f8 - _start
  14:                0x0 - <unknown>
```

???

Backtraces not enabled by default
Compile with rustc -g for source line numbers. 
Cargo build defaults to debug profile with -g by default
Discussion about if this should be on by default in cargo test https://internals.rust-lang.org/t/cargo-test-and-backtraces/2518/9

---
template: inverse
background-image: url(debugging.jpg)

# Debugging

???

---

# Symbols

* Debuggers need symbols
* Enable with `rustc -g`
* Or `cargo` profiles
* Also, backtraces need symbols for source line numbers

```ini
# The development profile, used for `cargo build`
[profile.dev]
opt-level = 0  # Controls the --opt-level the compiler builds with
debug = true   # Controls whether the compiler passes `-g`

# The release profile, used for `cargo build --release`
[profile.release]
opt-level = 3
debug = false
```

???

My work projects always generate symbols for release - crashes happen in release!

---

# rust-gdb and rust-lldb

* GDB and LLDB aren't Rust aware
* Rust provides `rust-gdb` and `rust-lldb` wrappers
* These add pretty printing for some Rust types

---

# Pretty printing

A trivial Rust program

```rust
// pretty.rs
const COLORS: [&'static str;7] =
  ["red", "yellow", "pink", "green", "purple", "orange", "blue"];

struct Label {
    index: usize,
    color: &'static str
}

fn main() {
    // create a Vec of Label
    let labels: Vec<Label> = (0..10).map(|i| {
        Label { index: i, color: COLORS[i % COLORS.len()] }
      }).collect();
    // print them
    for label in labels {
        println!("{}: {}", label.index, label.color);
    }
}
```

---

# Pretty output

```bash
$ ./pretty 
0: red
1: yellow
2: pink
3: green
4: purple
5: orange
6: blue
7: red
8: yellow
9: pink
```

---

# GDB

```bash
$ gdb -q ./pretty
Reading symbols from ./pretty...done.
warning: Missing auto-load script at offset 0 in section
.debug_gdb_scripts of file /home/cam/pretty.
Use `info auto-load python-scripts [REGEXP]' to list them.
```

Pay attention to that warning!

```bash
(gdb) b 14
Breakpoint 1 at 0x4d1f: file pretty.rs, line 14.
(gdb) r
Starting program: /home/cam/pretty

Breakpoint 1, pretty::main () at pretty.rs:14
14	        println!("{}: {}", label.index, label.color);
(gdb) p label
$1 = {index = 0, color = {
    data_ptr = 0x55555559155c <str4488> 
        "redyellowpinkgreenpurpleorangebluepretty.rs: \n", 
    length = 3}}
```

???

OK, what does that all mean!?
GDB isn't Rust aware
Rust appears to compile gdb scripts into the elf!

---

# Rust GDB

This time, use the `rust-gdb` wrapper

```bash
$ rust-gdb -q ./pretty
Reading symbols from ./pretty...done.
(gdb) b 14
Breakpoint 1 at 0x4d1f: file pretty.rs, line 14.
(gdb) r
Starting program: /home/cam/pretty

Breakpoint 1, pretty::main () at pretty.rs:14
14	        println!("{}: {}", label.index, label.color);
(gdb) p label
$1 = Label = {index = 0, color = "red"}
```

That's better!

???

rust-gdb sets up some module paths for Rust's gdb pretty printing python scripts.
There are some limitations though.
There's a similar wrapper for lldb

---

# Crash Scene Investigation

An example of a hard to trace bug:

* Main thread generates draw commands
* Render thread processes draw commands
* A particular draw command executes callbacks to run 3rd party code
* A few crash reports with differents crashes inside callback
* Looks like callback is pointing to deleted data
  * Data race - callback data didn't live long enough
* OK, but when was it deleted? Some time ago on a different thread...

Note: this example is from C++ project, one of the reasons I'm excited about Rust is I hope to see the back of these kinds of bugs!

???

Bugs don't need to be quite so exotic for rr to be useful

---
template: inverse
background-image: url(cctv.jpg)

# Record & Replay

---

# Wouldn't it be great...

* If you could run the program in reverse
* And step back to the cause of a problem

---

# Introducing rr

* [rr-project.org](http://rr-project.org/)
* Record trace with rr
* Playback trace in gdb
* Stop at some problem point
* Step backwards to see how it happened

---

# What is this magic?

* Replay must be the same every time
* Most code is deterministic
* rr records the non-deterministic parts
  * e.g. clock_gettime(), rtdsc, file read()
* Replay emulates these calls by playing back recorded state

???

If you saw the talk at LCA2016 this was discussed in a lot more detail
This process is common for graphics debuggers like RenderDoc, but the scope is much larger

---

# Limitations of rr

* Only Linux on Intel supported
* Requires Linux kernel > 3.4
* Requires specific Intel CPU features (> Nahelem)
* Unlikely to happen on Windows or Mac
* Some syscalls not supported
* No parallelism (not deterministic)
* Didn't like my NVIDIA GPU drivers, Intel OK
  * use `LIBGL_ALWAYS_SOFTWARE=1` for OpenGL applications

???

See LCA talk and other rr internals talks for more detail

---

# Quick example

```rust
println!("Guess the number!");
loop {
    println!("Please input your guess.");
    let guess = read_guess();
    println!("You guessed: {}", guess);
    match guess.cmp(&secret_number) {
        Ordering::Less    => println!("Too small!"),
        Ordering::Greater => println!("Too big!"),
        Ordering::Equal   => {
            println!("You win!");
            break;
        }
    }
}
```

```bash
$ rr record ./guess
rr: Saving the execution of `./guess' to trace directory `/home/cam/.rr/guess-0'.
```

---

# Quick example

```bash
$ rr replay -d rust-gdb ~/.rr/guess-0

(rr) c
Continuing.
Guess the number!
Please input your guess.
You guessed: 94
Too big!
Please input your guess.
You guessed: 92
Too small!
Please input your guess.
You guessed: 93
You win!

Program received signal SIGKILL, Killed.
0x0000000070000002 in ?? ()
```

Note the `-d rust-gdb` to use the Rust gdb wrapper.

???

Playback is deterministic, the numbers are always the same

---

# Quick example

```bash
(rr) b 28
Breakpoint 1 at 0x55872d5a51eb: file guess.rs, line 28.
(rr) rc
Continuing.

Breakpoint 1, guess::main () at guess.rs:28
28	        match guess.cmp(&secret_number) {
(rr) p guess
$1 = 93
(rr) rc
Continuing.

Breakpoint 1, guess::main () at guess.rs:28
28	        match guess.cmp(&secret_number) {
(rr) p guess
$2 = 92
```

Use reverse version of gdb commands; `rc`, `rn`, `rs`.

???

Can step back and inspect earlier state

---
template: inverse
background-image: url(questions.jpg)

# Questions?

???

# References

* [Huon's rreverrse debugging blog post](https://huonw.github.io/blog/2015/10/rreverse-debugging/)
* [rr project site](http://rr-project.org/)
* [A Firefox developer on debugging with rr](http://fitzgeraldnick.com/weblog/64/)
* [How rr works presentation](https://mozilla.github.io/rr/rr.html)
* [Record and replay with rr LCA2016 talk](https://youtu.be/4hSIrjL7IR8)