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.)

defmodule Drop do
  def fall_velocity(planemo, distance) do
    gravity = case planemo do
      :earth -> 9.8
      :moon -> 1.6
      :mars -> 3.71
    end
    try do
      :math.sqrt(2 * gravity * distance)
    rescue
      error -> error
    end
  end
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)> Drop.fall_velocity(:earth, 20)
19.79898987322333
iex(2)> Drop.fall_velocity(:earth, -20)
%ArithmeticError{message: "bad argument in arithmetic expression"}

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
    try do
      gravity = case planemo do
        :earth -> 9.8
        :moon -> 1.6
        :mars -> 3.71
      end
      :math.sqrt(2 * gravity * distance)
    rescue
      error -> error
    end
  end
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)> r(Drop)
warning: redefining module Drop (current version defined in memory)
  lib/drop.ex:1

{:reloaded, 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
    try do
      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
  end
end

And here is what it looks like in action:

iex(7)> r(Drop)
warning: redefining module Drop (current version defined in memory)
  lib/drop.ex:1

{:reloaded, 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"}

[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
Logger
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.

iex(8)> alias :dbg, as: Dbg
: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 Example 9-8 is duplicated in ch10/ex2-debug and is started here via iex -S mix:

iex(1)> :dbg.tracer()
{:ok,#PID<0.71.0>}
iex(2)> pid1 = spawn(MphDrop, :mph_drop, [])
#PID<0.148.0>
iex(3)> :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.148.0> is the mph_drop process, and <0.149.0> is the drop process.)

iex(4)> send(pid1, {:moon, 20})
On moon, a fall of 20 meters {:moon, 20}
(<0.148.0>) << {moon,20}
yields a velocity of 17.89549032 mph.
(<0.148.0>) <0.149.0> ! {<0.148.0>,moon,20}
(<0.148.0>) << {moon,20,8.0}
(<0.148.0>) <0.50.0> ! {io_request,<0.148.0>,#Ref<0.0.2.159>,
                           {put_chars,unicode,
                               <<"On moon, a fall of 20 meters ">>}}
(<0.148.0>) << {io_reply,#Ref<0.0.2.159>,ok}
(<0.148.0>) <0.50.0> ! {io_request,<0.148.0>,#Ref<0.0.3.350>,
                           {put_chars,unicode,
                               <<"yields a velocity of 17.89549032 mph.
">>}}
(<0.148.0>) << {io_reply,#Ref<0.0.3.350>,ok}

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. and the result of {:moon, 20} come through in the middle of the tracing information. The rest of the trace indicates how that report got there.

• mph_drop (<0.148.0>) receives the message tuple {moon,20}.

• It sends a further message, the tuple {<0.148.0>,moon,20}, to the drop process at pid <0.149.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)> :dbg.tracer()
{:ok,#PID<0.43.0>}
iex(2)> :dbg.p(:all, :c)
{:ok, [{:matched, :nonode@nohost, 51}]}
iex(3)> :dbg.tpl(Fact, :factorial, [])
{:ok, [{:matched, :nonode@nohost, 2}]}

iex(4)> 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)
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.