Production Error: Function Mix.Compilers.ApplicationTracer.trace/2 is undefined

In a nutshell I have an error in production that I don’t have in development while using the same versions for all the software involved.

Environment

  • Elixir version (elixir -v):
$ ./bin/tasks remote
Erlang/OTP 23 [erts-11.1.6] [source] [64-bit] [smp:1:1] [ds:1:1:10] [async-threads:1]

Interactive Elixir (1.11.3) - press Ctrl+C to exit (type h() ENTER for help)
  • Domo version (mix deps | grep domo | head -1):
$ mix deps | grep domo | head -1
* domo 1.0.1 (Hex package) (mix)
  • TypedStruct version (mix deps | grep typed_struct | head -1):
$ mix deps | grep typed_struct | head -1
* typed_struct 0.2.1 (Hex package) (mix)

I run it in development and in production with the docker image from the Phoenix releases docs:

https://hexdocs.pm/phoenix/releases.html#containers

Versions used to build the docker image:

ELIXIR_VERSION=1.11.3
ERLANG_OTP_VERSION=23.2.2
ALPINE_VERSION=3.12.1

Actual behavior

The error from a production release:

 09:20:32.459 | error | module=gen_server function=error_info/7 line=943  | GenServer #PID<0.2551.0> terminating
app_1  | ** (UndefinedFunctionError) function Mix.Compilers.ApplicationTracer.trace/2 is undefined (module Mix.Compilers.ApplicationTracer is not available)
app_1  |     Mix.Compilers.ApplicationTracer.trace({:alias_reference, [line: 45], NaiveDateTime}, #Macro.Env<aliases: [], context: nil, context_modules: [TypeIt.Progress], file: "/app/lib/type_it/lib/progress.ex", function: nil, functions: [{Kernel, [!=: 2, !==: 2, *: 2, ...]}], lexical_tracker: #PID<3.316.0>, line: 42, macro_aliases: [], macros: [{Domo, ...}, {...}], module: TypeIt.Progress, requires: [...], ...>)
app_1  |     (elixir 1.11.3) src/elixir_env.erl:36: :elixir_env."-trace/2-lc$^0/1-0-"/3
app_1  |     (elixir 1.11.3) src/elixir_env.erl:36: :elixir_env.trace/2
app_1  |     (elixir 1.11.3) lib/macro.ex:1440: Macro.do_expand_once/2
app_1  |     (elixir 1.11.3) lib/macro.ex:1610: Macro.expand_until/2
app_1  |     (domo 1.0.1) lib/domo/type_spec_matchable/remote_type.ex:11: Domo.TypeSpecMatchable.RemoteType.expand/2
app_1  |     (domo 1.0.1) lib/domo/type_contract.ex:642: Domo.TypeSpecMatchable.Any.match_spec?/3
app_1  |     (tasks 0.1.0) lib/type_it/lib/progress.ex:42: TypeIt.Progress.TypeChecker.__field_error/1

The Typed Struct code:

defmodule TypeIt.Progress do

  use Domo

  @all_states %{
    backlog: "Backlog",
    todo: "Todo",
    doing: "Doing",
    pending: "Pending",
    done: "Done",
    archived: "Archived",
  }

  @states Map.keys(@all_states)

  typedstruct do
    field :state, :backlog | :todo | :doing | :pending | :done | :archived
    field :title, String.t()
    field :since, NaiveDateTime.t()
  end

  def default(), do: new_for!(:todo)

  def next_state(:backlog), do: :todo
  def next_state(:todo), do: :done
  def next_state(:done), do: :todo

  def new_for!(state), do: new!(state: state, title: @all_states[state], since: NaiveDateTime.utc_now())
  def new_for!(state, since: since), do: new!(state: state, title: @all_states[state], since: since)
  def new_for!(state, title: title), do: new!(state: state, title: title, since: NaiveDateTime.utc_now())

  def states() do
    @states
  end

  def all() do
    @all_states
  end
end

Expected behavior

In production is throwing the reported error that crashes the app, but in development it works ok.

Summary

Looking to this line in the logs:

Mix.Compilers.ApplicationTracer.trace({:alias_reference, [line: 45], NaiveDateTime}, 

It seems the error is related with using:

field :since, NaiveDateTime.t()

but I don’t get why I don’t have the same error in development, when using the same exact versions of Elixir, Phoenix, OTP, and Domo library :thinking:

Any ideas?

I discovered the function ModuleName.module_info and running it in my development setup and production release yields this results:

Production

Module TypeIt.Progress:

iex> TypeIt.Progress.module_info
[
  module: TypeIt.Progress,
  exports: [
    __info__: 1,
    __struct__: 0,
    __struct__: 1,
    __tags__: 0,
    all: 0,
    default: 0,
    new_for!: 1,
    new_for!: 2,
    next_state: 1,
    states: 0,
    merge: 2,
    merge!: 2,
    new: 0,
    new: 1,
    new!: 0,
    new!: 1,
    put: 3,
    put!: 3,
    module_info: 0,
    module_info: 1
  ],
  attributes: [vsn: [108004656685435456836371178347728999311]],
  compile: [],
  md5: <<81, 64, 240, 179, 218, 245, 244, 243, 26, 20, 101, 206, 39, 68, 19,
    143>>
]

Module NaiveDateTime:

iex> NaiveDateTime.module_info
[
  module: NaiveDateTime,
  exports: [
    __info__: 1,
    __struct__: 0,
    __struct__: 1,
    add: 2,
    add: 3,
    compare: 2,
    convert: 2,
    convert!: 2,
    diff: 2,
    diff: 3,
    from_erl: 1,
    from_erl: 2,
    from_erl: 3,
    from_erl!: 1,
    from_erl!: 2,
    from_erl!: 3,
    from_gregorian_seconds: 1,
    from_gregorian_seconds: 2,
    from_gregorian_seconds: 3,
    from_iso8601: 1,
    from_iso8601: 2,
    from_iso8601!: 1,
    from_iso8601!: 2,
    local_now: 0,
    local_now: 1,
    new: 2,
    new: 6,
    new: 7,
    new: 8,
    new!: 2,
    new!: 6,
    new!: 7,
    new!: 8,
    to_date: 1,
    to_erl: 1,
    to_gregorian_seconds: 1,
    to_iso8601: 1,
    to_iso8601: 2,
    to_string: 1,
    to_time: 1,
    truncate: 2,
    utc_now: 0,
    utc_now: 1,
    module_info: 0,
    module_info: 1
  ],
  attributes: [vsn: [19129072002618629112922607679545684726]],
  compile: [],
  md5: <<14, 100, 32, 16, 229, 121, 12, 168, 97, 111, 246, 205, 147, 62, 50,
    246>>
]

Development

Module TypeIt.Progress:

iex> TypeIt.Progress.module_info
[
  module: TypeIt.Progress,
  exports: [
    __info__: 1,
    __struct__: 0,
    __struct__: 1,
    __tags__: 0,
    all: 0,
    default: 0,
    states: 0,
    merge: 2,
    merge!: 2,
    new: 0,
    new: 1,
    new!: 0,
    new!: 1,
    put: 3,
    put!: 3,
    module_info: 0,
    module_info: 1,
    next_state: 1,
    new_for!: 2,
    new_for!: 1
  ],
  attributes: [vsn: [108004656685435456836371178347728999311]],
  compile: [
    version: '7.6.6',
    options: [:no_spawn_compiler_process, :from_core, :no_core_prepare,
     :no_auto_import],
    source: '/home/developer/workspace/lib/type_it/lib/progress.ex'
  ],
  md5: <<81, 64, 240, 179, 218, 245, 244, 243, 26, 20, 101, 206, 39, 68, 19,
    143>>
]

Module NaiveDateTime:

iex> NaiveDateTime.module_info
[
  module: NaiveDateTime,
  exports: [
    __info__: 1,
    __struct__: 0,
    __struct__: 1,
    add: 3,
    compare: 2,
    convert!: 2,
    diff: 2,
    diff: 3,
    from_erl: 1,
    from_erl: 2,
    from_erl: 3,
    from_erl!: 2,
    from_erl!: 3,
    from_gregorian_seconds: 1,
    from_gregorian_seconds: 2,
    from_gregorian_seconds: 3,
    from_iso8601: 1,
    from_iso8601: 2,
    from_iso8601!: 1,
    from_iso8601!: 2,
    local_now: 0,
    local_now: 1,
    new: 6,
    new: 8,
    new!: 2,
    new!: 6,
    new!: 7,
    new!: 8,
    to_date: 1,
    to_gregorian_seconds: 1,
    to_iso8601: 2,
    to_string: 1,
    to_time: 1,
    truncate: 2,
    utc_now: 0,
    utc_now: 1,
    module_info: 0,
    module_info: 1,
    new: 2,
    convert: 2,
    add: 2,
    to_erl: 1,
    from_erl!: 1,
    new: 7,
    to_iso8601: 1
  ],
  attributes: [vsn: [19129072002618629112922607679545684726]],
  compile: [
    version: '7.6.3',
    options: [:no_spawn_compiler_process, :from_core, :no_core_prepare,
     :no_auto_import],
    source: '/home/build/elixir/lib/elixir/lib/calendar/naive_datetime.ex'
  ],
  md5: <<14, 100, 32, 16, 229, 121, 12, 168, 97, 111, 246, 205, 147, 62, 50,
    246>>
]

The Difference

Module TypeIt.Progress:

--- TypeIt.Progress.module_info
+++ TypeIt.Progress.module_info
@@ -8,9 +8,6 @@
     __tags__: 0,
     all: 0,
     default: 0,
-    new_for!: 1,
-    new_for!: 2,
-    next_state: 1,
     states: 0,
     merge: 2,
     merge!: 2,
@@ -21,10 +18,18 @@
     put: 3,
     put!: 3,
     module_info: 0,
-    module_info: 1
+    module_info: 1,
+    next_state: 1,
+    new_for!: 2,
+    new_for!: 1
   ],
   attributes: [vsn: [108004656685435456836371178347728999311]],
-  compile: [],
+  compile: [
+    version: '7.6.6',
+    options: [:no_spawn_compiler_process, :from_core, :no_core_prepare,
+     :no_auto_import],
+    source: '/home/developer/workspace/lib/type_it/lib/progress.ex'
+  ],
   md5: <<81, 64, 240, 179, 218, 245, 244, 243, 26, 20, 101, 206, 39, 68, 19,
     143>>
-]
+]

