Elixir/Phoenix：为什么我的异常堆栈跟踪中没有显示某些文件/行？

Question

每天在我的 Phoenix 应用程序中浏览错误堆栈跟踪时，我注意到某些肯定正在执行的文件没有显示在堆栈跟踪中。

示例 1：省略了视图辅助方法

这是一个涉及从我的模板调用的format_date 助手的示例。代码：

# 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

尝试渲染此页面会产生异常：

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

可以理解，Timex.format!/3 不喜欢nil 并且它爆炸了。但是等等，为什么堆栈跟踪中没有提到我的format_date/1 助手？毕竟，那个助手是错误所在。并且代码肯定会通过该函数运行；如果我将上面的nil 更改为传递date var，错误就会消失。

我可以查看模板代码来推断调用了这个特定的帮助程序，但我不知道错误出现在哪一行。如果函数很长或涉及多个 Timex 调用，我很容易最终会混淆哪个特定调用出错了。

示例 2：省略了上下文函数

这是另一个例子。在这种情况下，我的控制器正在调用上下文助手来获取 Ecto 记录。

# 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

正如预期的那样，当我运行控制器测试时，我得到了一个Ecto.NoResultsError，因为不存在具有该 ID 的项目。但同样，我注意到对 MyContext.get_project!/1 的调用不包含在堆栈跟踪中：

** (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
  ...

更奇怪的是，我注意到如果我像这样在 get_project/1 的末尾添加一个语句，堆栈跟踪会更改以包含该行。

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

但如果我将 nil 移到函数的顶部，该行会再次从堆栈跟踪中消失。

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

示例 3：省略了测试断言助手

这是一个控制器测试，它调用一个断言助手，该助手调用另一个助手，该助手调用另一个助手，最终使断言失败。但是在我的测试失败堆栈跟踪中，我没有看到任何迹象表明这些助手被调用了；我只得到了测试块中最高级别的行。

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

如果我在 sub-sub-sub-helper 中引发异常，而不是简单地做出注定要失败的断言，stacktrace 会提到最终的 helper 方法，但会继续省略中间的方法：

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

显然，在这个人为的例子中，调用链可以很容易地跟踪。但是在我最近一直在进行故障排除的实际应用程序中，我可能需要在几个不同的模块之间跳转以了解异常被调用的位置，当我不能指望每个链接到显示在报告的堆栈跟踪中。我想我认为堆栈跟踪的工作是列出异常发生时正在执行的每个文件和代码行。所以我对上面显示的行为感到非常困惑。

我的问题：

• 为什么 Elixir 有时会从堆栈跟踪中省略某些文件/行？
• 有没有办法告诉它请不要那样做？
• 只有我对此感到困惑吗？

Answer 1

这是由于尾调用优化而发生的。

通常，函数有一个堆栈帧，其中包含其局部变量和调用者的地址。当它调用另一个函数时，会在顶部添加另一个堆栈帧，当函数返回时，它会丢弃堆栈帧并跳转回调用者。

但是，当一个函数做的最后一件事是调用另一个函数时，没有必要保留堆栈帧，因为它会在内部函数返回后立即被丢弃。相反，内部函数的堆栈框架替换外部函数的堆栈框架。

这具有递归函数使用恒定数量的堆栈空间的优点，但正如您所注意到的那样，它的缺点是错误中的堆栈跟踪不完整。

---

为避免这种情况，请更改代码，使内部函数调用不再是外部函数执行的最后一件事。正如您所注意到的，返回 nil 而不是内部函数的返回值是有效的——这就是我为 assert 助手所做的。对于非测试代码，我更不愿意这样做，因为尾调用优化通常是你想要的：它减少了内存使用和执行时间。虽然看起来对从模板调用的函数来说可能值得这样做，只是为了提高可调试性。

---

你肯定不是唯一一个对此感到困惑的人：这种情况经常出现mentioned in the Erlang FAQ。另请参阅https://github.com/elixir-lang/elixir/issues/6357 中的讨论。