Cargo test and backtraces

#1

So, there have been a few requests to enable backtraces for cargo test by default. @alexcrichton and I were just having a bit of a discussion on #1634 and it seemed like it’d be better to move this discussion to a more public forum, so we can get a wider survey of opinions.

My basic feeling is that backtraces are pretty basic and we should make it easy for users to see them when a test fails. @alexcrichton righly points out that while many users have come to expect backtraces from VM-based languages, backtraces in a native environment are a different beast. And I agree with this. But I still think we want to print them, imperfect or no – otherwise, test failures tend to give you no clue as the context. Moreover, I find that as long as you pass -g, backtraces are quite reliable, even with optimization enabled – for example, at least on linux, they tell you what was inlined into what, and so forth.

One interesting point is that since we print backtraces on every panic, that sometimes includes “internal” panics where a backtrace printout is undesired. An example actually occurs within the execution of cargo test itself, I think, since the final backtrace that you see is basically an internal printout that derives from an error that will ultimately be handled. (Right?)

A middle-ground might be making backtraces more discoverable, e.g. via cargo test --backtrace. It seems to me though that adding an option makes it an order of magnitude less likely that people will find it, even if that option is prominently listed.

#2

I agree with Niko.

In practice, while we may want people to type RUST_BACKTRACE=1 so that they can learn, along the way, that it’s “not perfect”, that’s not what happens. Instead, people google “rust backtrace”, and find instructions for turning it on devoid of any kind of caveat, so it just ends up being an incantation you have to learn (a papercut).

#3

I’ve opened a PR to remove the one extraneous panic that I know about, but more generally my concern here is that we’ll get a bug report saying that “cargo test” printed a backtrace but running the binary manually did not. This kind of behavior can be quite surprising, especially when backtraces are also not printed out on cargo run or any other subcommand by default.

I 100% agree that backtraces are invaluable for debugging and we should certainly continue to improve them in the standard library! That being said I feel that having to learn about RUST_BACKTRACE, how it’s activated, and why it doesn’t show up by default is also a useful experience. After that the friction between throwing RUST_BACKTRACE=1 in front of a command seems relatively not-so-painful.

#4

At the very least having a flag like --backtrace would help, because it is a hassle temporarily setting environment variables sometimes (I’m looking at you powershell)

#5

Part of the googling it is because it’s not documented. Googling Rust issues hasn’t historically been very good so far anyway so I might not expect it would return anything useful.

Some people may not even realize a backtrace is possible making those issues problematic (for a long time I’d just insert random println!() statements to try to figure out where those errors came from because I didn’t realize there was a better way).

I would never have expected it would need an environmental variable. I would have thought it would go in the Cargo.toml because that’s how everything is already configured (though cargo --backtrace run perhaps makes more sense now).

Note: I’m not really trying to state an opinion as I don’t have a strong opinion about what it should be. I’m just noting what my expectations might be (even if they’re incorrect).

EDIT: Issue 27428 has since been fixed.

#6

I don’t have personally have a strong opinion on what the default should be, but I think it should be at least toggleable for now. A rather important use case for QuickCheck is to be able to witness test failures resulting from a panic. AFAIK, there’s no way to suppress the output of a child thread, so the panic is emitted to stderr. This isn’t too bad now because it’s only one line, but if a backtrace was emitted, it would clutter up the terminal pretty quickly.

#7

As I have just noted in the aforementioned issue I see another option here. You know, I have some very nice Perl background, and no matter what you think about Perl itself, there are a lot of things made right in it, or at least in its famous CPAN. What I’d like to point to is Carp module, which tries to make error messages really helpful by pointing to error in user’s codebase, not in a some part of “trusted” code in third party libs or standard lib. It does so by unwinding stack trace up to the point where it goes out of “trusted” code. In case of Rust it can just mean std (or std and libs current main crate depends on — as a second step). This way using this algo panic!() would point not to some random point of panic call site inside std, but to the point in your code where the error was originated from. I know problems with unwinding the call stack, but hey, it’s already here with RUST_BACKTRACE, so why not make another step to users to make errors even more friendly?

