Elixir 1.14: Better Debugging with dbg/2 and More

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.

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.

# 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:

[(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:

[(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:

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:

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:

[(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:

# 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:

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:

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:

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:

# 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:

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:

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

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:

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:

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.

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:

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.

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!