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以通过datevar，则错误消失。

我可以看一下模板代码来推断该特定的帮助程序已被调用，但是我无法确定错误所在的行。如果函数很长或涉及多个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的项目。但是再次，我注意到对call的调用MyContext.get_project!/1不包含在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
  ...

甚至很奇怪，我也注意到，如果我在这样的末尾添加一条语句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移到函数顶部，则该行再次从stacktrace中消失。

# 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：省略测试断言助手

这是一个控制器测试，该测试调用一个断言帮助器，该断言帮助器又调用另一个帮助器，该另一个帮助器又调用另一个最终使声明失败的帮助器。但是在我的测试失败stacktrace中，我看不到任何迹象表明这些助手被调用了。我只能在测试块中获得最高级别的代码。

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

显然，在这个人为的示例中，可以轻松地跟踪调用链。但是，在我最近进行的实际应用中，我一直在进行故障排除，我可能需要在几个不同的模块之间跳动，以了解在何处调用了异常，这在我无法指望每个链接时都有些压力。显示在报告的堆栈跟踪中。我想我以为stacktrace的工作是列出异常发生时正在执行的每个文件和代码行。因此，我对上面显示的行为感到非常困惑。

我的问题：

• 为什么Elixir有时会从stacktrace中省略某些文件/行？
• 有什么办法告诉它，请不要这样做？
• 只是我对此感到困惑吗？

Answer 1

发生这种情况是由于尾部呼叫优化。

通常，函数具有一个堆栈框架，其中包含其局部变量和调用者的地址。当它调用另一个函数时，另一个堆栈框架被添加到顶部，当该函数返回时，它丢弃该堆栈框架并跳回到调用方。

但是，当一个函数执行的最后一件事是调用另一个函数时，则无需保留堆栈帧，因为在内部函数返回后它将立即被丢弃。而是，内部功能的堆栈框架替换了外部功能的堆栈框架。

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

为避免这种情况，请更改代码，以使内部函数调用不再是外部函数要做的最后一件事。正如您所注意到的，返回nil而不是内部函数的返回值都可以工作-这就是我对断言助手的处理方式。对于非测试代码，我将更不愿意执行此操作，因为通常需要您执行尾部调用优化：它可以减少内存使用和执行时间。尽管看起来对于从模板调用的函数来说值得这样做，但仅仅是为了提高可调试性。

您绝对不是唯一对此感到困惑的人：这很常见，足以在Erlang FAQ中提到。另请参见https://github.com/elixir-lang/elixir/issues/6357中的讨论。