Skip to main content

13 Debugging: How to Interpret a Stacktrace

Episode 198 · July 17, 2017

Learn how to analyze and understand the Ruby stacktrace when something goes wrong in your app

Debugging


Transcripts

What's up guys? This episode I want to talk about debugging and specifically reading and interpreting the stacktrace in your ruby program, so any time you have an error, you get the error message appear, you get the class name of the error and this get this giant blob of text that is the stacktrace, and so all these lines that you see right here are the stack trace and those are actually far far more important than you might expect, so I wanted to talk about this because a lot of people will send errors on Stackoverflow or to me via email or on Slack or whatever and they will just grab this part at the top, and so they will just grab the message and the class and say: Hey, I got this error, how can you fix this and that is never enough information or it's rarely enough information to understand exactly what is going on and so you need to also include the stacktrace here. If we looked at this error, we would see "NoMethodError" and we added something to a symbol? probably? And we don't really understand what was it trying to add, what was the symbol or any of this stuff and we don't really understand what was the intent of the code because we just get this error that's very very vague, and we know that we can't add things to symbols and so we're trying to figure out why was it trying to add something to a symbol in the first place?

Let's take a look at our stacktrace here. This first line here starts with actionpack(3.2.8), which actually tells us which rails version or which version of actionpack that we're using so if we wanted to we could look into that on GitHub and we could find the code for this, and so the next piece for this shows us what file it is, it's lib/actioncontroller/metal/data_streaming.rb and then a colon and 125, and 125 is the line number for that in a method called send_file_headers! This is telling us that inside of this gem version 3.2.8 we ran this file on line 125, we were in this function and this is where our code crashed. This top line is always where our code crashed. We know then that the code actually crashed inside of rails and actionpack and it wasn't actually our code which is interesting. That tells us that we probably gave rails some bad method parameters and we passed in information that didn't work, and so then rails didn't know what to do with it and just blew up and gave us an error. That tells us then that we should probably look for the last line of code that we wrote to figure out what we passed into rails and maybe what we did wrong, so if we go into app/controllers/charges_controller.rb. This line here we can see is one that we wrote because it's in app/controllers and it's not in a gem as you can see there's no gem name and version at the beginning and so this is the line of code that we last ran before it blew up in rails and we can see here in charges_controller.rb line 13 inside a block and show that's where it crashed last running our code, so let's take a look at that code. This is line number 13, I've split it up in multiple lines, but we call send_data which is a rails method that you can pass in some content and then it will give a file in the browser back so you can have it set up something like this to render out a PDF and give it a name and then a type so it knows that it's a PDF and then you can do this position in line or attachment I believe so you can either have the PFD rendered in the browser or force downloaded by the browser, and so this is our help send that PDF down. This we can assume was working pretty well because it actually called this method so we know that this charge receipt render was correct. We also know that this charge.id ran and so it would have give a file name and some sort of rendered receipt to the method because it crashed inside so if this was to air out we would actually see a different error that we would actually understand probably a little bit more, so we didn't do anything with adding two symbols here, so we know that it really wasn't our code that went wrong and really the only symbol that we passed in was this disposition: :inline so maybe that has something to do with it. We don't really understand what's wrong with our code, it seems like we passed in everything correctly, so then the logical next step it let's take a look at the send_data method and check out the docs and see what it says and make sure that we're passing in the proper content and the file name and the type and the disposition. Make sure that that's all correct. If we take a look at the actionpack data_streaming, this send_data method here, we can click on that and see the docs here and this is going to tell us basically how it works, and the only thing that we notice is that disposition is a string here and we're passing in a symbol. Now ruby usually treats symbols and strings as exactly the same and because this code was pulled from a screencast of mine, we know that the symbol version of it did work, so we can kind of assume that: Yeah, they used a symbol here but a symbol should still work so there's something else going wrong and none of the other stuff really tells us what's wrong, so we know we're passing in content and the type is being set and we're setting the filename, so this doesn't really help us out too much, but it does maybe hint that something may be wrong with the disposition, like for example maybe they're not allowing symbols, and we know that if we look at this code, they were using rails 3.2.8, so if we wanted to we can then dive into this line of code and check out the file at line 125 and figure out what's going on there inside of this send_file_headers method.

