Introducing Elixir: Getting Started in Functional Programming (2014)

Chapter 10. Exceptions, Errors, and Debugging

“Let it crash” is a brilliant insight, but one whose application you probably want to control. While it’s possible to write code that constantly breaks and recovers, it can be easier to write and maintain code that explicitly handles failure where it happens. However you choose to deal with errors, you’ll definitely want to be able to track them down in your application.

Flavors of Errors

As you’ve already seen, some kinds of errors will keep Elixir from compiling your code, and the compiler will also give you warnings about potential issues, like variables that are declared but never used. Two other kinds of errors are common: runtime errors, which turn up when code is operating and can actually halt a function or process, and logic errors, which may not kill your program but can cause deeper headaches.

Logic errors are often the trickiest to diagnose, requiring careful thought and perhaps some time with the debugger, log files, or a test suite. Simple mathematical errors can take a lot of work to untangle. Sometimes issues are related to timing, when the sequence of operations isn’t what you expect. In severe cases, race conditions can create deadlocks and halting, but more mild cases can produce bad results and confusion.

Runtime errors can also be annoying, but they are much more manageable. In some ways you can see handling runtime errors as part of the logic of your program, though you don’t want to get carried away. In Elixir, unlike many other programs, handling errors as errors may offer only minor advantages over letting an error kill a process and then dealing with the problem at the process level, as Example 9-10 showed.

Rescuing Code from Runtime Errors as They Happen

If you want to catch runtime errors close to where they took place, the try…rescue construct lets you wrap suspect code and handle problems (if any) that code creates. It makes it clear to both the compiler and the programmer that something unusual is happening, and lets you deal with any unfortunate consequences of that work.

For a simple example, look back to Example 3-1, which calculated fall velocity without considering the possibility that it would be handed a negative distance. The :math.sqrt/1 function will produce a badarith error if it has a negative argument. Example 4-2 kept that problem from occurring by applying guards, but if you want to do more than block, you can take a more direct approach with try and rescue, as shown in Example 10-1. (You can find this and the following two variations in ch10/ex1-tryCatch.)

Example 10-1. Using try and catch to handle a possible error

defmodule Drop do

def fall_velocity(planemo, distance) do

gravity = case planemo do

:earth -> 9.8

:moon -> 1.6

:mars -> 3.71

end

trydo

:math.sqrt(2 * gravity * distance)

rescue

_error -> _error

end

The calculation itself is now wrapped in a try. If the calculation succeeds, the statement following the do will be used, and the return value will become the result of the calculation.

If the calculation fails, in this case because of a negative argument, the pattern match in the rescue clause comes into play. In this case, the variable _error will contain the exception type and message, and return that as its value.

You can try the following on the command line:

iex(1)> c("drop.ex")

[Drop]

iex(2)> Drop.fall_velocity(:earth, 20)

19.79898987322333

iex(3)> Drop.fall_velocity(:earth, -20)

%ArithmeticError{}

When the calculation is successful, you’ll just get the result. When it fails, you see the exception. It’s not a complete solution, but it’s a foundation on which you can build.

You can have multiple statements in the try (much as you can in a case). At least when you’re getting started, it’s easiest to keep the code you are trying simple so you can see where failures happened. However, if you wanted to watch for requests that provided an atom that didn’t match the planemos in the case, you could put it all into the try:

defmodule Drop do

def fall_velocity(planemo, distance) do

trydo

gravity = case planemo do

:earth -> 9.8

:moon -> 1.6

:mars -> 3.71

end

:math.sqrt(2 * gravity * distance)

rescue

_error -> _error

end

If you try an unsupported planemo, you’ll now see the code catch the problem, at least once you recompile the code to use the new version:

iex(4)> Drop.fall_velocity(:jupiter, 20)

** (CaseClauseError) no case clause matching: :jupiter

drop.ex:3: Drop.fall_velocity/2

iex(5)> c("drop.ex")

drop.ex:1: warning: redefining module Drop

[Drop]

iex(6)> Drop.fall_velocity(:jupiter, 20)

%CaseClauseError{term: :jupiter}

The CaseClauseError indicates that a case failed to match and tells you the actual item that didn’t match.

You can also have multiple pattern matches in the rescue. If the error doesn’t match any of the patterns in the rescue clause, it gets reported as a runtime error, as if the try hadn’t wrapped it. The following example will provide different messages for each type of error. The code doesn’t store the exception in a variable since it doesn’t use information stored in the exception:

defmodule Drop do

def fall_velocity(planemo, distance) do

trydo

gravity = case planemo do

:earth -> 9.8

:moon -> 1.6

:mars -> 3.71

