Iteration E2: Handling Errors
It’s apparent from the page shown in the screenshot that our application raised an exception at line 67 of the carts controller. Your line number might be different, as we have some book-related formatting stuff in our source files. If you go to that line, you’ll find the following code:
| | @cart = Cart.find(params[:id]) |
If the cart can’t be found, Active Record raises a RecordNotFound exception, which we clearly need to handle. The question arises—how?
We could silently ignore it. From a security standpoint, this is probably the best move, because it gives no information to a potential attacker. However, it also means that if we ever have a bug in our code that generates bad cart IDs, our application will appear to the outside world to be unresponsive—no one will know that an error occurred.
Instead, we’ll take two actions when an exception is raised. First, we’ll log the fact to an internal log file using the Rails logger facility.[48] Second, we’ll redisplay the catalog page along with a short message (something along the lines of “Invalid cart”) to the user, who can then continue to use our site.
Rails has a convenient way of dealing with errors and error reporting. It defines a structure called a flash. A flash is a bucket (actually closer to a Hash) in which you can store stuff as you process a request. The contents of the flash are available to the next request in this session before being deleted automatically. Typically, the flash is used to collect error messages. For example, when our show method detects that it was passed an invalid cart ID, it can store that error message in the flash area and redirect to the index action to redisplay the catalog. The view for the index action can extract the error and display it at the top of the catalog page. The flash information is accessible within the views via the flash accessor method.
Why can’t we store the error in any old instance variable? Remember that after a redirect is sent by our application to the browser, the browser sends a new request back to our application. By the time we receive that request, our application has moved on; all the instance variables from previous requests are long gone. The flash data is stored in the session to make it available between requests.
Armed with this background about flash data, we can create an invalid_cart method to report on the problem:
| | class CartsController < ApplicationController |
| | before_action :set_cart, only: [:show, :edit, :update, :destroy] |
| » | rescue_from ActiveRecord::RecordNotFound, with: :invalid_cart |
| | # GET /carts |
| | # ... |
| | private |
| | # ... |
| | |
| » | def invalid_cart |
| » | logger.error "Attempt to access invalid cart #{params[:id]}" |
| » | redirect_to store_index_url, notice: 'Invalid cart' |
| » | end |
| | end |
The rescue_from clause intercepts the exception raised by Cart.find. In the handler, we do the following:
-
Use the Rails logger to record the error. Every controller has a logger attribute. Here we use it to record a message at the error logging level.
-
Redirect to the catalog display by using the redirect_to method. The :notice parameter specifies a message to be stored in the flash as a notice. Why redirect rather than display the catalog here? If we redirect, the user’s browser will end up displaying the store URL, rather than http://.../cart/wibble. We expose less of the application this way. We also prevent the user from retriggering the error by clicking the Reload button.
With this code in place, we can rerun our customer’s problematic query by entering the following URL:
| | http://localhost:3000/carts/wibble |
We don’t see a bunch of errors in the browser now. Instead, the catalog page is displayed with the error message shown in the following screenshot.
If we look at the end of the log file (development.log in the log directory), we see our message:
| | Started GET "/carts/wibble" for 127.0.0.1 at 2016-01-29 09:37:39 -0500 |
| | Processing by CartsController#show as HTML |
| | Parameters: {"id"=>"wibble"} |
| | ^[[1m^[[35mCart Load (0.1ms)^[[0m SELECT "carts".* FROM "carts" WHERE |
| | "carts"."id" = ? LIMIT 1 [["id", "wibble"]] |
| » | Attempt to access invalid cart wibble |
| | Redirected to http://localhost:3000/ |
| | Completed 302 Found in 3ms (ActiveRecord: 0.4ms) |
On Unix machines, we’d probably use a command such as tail or less to view this file. On Windows, you can use your favorite editor. It’s often a good idea to keep a window open to show new lines as they’re added to this file. In Unix, you’d use tail -f. You can download a tail command for Windows[49] or get a GUI-based tool.[50] Finally, some OS X users use Console.app to track log files. Just say open development.log at the command line.
This being the Internet, we can’t worry only about our published web forms; we have to worry about every possible interface, because malicious crackers can get underneath the HTML we provide and attempt to provide additional parameters. Invalid carts aren’t our biggest problem here; we also want to prevent access to other people’s carts.
As always, your controllers are your first line of defense. Let’s go ahead and remove cart_id from the list of parameters that are permitted:
| | def line_item_params |
| » | params.require(:line_item).permit(:product_id) |
| | end |
We can see this in action by rerunning our controller tests:
| | bin/rails test:controllers |
No tests fail, but a peek into our log/test.log reveals a thwarted attempt to breach security:
| | LineItemsControllerTest: test_should_update_line_item |
| | ----------------------------------------------------- |
| | (0.0ms) begin transaction |
| | LineItem Load (0.1ms) SELECT "line_items".* FROM |
| | "line_items" WHERE "line_items"."id" = ? LIMIT 1 [["id", 980190962]] |
| | Processing by LineItemsController#update as HTML |
| | Parameters: {"line_item"=>{"product_id"=>nil}, "id"=>"980190962"} |
| | LineItem Load (0.1ms) SELECT "line_items".* FROM |
| | "line_items" WHERE "line_items"."id" = ? LIMIT 1 [["id", "980190962"]] |
| » | Unpermitted parameter: cart_id |
| | (0.0ms) SAVEPOINT active_record_1 |
| | (0.1ms) RELEASE SAVEPOINT active_record_1 |
| | Redirected to http://test.host/line_items/980190962 |
| | Completed 302 Found in 2ms (ActiveRecord: 0.2ms) |
| | (0.0ms) rollback transaction |
Let’s clean up that test case to make the problem go away:
| | test "should update line_item" do |
| » | patch line_item_url(@line_item), |
| » | params: { line_item: { product_id: @line_item.product_id } } |
| | assert_redirected_to line_item_url(@line_item) |
| | end |
At this point, we clear the test logs and rerun the tests:
| | bin/rails log:clear LOGS=test |
| | bin/rails test:controllers |
A final scan of the logs identifies no further problems.
It makes good sense to review log files periodically. They hold a lot of useful information.
Sensing the end of an iteration, we call our customer over and show her that the error is now properly handled. She’s delighted and continues to play with the application. She notices a minor problem on our new cart display: there’s no way to empty items out of a cart. This minor change will be our next iteration. We should make it before heading home.