Module NaiveDateTime:

--- NaiveDateTime.module_info
+++ NaiveDateTime.module_info
@@ -1,21 +1,18 @@
-NaiveDateTime.module_info  
+NaiveDateTime.module_info
 [
   module: NaiveDateTime,
   exports: [
     __info__: 1,
     __struct__: 0,
     __struct__: 1,
-    add: 2,
     add: 3,
     compare: 2,
-    convert: 2,
     convert!: 2,
     diff: 2,
     diff: 3,
     from_erl: 1,
     from_erl: 2,
     from_erl: 3,
-    from_erl!: 1,
     from_erl!: 2,
     from_erl!: 3,
     from_gregorian_seconds: 1,
@@ -27,18 +24,14 @@
     from_iso8601!: 2,
     local_now: 0,
     local_now: 1,
-    new: 2,
     new: 6,
-    new: 7,
     new: 8,
     new!: 2,
     new!: 6,
     new!: 7,
     new!: 8,
     to_date: 1,
-    to_erl: 1,
     to_gregorian_seconds: 1,
-    to_iso8601: 1,
     to_iso8601: 2,
     to_string: 1,
     to_time: 1,
@@ -46,10 +39,22 @@
     utc_now: 0,
     utc_now: 1,
     module_info: 0,
-    module_info: 1
+    module_info: 1,
+    new: 2,
+    convert: 2,
+    add: 2,
+    to_erl: 1,
+    from_erl!: 1,
+    new: 7,
+    to_iso8601: 1
   ],
   attributes: [vsn: [19129072002618629112922607679545684726]],
-  compile: [],
+  compile: [
+    version: '7.6.3',
+    options: [:no_spawn_compiler_process, :from_core, :no_core_prepare,
+     :no_auto_import],
+    source: '/home/build/elixir/lib/elixir/lib/calendar/naive_datetime.ex'
+  ],
   md5: <<14, 100, 32, 16, 229, 121, 12, 168, 97, 111, 246, 205, 147, 62, 50,
     246>>
 ]

