:undef to 500 response when running tests

Questions / Help
, ,
1

When I run my tests, I get a :undef to 500 response if a method do not exist. This does not happen when I run in dev, and I am pretty sure it is something I have done with some configs at some point. The problem is that I can’t understand where or how, and it is starting to get annoying.

My configs for logger in config.exs is:

# Our Logger application configuration (affects all logging)
config :logger,
  backends: [
    :console
  ],
  compile_time_purge_matching: [
    [level_lower_than: :info]
  ]

# Our Console Backend-specific configuration
config :logger, :console,
  format: {AppName.LogFormatter, :format},
  metadata: [:request_id, :crash_reason, :user_id],
  level: :debug

In test.exs

config :logger, level: :info

And my LogFormatter

  def format(level, message, timestamp, metadata) do
    "##### #{format_timestamp(timestamp, level)} #{format_metadata(metadata)} [#{level}] #{
      message
    }\n"
  rescue
    _ -> "Could not format message: #{inspect({level, message, timestamp, metadata})}\n"
  end

  defp format_timestamp({{_year, _month, _date}, {hh, mm, ss, _ms}}, :debug) do
    Integer.to_string(hh) <> ":" <> Integer.to_string(mm) <> ":" <> Integer.to_string(ss)
  end

  defp format_timestamp({{year, month, date}, {hh, mm, ss, ms}}, _level) do
    %DateTime{
      year: year,
      month: month,
      day: date,
      zone_abbr: "UTC",
      hour: hh,
      minute: mm,
      second: ss,
      microsecond: {ms, 0},
      utc_offset: 0,
      std_offset: 0,
      time_zone: "Etc/UTC"
    }
    |> DateTime.to_string()
  end

  defp format_metadata(metadata) do
    metadata
    |> output_file_and_line
  end

  defp output_file_and_line(metadata) do
    case {Keyword.get(metadata, :file), Keyword.get(metadata, :line)} do
      {nil, nil} -> ""
      {file, line} -> file <> ":" <> Integer.to_string(line)
    end
  end

Any help would be greatly appreciated!

2

I looked at what you posted and did not see a problem – on its face.

I tried to recreate your error, but everything seems to be working as programmed. What function call is causing the error?

3

I have noticed that the error occur when there an undefined function is called or if it doesn’t match the parameters of a defined function.

4

Edit: I see that more errors, e.g. :undef and :badarith doesn’t get handled property, and just shown as “Converted error :badarith to 500 response”

5

I am not sure what is happening here, but badarith and undef are both Erlang errors. Normally, in a try/rescue clause, they would be translated to an equivalent Elixir error. Maybe that gives you hints in the right direction?

One question: is this a Phoenix app? Any more info on the particular app that might be useful?

6

In addition to @lucaong questions, do you get any stacktrace? If something is logged or if a test fails, please try to include everything that is printed in the terminal as that can help identify the root cause.

7

Yeah, I have previous thought it might be an Erlang error and tried to use IO.error to print a stacktrace, but without getting anything that was actually useful.

I have Phoenix 1.4.16 backend and Elixir 1.9 backend, but with Elm frontend.

The deps in mix.exs:

 [
      {:phoenix, "~> 1.4.16"},
      {:phoenix_pubsub, "~> 1.0"},
      {:phoenix_ecto, "~> 4.1.0"},
      {:postgrex, "~> 0.14.3"},
      {:phoenix_html, "~> 2.13"},
      {:phoenix_live_reload, "~> 1.2.1", only: [:dev, :e2e, :personal]},
      {:gettext, "~> 0.17.4"},
      {:plug_cowboy, "~> 2.0"},
      {:plug, "~> 1.9"},
      {:csv, "~> 2.3.1"},
      {:timex, "~> 3.6.1"},
      {:decimal, "~> 1.6"},
      {:number, "~> 1.0.1"},
      {:arc_ecto, "~> 0.11.3"},
      {:phoenix_slime, "~> 0.12.0"},
      {:dialyxir, "~> 1.0.0", only: [:dev], runtime: false},
      {:scrivener_ecto, "~> 2.2.0"},
      {:ex_machina, "~> 2.4.0"},
      {:excoveralls, "~> 0.10.6", only: :test},
      {:scribe, "~> 0.8"},
      {:bamboo, "~> 1.4"},
      {:xlsxir, "~> 1.6.4"},
      {:timber, "~> 3.1.2"},
      {:timber_ecto, "~> 2.0"},
      {:inquisitor, "~> 0.5.0"},
      {:inquisitor_jsonapi, "~> 0.1.0"},
      {:ex_doc, "~> 0.19.0", only: :dev, runtime: false, override: true},
      {:distillery, "~> 2.1"},
      {:bcrypt_elixir, "~> 2.2"},
      {:comeonin, "~> 5.3.1"},
      {:recase, "~> 0.6.0"},
      {:db_connection, "~> 2.0.6"},
      {:ecto, "~> 3.1.7"},
      {:ecto_enum, "~>1.4.0"},
      {:ecto_sql, "~> 3.1.6"},
      {:corsica, "~> 1.1.3"},
      {:httpoison, "~> 1.6.2"},
      {:sentry, "~> 7.2.4"},
      {:sobelow, "~> 0.10.1", only: :dev},
      {:pot, "~> 0.10.2"},
      {:pow, "~> 1.0.19"},
      {:mock, "~> 0.3.0", only: :test},
      {:hammer, "~> 6.0"},
      {:accent, "~> 1.0"},
      {:jason, "~> 1.0"}
8

No, no stacktrace. I have tried to use IO.error in the logformatter to get stacktrace, but it didn’t give me any useful. In test-environment, all I get is that formatted message with the atom for what is wrong. If I am in dev or prod, I get the whole stacktrace as expected.

9

Thanks for the info @teatimes! Unfortunately I still cannot figure out why this is happening. I would need a way to reproduce the issue locally, but setting up a reproduction app may be non-trivial.

10

That’s okey. I might try to recreate the project and add one and one dependency, to see if that might have something to do with the case. Anyway, thank you for the effort!

11

Update:

So, I tried to create an empty project an in iterations add the dependencies and configs. I found out that by changing level in

config :logger, level :info

to :warn, I no longer received Converted error :function_clause to 500 response.

I further added Logger.error(error) to render() in ErrorView, and while it still converts an error and prints it as 500.json, I at least now also get the actual error printed, e.g. FunctionClauseError with a more detailed description of what caused the error.

2 Likes