#8

Since backtraces are currently completely devoid of content (just a long string of meaningless hexadecimal addresses) on mingw64, force-enabling them would be worse than useless to me for the time being. Until #20351 is fixed, and assuming backtraces are enabled by default at all, please exclude Windows from it.

#9

Lots of interesting stuff here. Some thoughts:

Yeah, we may, and I imagine we’d close them with an explanation. But right now we’re getting bug reports saying “give me my backtraces!” Win some, lose some. In any case, it seems reasonable to expect that “unit test mode” behaves a bit differently, so you may find people are a bit less surprised than you think. Still, an interesting point.

I’m not sure about this. A lot of people may not be familiar with environment variables – or even the command line! Or there may be using environments where this is awkward. But mostly it’s a matter of discoverability: how do you know to write RUST_BACKTRACE=1, or even that such an option is available? If you google, you can find out, but you may just assume “rust is immature” and not look further.

Definitely. @rkruppe gave another scenario too.

This seems reasonable, but I personally actually really like getting traces into libstd. It’s not because I’m a core Rust hacker – after all, the stdlib is kind of a black box to me these days – but because when I’m trying to figure out what I did wrong, it’s great to be able to read the code. When using the JVM, for example, I would often download the sources to the JDK so that I could get the same experience there (similarly elisp etc). In any case, though, this seems like an orthogonal sugggestion – that is, we could improve the output of RUST_BACKTRACE (and perhaps you could signal whether you “trust” libstd or not) but in the end the question is whether it is on by default in any form whatsoever.

#10

Also, setting environment variables is not as simple in most Windows shells. (I have to look it up everytime I need to do so).

#11

My point is, most times I get panic, it’s because of some unwrap() call, and tells me something like “line 123 in option.rs” or something, which tells me nothing about real reason of the panic. What I really need to know is where the offensing unwrap call in my code is. If the message pointed to my code I wouldn’t need any backtraces 9 times out of 10 at all.

#12

@kstep the thing is, at least for me, often knowing the immediate caller in my code isn’t that useful, because it too is a generic helper function that’s not really at fault: I want to know about the caller’s caller (or grandcaller, or whatever). In other words, a backtrace gives me all the context I could want.

#13

In powershell I have to do $env:RUST_BACKTRACE = 1 separately and then I have no idea how to unset it.

#14

$Env:RUST_BACKTRACE='' should do it.

AFAIK, neither cmd or PowerShell have any kind of “set an environment variable for this command” shortcut, however. A more painful one is RUST_LOG: cargo build, set it, run manually, then manually un-set it so that it isn’t set for the next compile.

#15

This might be a silly question but what’s wrong with unconditionally enabling a full backtrace? Python, Ruby or Java developers don’t usually complain about lengthy backtraces on the terminal.

#16

Just a thought: this also becomes an issue if you have flaky tests, i.e. ones that work 99% of the time and then fail. Not having the stack trace printed by default in those cases would often be quite a pain, since it might be nigh on impossible to reproduce locally (or once you’ve enabled backtraces).

#17

I’m surprised that running test binaries manually is a thing. I wouldn’t expect it to be a supported at all. In other languages running tests without the test harness is obviously unsupported.

I guess that people who run the tests outside cargo do it to run them under a debugger? In that case they’d get better backtrace from the debugger, so it doesn’t seem like a problem to me.

That assumption doesn’t hold in my case. I haven’t learned about it. I don’t know where to even look for its documentation. I don’t know what the caveats are.

I just run Cargo, and it tells me “note: Run with RUST_BACKTRACE=1 for a backtrace.”, so I run the command again. From my perspective it feels like Cargo knows how to show me helpful information, but chooses not to.

#18

Well, this is true here as well, but it harness is compiled into the binary.

#19

I was trying to say that my mental model is that cargo test is the testing tool itself, and not a transparent wrapper or a launcher for some other standalone testing tool. Therefore, it wouldn’t be a surprise to me that bypassing Cargo and running tests without it didn’t have all the features of cargo test.