end

:math.sqrt(2 * gravity * distance)

rescue

ArithmeticError -> {:error, "Distance must be non-negative"}

CaseClauseError -> {:error, "Unknown planemo #{planemo}"}

end

And here is what it looks like in action:

iex(7)> c("drop.ex")

drop3.ex:1: warning: redefining module Drop

[Drop]

iex(8)> Drop.fall_velocity(:earth, -20)

{:error,"Distance must be non-negative"}

iex(9)> Drop.fall_velocity(:jupiter, 20)

{:error,"Unknown planemo jupiter"}

NOTE

If you want to do the same actions for multiple exceptions, you can write code like this:

[ArithmeticError, CaseClauseError] -> "Generic Error"

err in [ErlangError, RuntimeError] -> {:error, err}

If the code that might fail can create a mess, you may want to include an after clause after the rescue clause and before the closing end. The code in an after clause is guaranteed to run whether the attempted code succeeds or fails and can be a good place to address any side effects of the code. It doesn’t affect the return value of the clause.

Logging Progress and Failure

The IO:puts function is useful for simple communications with the shell, but as your programs grow (and especially as they become distributed processes), hurling text toward standard output is less likely to get you the information you need. Elixir offers a set of functions for more formal logging. They can hook into more sophisticated logging systems, but it’s easy to get started with them as a way to structure messages from your application.

These functions in Elixir’s Logger module give you four levels of reporting:

:info

For information of any kind.

:debug

For debug-related messages.

:warn

For news that’s worse. Someone should do something eventually.

:error

Something just plain broke and needs to be looked at.

As you can see, these calls produce reports that are visually distinctive. If you run IEx and enter these statements, you will see that the messages also appear in different colors:

iex(1)> require Logger

nil

iex(2)> counter=255

255

iex(3)> Logger.info("About to begin test")

18:57:36.846 [info] About to begin test

:ok

iex(4)> Logger.debug("Current value of counter is #{counter}")

18:58:06.526 [debug] Current value of counter is 255

:ok

iex(5)> Logger.warn("Connection lost; will retry.")

18:58:21.759 [warn] Connection lost; will retry.

:ok

iex(6)> Logger.error("Unable to read database.")

18:58:37.008 [error] Unable to read database.

:ok

These functions produce only a mild improvement over IO.puts, so why would you use them? Because there is much much more lurking under the surface. By default, when Elixir starts up, it sets up the Logger module to report to the shell. However, you can design a custom backend to log information to any destination you please.

While logging information is useful, it’s not unusual to write code with subtle errors where you’re not positive what to log where. You could litter the code with reporting, or you could use the Erlang debugging tools that are also available in Elixir.

Tracing Messages

Elixir offers a wide variety of tools for tracing code, both with other code (using Erlang’s trace and trace_pattern built-in functions) and with a text-based debugger/reporter. The dbg module is the easiest place to start into this toolset, letting you specify what you want traced and showing you the results in the shell.

NOTE

The :dbg module is an Erlang module, but if you are getting tired of typing the leading : every time you use an Erlang function, you can make things feel more Elixir-like by typing this command:

iex(8)> alias :dbg, as: Dbg

[]

For now, we will continue to use :dbg.

An easy place to get started is tracing messages sent between processes. You can use :dbg.p to trace the messages sent between the mph_drop process defined in Example 9-8 and the drop process from Example 9-6. After compiling the modules, you call :dbg.tracer() to start reporting trace information to the shell. Then you spawn the mph_drop process as usual and pass that pid to the :dbg.p/2 process. The second argument here will be :m, meaning that the trace should report the messages. The code from Chapter 8 is duplicated in ch10/ex2-debug:

iex(1)> c("drop.ex")

[Drop]

iex(2)> c("mph_drop.ex")

[MphDrop]

iex(3)> :dbg.tracer()