The + are for the development output. The differences in the exports seem to be only due to the order of the output from running the command in production and development.

I can observe that in other modules that I try module_info on I always get the compile info in development, but not in production.

So, I don’t see anything here that reveals a potential issue. Even the vsn and md5 are exactly the same between production and development.

I am really lost in how to debug this issue :thinking:

I imagine you don’t have mix in the prod env, or you’re not including it?

2 Likes

Hi @amnu3387 is on the right direction. I can confirm this is a bug and the root cause is that the application tracer used by Mix is not available in production and it should not be required either.

I need a small app that reproduces the error to understand if this is a Mix bug or a library/application bug. Given the fact it is expanding compilation code at runtime, I am more inclined to think it is the latter.

2 Likes

I feel stupid now… I completely forgot that Mix is only available in development or when compiling the release.

Totally makes sense.

I will work on one.

The library being used is Domo and I am also inclined to be a bug on it, and that was the reason I open first an issue in Github.

@josevalim here it is the proof of concept for the bug:

2 Likes

I assume the issue is around this line:

It is trying to save a compilation environment to use it to expand things at runtime. Not only this slow, it won’t work as you noticed. :slight_smile: They should do whatever expansion they need at compile time and remove the runtime expand calls.

2 Likes

Many thanks for your time on this Jose. I really appreciate that you have jumped on :slight_smile:

I will add your info to the Github issue, and see what @IvanR as to say.

Having the creator of the language interacting with us to help in issues or just discussions was one of the main drivers to make me stick around this forum, and by extension in Elixir :heart:

2 Likes

Many thanks for noticing this. I’m working on the version that expands types within a given environment at the compile-time only.
I intend to mark this lib as not production-ready till then.

@Exadra37 Let’s see what can be done, I’ll give an update on the GitHub issue.

3 Likes

The version 1.2.0 of the Domo library is released. It resolves types and generates struct specific validation code at compile time only. It was in development for a couple of months, and it seems this is a good time for the release :slightly_smiling_face:

This version obviously increases project compilation times that is a matter for further evaluation and optimization. It’d be nice to get feedback about compilation time changes.

Ensuring that the structure’s value matches the type with generated new/1 function comes at the cost of 1.2-1.5x slower operation comparing with struct!/1. Depending on the level of nestedness of structure types in each other and whether there are fields with lists, and how long they are.

At the same time, that can be ok for various business applications.

3 Likes

One thing you will also want to consider is that, depending on how you expand, you may end-up adding compile time dependencies to the referenced modules. Which will be much more impactful to compilation times than the time spent spending.

If you really don’t use those values at compile-time, then you should do this when expanding them:

Macro.expand(alias, %{function: {:new!, 1}})

So they are tagged as runtime expansions.

3 Likes

Increasing compilation times is a very good trade-off for not doing it at compile time :slight_smile:

It’s not an issue for my pet app, but would be nice to see future improvements here :slight_smile:

Doesn’t this make the library slow at runtime? If yes I prefer to pay the toll at compile time :slight_smile:

1 Like

No, it does not.

2 Likes

In Domo 1.2.2 there is a verification that a struct built at compile time matches its type. That works as the last step of compilation with the library’s custom compile task :smile:

The verification works for given modules as follows:

defmodule Planet.Bar do
  use Domo

  defstruct [:name]
  @type t :: %__MODULE__{name: String.t()}
end

defmodule Foo do
  use Domo

  alias Planet.Bar

  @default_name :coyote

  defstruct [bar: Bar.new(name: @default_name)]
  @type t :: %__MODULE__{bar: Bar.t()}
end

➜ ~ mix compile
Compiling 1 file (.ex)
Domo is compiling type ensurer for 2 modules (.ex)

== Compilation error in file lib/foo_bar.ex:15 ==
** Failed to build Planet.Bar struct.
Invalid value :coyote for field :name. Expected the value matching the <<::*8>> type.
➜ ~ echo $?
1

And with:

  @default_name "Coyote"

➜ ~ mix compile
Compiling 1 file (.ex)
Domo is compiling type ensurer for 2 modules (.ex)
➜ ~ echo $?
0

There is no Macro expansion during the Foo and Bar modules compilation with Elixir. Their environments are temporary stored for the :domo_compiler step. During the Domo compiler step, the expansion works like Macro.expand_once(Bar, foo_env) to get the full name of the Planet.Bar module. Then type ensurer modules code is generated and compiled, and Bar fields stored from the new call are ensured to match the type. Then Domo compiler step drops environments and compilation finishes.

It seems that it shouldn’t be additional compile/runtime dependencies for Foo and Bar modules with the process described above :slightly_smiling_face:

P.S. At the application’s runtime, Foo.new/1 and Bar.new/1 ensures that input fields match the type themselves or raises on mismatch.

4 Likes