The easy way to do this is to open up the rails repository in GitHub, and then open up the proper tag for your rails version. Now unfortunately this is an old rails app, so if we look at the tag section, they have a tag for every single release that they've made except they only have tags going back to 4.0, so they don't have one for 3.2.8 unfortunately, and if we look at branches, we do get a 3.2-stable, so we can click on that and this will pull up the code for the very most recent version of 3.2, so this is what we're going to look at and we need to go into actionpack because we know that's where it ran lib/actioncontroller/metal/data_streaming.rb and we're looking for line 125 which should be inside the send_file_headers method. Let's go down to line 125, highlight that and weirdly it's inside of a comment, so chances are this code has changed a bit because this is not referencing real code and of course out code cannot crash inside of a comment, so chances are this has been modified between our version of 3.2.8 and the latest version of 3.2 that we're reading here. Now if we look a little bit further down, we see that send_file_headers! method, and this is like 11 lines of code off, and that's going to tell us that they're probably adding some different pieces up above which pushed our send_file_headers! method down and I'm not really sure where this is going to be but we can pay attention to this and just kind of read through it and see what it's doing.

It's taking some options and those appear to be the options that we passed in. Here it's looking for type, and disposition and as you've noticed, we've passed in file name type and disposition so it's kind of reading those and saying: If you passed in type, it will raise an error, I don't really care that doesn't seem to be adding to a symbol, and if we look at this, the next part we see is while it is adding to the disposition here except it's converting that disposition to a string which is what we expected because in my code it was converting the symbol properly in the screencast that this code was taken from and this options dispositions is converted into a string so this addition should work successfully but this kind of points out that we're using an older version of rails and maybe it wasn't always converting to a string, so the thing that you can use here is the blame method in Git, and blame is going to then show you which commit is responsible for the code that you see in the file currently. If we go back down to this and we look for that line of code here where we convert it to a string, we can click on that and see that five years ago, this was added to accept symbols as send_data disposition value and that's pretty cool, so we know when this function got added to accept symbols, and we can see here that the test accepted a disposition as a symbol and it's testing all of that, but notice here that our rails version that that was released on is 3.2.10 and so this tells us now that we are using an outdated version of rails which is actually not supporting that symbol version of the disposition, so that's pretty interesting. What's really interesting about this is that the stacktrace tells you a story of what happened, and by looking at the last line of code that we ran, we can take a look at that, make sure it looks correct and then we can take a look at what the gem was trying to do in our case it was the rails actionpack gem, and we can look at that code and say: Well what is it trying to do and did we pass in the correct information? and when it looked like we did, we could use git blame to figure out what were they trying to do, and we can see here that while the send disposition as a symbol is now added in 3.2 which we stumbled into, and we never would have known had we not looked at the source code of rails to figure that out, so it's really interesting to see that, so anytime that you get an error in ruby, you will now know that this error in the message are not really the most important thing. You need to understand them and say: Well it was blowing up in this kind of way, but you're trying to figure out where that came from and the way to do that is to read the story of your code which is the stacktrace. So anytime you ask someone else for help, make sure you include the entire stacktrace so that they can look at it and ask you questions.

That's about it. Debugging and reading your stacktrace isn't as daunting as you might think it is but you'll always need that information to properly walk through what happened and figure out whats wrong and so this is a quick process that you can go through in pretty much any language, so if you read the error messages, number one, you want to make sure that you have an understanding of what it was doing and number two: You can look at the last line of code that you wrote and make sure that your code was correct, you can fix anything there, that might solve the problem, but in our case our code looked correct so we could assume that we should look at number three: The source code of the library and here it tells us a line number and everything so we could go look at that and look inside that send_file_headers method and figure out inside the library what does it actually do and what does it expect from us, and we can figure out our error there. Now because we happen to have been looking at newer source code than what was actually being used, we can tell then that symbols are allowed now, but they weren't previously, and so our solution is then we upgrade rails but your solution for whatever errors you run into may be that you didn't pass in your arguments correctly or something like that, and the stacktrace is going to tell you all of those things that are wrong and where you can go to look for that stuff. The stacktrace is incredibly important and anytime that you ask for help from somebody, you should include the stacktrace because that is going to help them ask you the right questions to figure out what went wrong.

Transcript written by Miguel

Discussion