{:ok,#PID<0.47.0>}

iex(4)> pid1 = spawn(MphDrop, :mph_drop, [])

#PID<0.49.0>

iex(5)> :dbg.p(pid1, :m)

{:ok,[{:matched,:"nonode@nohost",1}]}

Now when you send a message to the mph_drop process, you’ll get a set of reports on the resulting flow of messages. (<0.49.0> is the mph_drop process, and <0.50.0> is the drop process.)

iex(6)> send(pid1, {:moon, 20})

(<0.49.0>) << {moon,20}

(<0.49.0>) <0.50.0> ! {<0.49.0>,moon,20}

(<0.49.0>) << {moon,20,8.0}

(<0.49.0>) << {code_server,{module,'Elixir.String.Chars.Atom'}}

(<0.49.0>) << {code_server,{module,'Elixir.String.Chars.Integer'}}

(<0.49.0>) << {code_server,{module,'Elixir.String.Chars.Float'}}

(<0.49.0>) << {code_server,{module,'Elixir.String.Chars.BitString'}}

On moon, a fall of 20 meters yields a velocity of 17.89549032 mph.

(<0.49.0>) <0.26.0> ! {io_request,<0.49.0>,<0.26.0>,

{put_chars,unicode,

<<"On moon, a fall of 20 meters yields a velocity

of 17.89549032 mph.\n">>}}

(<0.49.0>) << {io_reply,<0.26.0>,ok}

{:moon, 20}

The << pointing to a pid indicates that that process received a message. Sends are indicated with the pid followed by ! followed by the message. This is much like what you saw when using the observer to view process messages in Watching Your Processes. In this case:

§ On this run, the report from mph_drop that On moon, a fall of 20 meters yields a velocity of 17.89549032 mph. comes through in the middle of the tracing information. The rest of the trace indicates how that report got there.

§ mph_drop (<0.49.0>) receives the message tuple {moon,20}.

§ It sends a further message, the tuple {<0.49.0>,moon,20}, to the drop process at pid <0.50.0>.

§ mph_drop receives a tuple {moon,20,8.0} (from drop).

§ Then it calls io:request/2, which triggers another set of process messages to make the report.

The trace reports come through interleaved with the actual execution of the code, but they make the flow of messages clear. You’ll want to learn to use :dbg in its many variations to trace your code and may eventually want to use match patterns and the trace functions themselves to create more elegant systems for watching specific code.

Watching Function Calls

If you just want to keep track of arguments moving between function calls, you can use the tracer to report on the sequence of calls. Chapter 4 demonstrated recursion and reported results along the way through IO.puts. There’s another way to see that work, again using the :dbg module.

Example 4-11, the upward factorial calculator, started with a call to Fact.factorial/1, which then called Fact.factorial/3 recursively. :dbg will let you see the actual function calls and their arguments, mixed with the IO.puts reporting. (You can find it in ch10/ex3-debug.)

Tracing functions is a little trickier than tracing messages because you can’t just pass :dbg.p/2 a pid. As shown on line 3 in the following code sample, you need to tell it you want it to report on all processes (:all) and their calls (:c). Once you’ve done that, you have to specify which calls you want it to report, using :dbg.tpl as shown on line 4. It takes a module name (Fact), function name as an atom (:factorial), and optionally a match specification that lets you specify arguments more precisely. Variations on this function also let you specify arity.

So turn on the tracer, tell it you want to follow function calls, and specify a function (or functions, through multiple calls to :dbg.tpl) to watch. Then call the function, and you’ll see a list of the calls:

iex(1)> c("fact.ex")

[Fact]

iex(2)> :dbg.tracer()

{:ok,#PID<0.43.0>}

iex(3)> :dbg.p(:all, :c)

{:ok,[{:matched,:"nonode@nohost",29}]}

iex(4)> :dbg.tpl(Fact, :factorial, [])

{:ok,[{:matched,:"nonode@nohost",2}]}

iex(5)> Fact.factorial(4)

1 yields 1!

(<0.26.0>) call 'Elixir-Fact':factorial(4)

(<0.26.0>) call 'Elixir-Fact':factorial(1,4,1)

2 yields 2!

(<0.26.0>) call 'Elixir-Fact':factorial(2,4,1)

3 yields 6!

(<0.26.0>) call 'Elixir-Fact':factorial(3,4,2)

4 yields 24!

(<0.26.0>) call 'Elixir-Fact':factorial(4,4,6)

Finished.

(<0.26.0>) call 'Elixir-Fact':factorial(5,4,24)

You can see that the sequence is a bit messy here, with the trace reporting coming a little bit after the IO.puts results from the function being traced. Because the trace is running in a separate process (at pid <0.43.0>) from the function (at pid <0.26.0>), its reporting may not line up smoothly (or at all, though it usually does).

When you’re done tracing, call :dbg.stop/0 (if you might want to restart tracing with the same setup) or :dbg.stop_clear/0 (if you know that when you start again you’ll want to set things up again).

The :dbg module and the trace functions on which it builds are incredibly powerful tools.

Writing Unit Tests

You can avoid some debugging by adequately testing your code beforehand, and Elixir has a unit-testing module named ExUnit to make this easy for you.

To demonstrate ExUnit, the following is a Drop module with an error in it. The gravity constant for Mars has been accidentally mistyped as 3.41 instead of 3.71 (someone’s finger slipped on the numeric keypad). Save this as file drop_bad.ex:

defmodule Drop do

def fall_velocity(planemo, distance) do

gravity = case planemo do

:earth -> 9.8

:moon -> 1.6

:mars -> 3.41

end

:math.sqrt(2 * gravity * distance)

end

You write your tests in an Elixir script file (with an extension of .exs) so that it doesn’t need to be compiled. You then define tests using the test macro. Here are two tests. The first tests that a distance of zero returns a velocity of zero, and the second tests that a fall of 10 meters on Mars produces the correct answer. Save this in a file named drop_test.exs:

ExUnit.start

defmodule DropTest do

use ExUnit.Case, async: true

test "Zero distance gives zero velocity" do

assert Drop.fall_velocity(:earth,0) == 0

end

test "Mars calculation correct" do

assert Drop.fall_velocity(:mars, 10) == :math.sqrt(2 * 3.71 * 10)

end

The first line of the script sets up ExUnit to run automatically, and the use line allows Elixir to run the test cases in parallel.

A test begins with the macro test and a string that describes the test. The content of the test consists of executing some code and then asserting some condition. If the result of executing the code is true, then the test passes; if the result is false, the test fails.

To run the tests, you need to compile the Drop module (which you can do from the command line) and then type elixir drop_test.exs:

$ elixirc drop_bad.ex

$ elixir drop_test.exs

1) test Mars calculation correct (DropTest)

drop_test.exs:10

Assertion with == failed

code: Drop.fall_velocity(:mars, 10) == :math.sqrt(2 * 3.71 * 10)

lhs: 8.258329128825032

rhs: 8.613942186943213

stacktrace:

drop_test.exs:11

Finished in 0.3 seconds (0.2s on load, 0.07s on tests)

2 tests, 1 failures

Randomized with seed 210488

The line starting . indicates the status of each test; a . means that the test succeeded.

Fix the error by going into the Drop module and changing Mars’s gravity constant to the correct value of 3.71. Save it with the name drop.ex and recompile. Then run the test again, and you will see what a successful test looks like:

$ elixirc drop.ex

drop.ex:1: warning: redefining module Drop

$ elixir drop_test.exs

Finished in 0.1 seconds (0.1s on load, 0.00s on tests)

2 tests, 0 failures

Randomized with seed 878156

In addition to assert/1, you may also use refute/1, which expects the condition you are testing to be false in order for a test to pass. Both assert/1 and refute/1 automatically generate an appropriate message. There is also a two-argument version of each function that lets you specify the message to produce if the assertion or refutation fails.

If you are using floating-point operations, you may not be able to count on an exact result. In that case, you can use the assert_in_delta/4 function. Its four arguments are the expected value, the value you actually received, the delta, and a message. If the expected and received values are within delta of each other, the test passes. Otherwise, the test fails and ExUnit prints your message. Here is a test to see if a fall velocity from a distance of one meter on Earth is close to 4.4 meters per second. Add this to your drop_test.exs file and run the tests again. (The revised version is in file ch10/ex4-testing/drop_test2.exs.)

test "Earth calculation correct" do

calculated = Drop.fall_velocity(:earth, 1)

assert_in_delta calculated, 4.4, 0.05,

"Result of #{calculated} is not within 0.05 of 4.4"

end

If you want to see the failure message, change the test to require the calculation to be more precise, and save it. (This version is in file ch10/ex4-testing/drop_test3.exs.)

test "Earth calculation correct" do

calculated = Drop.fall_velocity(:earth, 1)

assert_in_delta calculated, 4.4, 0.0001,

"Result of #{calculated} is not within 0.0001 of 4.4"

end

This is the result:

$ elixirc drop_test3.exs

1) test Earth calculation correct (DropTest)

drop_test3.exs:14

Result of 4.427188724235731 is not within 0.0001 of 4.4

stacktrace:

drop_test3.exs:16

Finished in 0.1 seconds (0.1s on load, 0.01s on tests)

3 tests, 1 failures

Randomized with seed 336034

You can also test that parts of your code will correctly raise exceptions. These following two tests will check that an incorrect planemo and a negative distance actually cause errors. In each test, you wrap the code you want to test in an anonymous function. You can find these additional tests in file ch10/ex4-testing/drop_test4.exs:

test "Unknown planemo causes error" do

assert_raise CaseClauseError, fn ->

Drop.fall_velocity(:planetX, 10)

end

test "Negative distance causes error" do

assert_raise ArithmeticError, fn ->

Drop.fall_velocity(:earth, -10)

end

Elixir’s testing facilities also allow you to test whether messages have been received or not, specify code to be run before and after each test, write functions to be shared among tests, and much more. The full details are available in the Elixir documentation.