Elixir/Phoenix: Why are certain files / lines not shown in my exception stacktrace?

Question

A couple times a day when skimming an error stacktrace in my Phoenix app, I notice that certain files that are definitely being executed, aren't showing up in the stacktrace.

Example 1: A view helper method is omitted

Here's one example involving a format_date helper called from my template. The code:

# The template, `...web/templates/home/index.html.eex`:
<h1>My Super Old Company</h1>
<p>We've been operating since <%= format_date(Timex.now()) %>!!</p>

# The `format_date` helper lives in the corresponding View module:
def format_date(date) do
  template = "%b %d, %Y"
  method = :strftime
  # Whoops, it looks like I passed a bad value to Timex here
  Timex.format!(nil, template, method)
end

Trying to render this page produces an exception:

Request: GET /
** (exit) an exception was raised:
    ** (ArgumentError) invalid_date
        (timex) lib/format/datetime/formatter.ex:60: Timex.Format.DateTime.Formatter.lformat!/4
        (rtl) lib/rtl_web/templates/home/index.html.eex:3: RTLWeb.HomeView."index.html"/1
        (rtl) lib/rtl_web/templates/layout/app.html.eex:27: RTLWeb.LayoutView."app.html"/1
        ...

Understandably, Timex.format!/3 doesn't like the nil and it blows up. But wait, why isn't my format_date/1 helper mentioned in the stacktrace? After all, that helper is where the error is. And the code definitely runs through that function; if I change the above nil to pass the date var, the error disappears.

I could look at the template code to infer that this particular helper was called, but I can't tell what line the error was on. If the function is long or involves several Timex calls, I could easily end up confused about which particular call errored out.

Example 2: A context function is omitted

Here's another example. In this case, my controller is calling a context helper to fetch an Ecto record.

# The controller action:
def index(conn, _params) do
  # Whoops, looks like I hard-coded the project id by accident
  project = MyContext.get_project!(42)
  render(conn, "index.html", project: project)
end

# The MyContext context defines `get_project!/1` to fetch that id from the repo:
def get_project!(id) do
  Repo.get!(Project, id)
end

As expected, when I run my controller test, I get an Ecto.NoResultsError because no project exists with that id. But again, I notice that the call to MyContext.get_project!/1 isn't included in the stacktrace:

** (Ecto.NoResultsError) expected at least one result but got none in query:

from p in RTL.Projects.Project,
  where: p.id == ^42

code: conn = get(conn, Routes.home_path(conn, :index))
stacktrace:
  (ecto) lib/ecto/repo/queryable.ex:80: Ecto.Repo.Queryable.one!/4
  (rtl) lib/rtl_web/controllers/home_controller.ex:5: RTLWeb.HomeController.index/2
  (rtl) lib/rtl_web/controllers/home_controller.ex:1: RTLWeb.HomeController.action/2
  (rtl) lib/rtl_web/controllers/home_controller.ex:1: RTLWeb.HomeController.phoenix_controller_pipeline/2
  ...

Even weirder, I notice that if I add a statement at the end of get_project/1 like this, the stacktrace changes to include that line.

# When I add this nil at the tail...
def get_project!(id) do
  Repo.get!(Project, id)
  nil
end

# The stacktrace includes the function call.
...
(ecto) lib/ecto/repo/queryable.ex:80: Ecto.Repo.Queryable.one!/4
(rtl) lib/rtl/projects/projects.ex:12: RTL.Projects.get_project!/1
(rtl) lib/rtl_web/controllers/home_controller.ex:5: RTLWeb.HomeController.index/2
...

But if I move that nil to the top of the function, the line disappears from the stacktrace again.

# When I move the nil to above the Repo.get! call...
def get_project!(id) do
  nil
  Repo.get!(Project, id)
end

# The stacktrace excludes the function call.
...
(ecto) lib/ecto/repo/queryable.ex:80: Ecto.Repo.Queryable.one!/4
(rtl) lib/rtl_web/controllers/home_controller.ex:5: RTLWeb.HomeController.index/2
...

Example 3: Test assertion helpers are omitted

Here's a controller test that calls an assertion helper that calls another helper that calls another helper that finally fails an assertion. But in my test failure stacktrace, I don't see any indication that those helpers are called; I only get the highest-level line in my test block.

# The test example and helpers:
test "#index renders the page", %{conn: conn} do
  conn = get(conn, Routes.home_path(conn, :index))
  assert_foo("foo")
  assert html_response(conn, 200) =~ "bring personal storytelling back"
end

defp assert_foo(object) do
  assert_bar(object)
end

defp assert_bar(object) do
  assert_baz(object)
end

defp assert_baz(object) do
  learn_secret_of_life(object)
end

defp learn_secret_of_life(object) do
  assert object == "elixir"
end

# The test failure message:
Assertion with == failed
code:  assert object == "elixir"
left:  "foo"
right: "elixir"
stacktrace:
  test/rtl_web/controllers/home_controller_test.exs:6: (test)

If I raise an exception in the sub-sub-sub-helper, rather than simply making a doomed assertion, the stacktrace mentions the final helper method, but continues to omit the in-between ones:

# Modified helper function:
defp learn_secret_of_life(object) do
  assert object == raise("OMG")
end

# Now the stacktrace includes this helper, but not any of the chain of helpers that lead to its invocation:
** (RuntimeError) OMG
code: assert_foo("foo")
stacktrace:
  test/rtl_web/controllers/home_controller_test.exs:23: RTLWeb.HomeControllerTest.learn_secret_of_life/1
  test/rtl_web/controllers/home_controller_test.exs:6: (test)

Obviously, in this contrived example, the chain of calls can be easily traced. But in the real-world app I've been troubleshooting lately, I might need to bounce between several different modules to understand where an exception got called, which is a little stressful when I can't count on each of those chain-links to show up in the reported stacktrace. I guess I thought that the job of a stacktrace was to, you know, list each of the files and lines of code that were being executed at the time that the exception occurred. So I'm super confused by the behavior shown above.

My questions:

• Why does Elixir sometimes omit certain files / lines from the stacktrace?
• Is there any way to tell it please don't do that?
• Is it only me who's confused by this?

Answer 1

This happens because of tail call optimisation.

Normally, a function has a stack frame containing its local variables and the address of the caller. When it calls another function, another stack frame is added on top, and when the function returns, it discards the stack frame and jumps back to the caller.

However, when the very last thing that a function does is calling another function, there is no need to keep the stack frame, since it's going to be discarded right after the inner function returns. Instead, the stack frame for the inner function replaces the stack frame for the outer function.

This has the advantage that recursive functions use a constant amount of stack space, but as you've noticed it has the disadvantage that stack traces in errors are incomplete.

---

To avoid this, change the code so that the inner function call is no longer the last thing that the outer function does. As you've noticed, returning nil instead of the return value of the inner function works - that's what I would do for the assert helper. For non-test code, I would be more reluctant to do this, as tail call optimisation is normally what you want: it reduces memory usage and execution time. Though it looks like it might be worth doing it for functions called from templates, just for increased debuggability.

---

You're definitely not the only one who's confused by this: this is frequent enough to be mentioned in the Erlang FAQ. See also the discussion in https://github.com/elixir-lang/elixir/issues/6357.