Elixir 1.14: Better Debugging with dbg/2 and More
Tags: elixir
Published: 2022-09-21 11:52:49

The latest Elixir release introduces new features to improve your developer and debugging experience.

In this post, we'll take a look at the new `dbg()` functionality, along with some improvements to `Inspect` and binary evaluation error messaging. All these changes come together to make you an even more productive Elixirist.

Let's get started!

## Debugging with `Kernel.dbg/2` in Elixir

The Elixir Kernel now exposes a `dbg/2` macro that you can use with or without IEx for enhanced debugging. Let's walk through a few examples that illustrate just how useful this tool can be in your debugging toolkit.

In this example, we have a Phoenix LiveView application called Live Library. Users can browse, checkout, and return books. Unfortunately for us, however, it looks like we have a bug--when a user tries to check out a book, [the live view crashes](https://www.youtube.com/watch?v=67oEY46y5Wk).

We can use the `dbg/2` function to gain insight into what's going wrong. We'll start with a few well-placed calls to `dbg/2`. Then, we'll move on to leveraging `dbg/2` within an IEx session.

### Debugging the Current Binding

First, we'll make a call to `dbg/2` in the live view's event handler function that gets called when the user clicks "checkout". This is the entry point of our "checkout book" code flow, so we'll start our debugging process there.

```elixir
# lib/live_library_web/live/book_live/checkout_component.ex

def handle_event("checkout", _, %{assigns: %{book: book}} = socket) do
  dbg() # this is new!
  case Library.checkout_book(book, socket.assigns.current_user.id) do
    {:ok, book} ->
      {:noreply, socket |> assign(:book, book)}

    {:err, _err} ->
      {:noreply, socket}
  end
end
```

Now, if we try once again to check out a book, we'll see the following output in our terminal where we're running the Phoenix server via `mix phx.server`:

```elixir
[(live_library 0.1.0) lib/live_library_web/live/book_live/checkout_component.ex:33: LiveLibraryWeb.CheckoutComponent.handle_event/3]
binding() #=> [
  book: %LiveLibrary.Library.Book{
    updated_at: ~N[2022-09-11 17:42:19],
    inserted_at: ~N[2022-02-28 16:33:45],
    book_loans: [
      %LiveLibrary.Library.BookLoan{
        updated_at: ~N[2022-09-11 17:39:18],
        inserted_at: ~N[2022-09-11 17:39:18],
        book_id: 7,
        user_id: 4,
        id: 51,
        __meta__: #Ecto.Schema.Metadata<:loaded, "book_loans">
      }
    ],
    author_id: 4,
    title: "My Test Book!!!",
    description: "A book I made up. Different from the book I wrote which I also technically made up.",
    cover: "live_view_upload-1657544569-150520820351856-7",
    available: true,
    id: 7,
    __meta__: #Ecto.Schema.Metadata<:loaded, "books">
  },
  socket: #Phoenix.LiveView.Socket<
    id: "phx-FxPfPGQDjqGwUAyB",
    endpoint: LiveLibraryWeb.Endpoint,
    view: LiveLibraryWeb.BookLive.Index,
    parent_pid: nil,
    root_pid: #PID<0.780.0>,
    router: LiveLibraryWeb.Router,
    assigns: %{
      __changed__: %{},
      book: %LiveLibrary.Library.Book{
        updated_at: ~N[2022-09-11 17:42:19],
        inserted_at: ~N[2022-02-28 16:33:45],
        # ...
      },
      current_user: #LiveLibrary.Accounts.User<
        updated_at: ~N[2022-02-18 14:49:02],
        inserted_at: ~N[2022-02-18 14:49:02],
        admin: true,
        confirmed_at: nil,
        email: "admin@email.com",
        id: 4,
        __meta__: #Ecto.Schema.Metadata<:loaded, "users">,
        ...
      >,
      flash: %{},
      id: "checkout-7",
      myself: %Phoenix.LiveComponent.CID{cid: 5}
    },
    transport_pid: #PID<0.768.0>,
    # ...
  >
]
```

When called without any arguments, `dbg/2` defaults to debugging the binding for the current context. In this case, that's the `handle_event/3` function (and the variables available to us by the time the `dbg/2` call is hit on the first line of that function).

As you can see in the output above, calling `dbg/2` does a few things for us - printing out the:

- Location of the debugged code:

```elixir
[(live_library 0.1.0) lib/live_library_web/live/book_live/checkout_component.ex:33: LiveLibraryWeb.CheckoutComponent.handle_event/3]
```

- Value of the current context's binding:

```elixir
binding() #=> [
  book: %LiveLibrary.Library.Book{
    #...
```

The call to `dbg/2` also _returns the value of the debugged code itself_. We'll see how helpful this is in a bit.

For now, we're already experiencing some of the benefits of `dbg/2` with just this basic usage. Let's examine the value of the arguments that `handle_event/3` is called with. This way, we'll better understand how our code is executing and what might be going wrong.

Based on the `dbg/2` output, it looks like the input to `handle_event/3` is exactly what we expect. We have a socket whose `assigns` correctly contain a book and a current user. So, let's move our call to `dbg/2` downstream a bit, into the `Library.checkout_book/2` context function.

### Debugging Provided Code

At this point in our debugging journey, we're ready to turn our attention to the behavior of the `Library.checkout_book/2` function. This is the next step in our broken "checkout book" code flow.

We're interested in a few things. We'd like to understand what exact arguments the function is being called with, and what it returns. We can easily reveal this information with two calls to `debug/2`.

We'll call `dbg/2` with the current default context at the beginning of the `checkout_book/2` function to look at the arguments' values.

Then, we'll pipe the code in `Library.checkout_book/2` into a call to `dbg/2` at the _end_ of the function. This will allow us to see the return value of the function. And, since `dbg/2` returns the value of the executed code you pass to it as a first argument, the remainder of our "checkout book" code flow will be unaffected by this call to `dbg/2`.

Here's what our debugged function looks like:

```elixir
def checkout_book(book, user_id) do
  dbg()
  with {:ok, _loan} <- Library.create_book_loan(%{user_id: user_id, book_id: book.id}),
       {:ok, book} <- Library.update_book(book, %{available: false}) do
        book
  else
    err -> err
  end
  |> dbg()
end
```

Now if we try to check out a book, we'll see the following output in our terminal:

```elixir
[(live_library 0.1.0) lib/live_library/library.ex:13: LiveLibrary.Library.checkout_book/2]
binding() #=> [
  book: %LiveLibrary.Library.Book{
    updated_at: ~N[2022-09-11 18:27:59],
    inserted_at: ~N[2022-02-28 16:33:45],
    author_id: 4,
    title: "My Test Book!!!",
    description: "A book I made up. Different from the book I wrote which I also technically made up.",
    cover: "live_view_upload-1657544569-150520820351856-7",
    available: true,
    id: 7,
    __meta__: #Ecto.Schema.Metadata<:loaded, "books">,
    # ...
  },
  user_id: 4
]

# ...

[(live_library 0.1.0) lib/live_library/library.ex:21: LiveLibrary.Library.checkout_book/2]
with {:ok, _loan} <- Library.create_book_loan(%{user_id: user_id, book_id: book.id}),
     {:ok, book} <- Library.update_book(book, %{available: false}) do
  book
else
  err -> err
end #=>
%LiveLibrary.Library.Book{
  updated_at: ~N[2022-09-11 18:28:00],
  inserted_at: ~N[2022-02-28 16:33:45],
  # ...
}
```

From this, we can clearly see that the `checkout_book/2` function returns a single book struct. We're close to solving our bug now.

Let's return to the `handle_event/3` function that calls `checkout_book/2`. This time, we'll run our server in an IEx session with `iex -S mix phx.server`. Then, we'll place another `dbg/2` call in the `handle_event/3` function to freeze code execution and interact with our code in real time.

### Debugging with `dbg/2` and IEx in Elixir

The `dbg/2` function is configurable, and you can extend it with advanced behavior. IEx comes with one such extension baked in.

In Elixir 1.14, IEx extends `dbg/2` with an interactive shell, similar to `IEx.pry`.

Let's add back our `dbg/2` call to the event handler function and play around:

```elixir
# lib/live_library_web/live/book_live/checkout_component.ex

def handle_event("checkout", _, %{assigns: %{book: book}} = socket) do
  dbg()
  case Library.checkout_book(book, socket.assigns.current_user.id) do
    {:ok, book} ->
      {:noreply, socket |> assign(:book, book)}

    {:err, _err} ->
      {:noreply, socket}
  end
end
```

Now when we try to check out a book in the browser, we'll see that we have a request to pry in our terminal:

```elixir
Request to pry #PID<0.816.0> at LiveLibraryWeb.CheckoutComponent.handle_event/3 (lib/live_library_web/live/book_live/checkout_component.ex:33)

   32:   def handle_event("checkout", _, %{assigns: %{book: book}} = socket) do
   33:     dbg()
   34:     case Library.checkout_book(book, socket.assigns.current_user.id) do
   35:       {:ok, book} ->
   36:         Endpoint.broadcast(@checkout_topic, "checkout_event", %{book: book})

Allow? [Yn] Y
```

We can now interact with and execute our code. Let's manually execute the `checkout_book/2` function like this:

```elixir
pry(1)> Library.checkout_book(book, socket.assigns.current_user.id)
iex(1)> [debug] QUERY OK db=1.0ms idle=1240.2ms
INSERT INTO "book_loans" ("book_id","user_id","inserted_at","updated_at") VALUES ($1,$2,$3,$4) RETURNING "id" [7, 4, ~N[2022-09-11 18:46:06], ~N[2022-09-11 18:46:06]]
[debug] QUERY OK db=1.0ms queue=0.3ms idle=1241.5ms
UPDATE "books" SET "available" = $1, "updated_at" = $2 WHERE "id" = $3 [false, ~N[2022-09-11 18:46:06], 7]
%LiveLibrary.Library.Book{
  updated_at: ~N[2022-09-11 18:46:06],
  inserted_at: ~N[2022-02-28 16:33:45],
  # ...
  ],
```

Here, we can see that we are returning the newly checked-out book. A call to `whereami` will show us the next bit of code flow that will try to execute:

```elixir
pry(2)> whereami
Location: lib/live_library_web/live/book_live/checkout_component.ex:33

   31:
   32:   def handle_event("checkout", _, %{assigns: %{book: book}} = socket) do
   33:     dbg()
   34:     case Library.checkout_book(book, socket.assigns.current_user.id) do
   35:       {:ok, book} ->

    (live_library 0.1.0) lib/live_library_web/live/book_live/checkout_component.ex:33: LiveLibraryWeb.CheckoutComponent.handle_event/3
```

This reminds us that the case statement expects to match on a return value _not_ of a single book struct, but rather of an `{:ok, book}` tuple. With that, we've found our bug! By updating the `checkout_book/2` function to return a tuple instead of a book struct, we'll fix our problem.

Before we move on to some other new Elixir 1.14 features that will improve your development and debugging experience, let's take a last look at some additional `dbg/2` functionality.

### More `dbg/2` Goodies

Let's examine how `dbg/2` makes it easier than ever before to debug pipelines. Then, we'll peek at some of the more advanced `dbg/2` configuration capabilities.

### Debugging Pipelines with `dbg/2`

The `dbg/2` macro makes it easier to debug pipelines. Before `dbg/2`, if you wanted to examine return values at each step of your pipeline, you'd have to add an explicit call to `IO.inspect` at each step - like this:

```elixir
# lib/live_library_web/live/book_live/index.ex
def mount(_params, %{"user_token" => user_token}, socket) do
  {:ok,
   socket
   |> assign_user(user_token)
   |> IO.inspect()
   |> assign_books()
   |> IO.inspect()
   |> assign_search()
   |> IO.inspect()
   |> assign_search_changeset()
   |> IO.inspect()
   |> assign_categories()
   |> IO.inspect()
   |> assign_category_ids()}
end
```

This isn't very eloquent and it can be tedious to implement. Now in Elixir 1.14, we can place just one call to `dgb/2` at the end of our pipeline. This will print out the value at each individual step of the pipeline and ensure that the pipeline still returns the value of the executed code. Let's add in our `dbg/2` call here:

```elixir
def mount(_params, %{"user_token" => user_token}, socket) do
  {:ok,
   socket
   |> assign_user(user_token) # %{assigns: %{user: #...}}
   |> assign_books() # %{assigns: %{books: #...}}
   |> assign_search() # %{assigns: %{search: #...}}
   |> assign_search_changeset() # # %{assigns: %{search_changeset: #...}}
   |> assign_categories() # %{assigns: %{categories: #...}}
   |> assign_category_ids() # %{assigns: %{category_ids: #...}}
   |> dbg()}
end
```

Now, when we visit the `/books` index page that brings up this live view, we'll see that the return value of each step of the pipeline has been printed for us to examine.

Additionally, if you run this code in an IEx session, you will be able to step, or pry, through each individual step in the pipeline. Code execution will freeze at each successive line in the pipeline.

Pipelines represent one of Elixir's most powerful and eloquent language features, and debugging them just got easier.

### Configuring `dbg/2`

You can extend the behavior of `dbg/2` in your Elixir application by defining a custom function. Tell `dbg/2` to use that custom function via your app's `:dbg_callback` configuration key. Your app configuration should look like this:

```elixir
# config/config.exs
config :elixir, :dbg_callback, {MyMod, :debug_fun, [:stdio]}
```

Where you've defined a function `MyMod.debug_fun/4`.

Then when `dbg/2` is called, your custom function will be called with three arguments prepended to any arguments you specify in your app config:

1. An AST representing the code to be debugged that was passed to `dbg/2` as a first argument.
2. An AST representing any options given to `dbg/2` as a second argument.
3. The `Macro.Env` struct representing the context in which `dbg/2` was invoked.

You can find a more detailed example of this [`dbg/2` custom configuration approach in the docs](https://hexdocs.pm/elixir/Kernel.html#dbg/2-configuring-the-debug-function).

Now that we've taken a pretty comprehensive look at what `dbg/2` has to offer, let's move on to some other new Elixir 1.14 features that improve the development experience.

## Inspect Improvements

Elixir 1.14 has improved the `Inspect` protocol implementation for a few core library modules: `MapSet`, `Version.Requirement`, and `Date.Range`. Previously, calls to inspect a new `MapSet` would return notation that is not valid Elixir:

```elixir
iex> MapSet.new([1, :two, {"three"}])
#MapSet<[1, :two, {"three"}]>
```

This output can't be copied and pasted in IEx, or operated on by subsequent function calls.

This is no longer the case in Elixir 1.14. Now, you'll see this behavior:

```elixir
iex> MapSet.new([1, :two, {"three"}])
MapSet.new([1, :two, {"three"}])
```

Here, the output _is_ valid Elixir that can be operated on by subsequent Elixir code.

Some additional improvements have been made to `Inspect` protocol for structs:

- When you inspect a struct, fields will be displayed in the order in which they are defined in `defstruct`.

- If you want to customize the `Inspect` behavior for your struct by deriving it, you can use the new `:optional` keyword to omit struct fields that have not changed from their default value when displaying the inspection results. This simplifies struct representation and adds some much-needed brevity to the representation of larger structs. You can learn more info about the [`Inspect` customization option in the docs](https://hexdocs.pm/elixir/Inspect.html#module-deriving).

We have just one more Elixir 1.14 improvement to look at before we wrap up.

## Better Binary Evaluation Errors

In keeping with the improved debugging and developer experience we see throughout the Elixir 1.14 release, the latest version of Elixir also improves error messaging on binary construction and evaluation. This brings Elixir in line with Erlang/OTP 25 improvements in the same area.

Instead of getting generic `ArgumentError` messages when constructing binaries in an invalid manner, we get more informative error messages like this:

```elixir
iex> 123 <> "456"
** (ArgumentError) expected binary argument in <> operator but got: 123
```

**Want to learn how you can also save time debugging an app in production with AppSignal? [Check out how Upside does it](https://www.appsignal.com/customers/upside).**

## Wrap Up

Elixir has a devoted following and an increasingly growing community and adoption rate, in part because the language prioritizes developer happiness.

This latest Elixir release is no exception. With new debugging capabilities and improvements to `Inspect` protocols as well as binary evaluation error messages, Elixir's developer experience toolkit has grown even more.

Thanks to these new features, you'll be more productive in Elixir than ever before. Upgrade your Elixir apps today, and get going!

**P.S. If you'd like to read Elixir Alchemy posts as soon as they get off the press, [subscribe to our Elixir Alchemy newsletter and never miss a single post](/elixir-alchemy)!**