Spandex Decorators seem to be causing some problems during `mix release`

[wizardone]

👋
I realise that the title might be a bit misleading and there is a chance that the problem lies elsewhere, but I hope you can assist me in this.

Environment:

Erlang/OTP 22 [erts-10.7] [source] [64-bit] [smp:2:2] [ds:2:2:10] [async-threads:1]

Elixir 1.9.4 (compiled with Erlang/OTP 22)

Relevant parts of my mix.exs file:

{:spandex, "~> 2.4"},
      {:spandex_datadog, "~> 0.4"},
      {:spandex_phoenix, "~> 0.3"},
      {:spandex_ecto, "~> 0.4"},
      {:decorator, "~> 1.3"}

In short: I inherited a phoenix app and I have to add some Datadog tracing. I've added everything required, following the docs + a small custom module to use in every module that I would like to be traced:

defmodule MyService.Tracer do

  # All the required default tracer stuff here

  defmodule ModuleTracer do
    defmacro __using__(_opts) do
      quote do
        use Spandex.Decorators

        @decorate_all span()
      end
    end
  end
end

And the intended usage is:

defmodule MyService.SomeModule do
  # I want to span everything happening in this module
  use MyService.Tracer.ModuleTracer
end

Now whenever I build my docker image I always get an error on the mix release step:

== Compilation error in file lib/my_service/some_module.ex ==
** (CompileError) lib/my_service/some_module.ex:1: module nil is not loaded and could not be found
    (stdlib) erl_eval.erl:680: :erl_eval.do_apply/6
    /lib/my_service/some_module.ex:1: Decorator.Decorate.before_compile/1

Some quick notes:

• The error is always in the module that "uses" the ModuleTracer.
• If I don't "use" it anywhere the mix release is successful and the build succeeds.

Am I trying to do something stupid here? That's the first time I am using the spandex-project so maybe I am messing up something.
Would really appreciate your help, thank you :)

[zachdaniel]

Hm...what happens if you add the use and the @decorate_all directly into a module? I haven’t ever tested it with @decorate_all. Didn’t even know that was a thing, honestly.

[wizardone]

@zachdaniel Thanks for the quick reply. I have added the use and @decorate_all straight into the module. Exactly the same error...

[zachdaniel]

Makes sense. And what if you just decorate a single function in the module?

[wizardone]

@zachdaniel
Using span or trace, both with and without arguments

@decorate span()
def my_function() do: end

always results in the same error...

As I said I am new to spandex, so am not completely sure if we are following breadcrumbs. Here is the relevant config in config.exs, in case it makes any difference:

config :my_service, MyService.Tracer,
  service: :name_of_service,
  adapter: SpandexDatadog.Adapter,
  disabled?: false,
  env: System.get_env("ENV_NAME")

config :spandex_phoenix,
  tracer: MyService.Tracer

config :spandex_ecto, SpandexEcto.EctoLogger, tracer: MyService.Tracer

config :spandex, :decorators, tracer: MyService.Tracer

And the tracer:

defmodule MyService.Tracer do
  @moduledoc """
  Spandex Tracer for service. Bounds datadog and other tracing configuration
  """

  use Spandex.Tracer, otp_app: :my_app

  def datadog_opts do
    [
      host: System.get_env("DD_ADDR") || "localhost",
      port: System.get_env("DD_PORT") || 8126,
      batch_size: 1,
      sync_threshold: 100,
      http: HTTPoison,
      verbose?: true
    ]
  end

  def current_trace_id_string do
    string_integer(current_trace_id())
  end

  def current_span_id_string do
    string_integer(current_span_id())
  end

  defp string_integer(nil), do: "0"
  defp string_integer(integer), do: to_string(integer)

  defmodule ModuleTracer do
    defmacro __using__(_opts) do
      quote do
        use Spandex.Decorators

        @decorate_all span()
      end
    end
  end
end

[GregMefford]

What if you do @decorate span() above a few single functions? Does that compile and work? That’s the only way I’ve personally used the decorators, but I’ve heard that others use @decorate_all successfully.

Also, does any combination of these things work when not using releases?

I’m just trying to narrow down what works and doesn’t work, because we’ve been successfully migrating to Elixir Releases recently, but potentially something has broken particularly in the combination of Elixir/OTP you’re using.

[GregMefford]

Oh I see you already tried just decorating a single module and it didn’t work. That’s very curious... 🧐🤔

[zachdaniel]

I believe the otp_app configuration is wrong. It needs to be the same as the first argument in the config. Like config :my_app, MyMod

[wizardone]

Sorry about that, I was just replacing the actual name of the app with my_service/my_app
The config is identical, as in:
In config:

config :my_service, MyService.Tracer,
  service: :voucher,
  adapter: SpandexDatadog.Adapter,
  disabled?: false,
  env: System.get_env("ENV_NAME")

In Tracer:

use Spandex.Tracer, otp_app: :my_service

On a sidenote I just ran MIX_ENV=prod mix release locally successfully and I can start the app with mix phx.server just fine...Not sure why the docker build fails

Here is my Dockerfile:

FROM elixir:1.9.4-alpine AS app_builder
RUN apk add --no-cache gcc g++ git make

RUN mix do local.hex --force, local.rebar --force	

FROM app_builder as deps
COPY mix.exs mix.lock ./
ENV MIX_ENV=prod
RUN mix do deps.get --only=$MIX_ENV, deps.compile

FROM deps as releaser
COPY config ./config
COPY lib ./lib
COPY priv ./priv
RUN mix release 

FROM alpine as app
RUN apk add --no-cache bash libstdc++ openssl
EXPOSE 4000
COPY --from=releaser ./_build .
CMD ["sh","-c","./prod/rel/my_app/bin/my_app start"]

[GregMefford]

I didn’t have a chance yet to verify, but you might need to change ENV MIX_ENV=prod to ARG MIX_ENV=prod and pass that in as a —build-arg or else it might not carry over to the next stage like you expect and it might be doing the release in dev mode whereas the deps are only fetched for prod mode. You could also try combining the deps and the releaser stages to see if that works properly. Just a wild guess.

[wizardone]

I did try to change a couple of things re: the docker config but nothing seems to work. Also the fact that the build succeeds as soon as I remove the decorate calls leads me to believe that this is somehow related to the decorators, I just can't make sense of the actual error :)
One other pointer that I have and might be useful is that a previous version of the Docker file, using elixir 1.8 and distillery for releases did not have that problem, while still using the exact same spandex code. I will try to reproduce the problem with a bare minimum new app to eliminate all potential side effects and will tell you the results.

[wizardone]

👋 I managed to reproduce the problem with a fresh phoenix app, using the same Docker file:

mix phx.new tracer_test --no-html --no-webpack
mix phx.gen.json Accounts User users name:string (something basic to use the tracer module in)
mix file:

defmodule TracerTest.MixProject do
  use Mix.Project

  def project do
    [
      app: :tracer_test,
      version: "0.1.0",
      elixir: "~> 1.9",
      elixirc_paths: elixirc_paths(Mix.env()),
      compilers: [:phoenix, :gettext] ++ Mix.compilers(),
      start_permanent: Mix.env() == :prod,
      aliases: aliases(),
      deps: deps()
    ]
  end

  # Configuration for the OTP application.
  #
  # Type `mix help compile.app` for more information.
  def application do
    [
      mod: {TracerTest.Application, []},
      extra_applications: [:logger, :runtime_tools]
    ]
  end

  # Specifies which paths to compile per environment.
  defp elixirc_paths(:test), do: ["lib", "test/support"]
  defp elixirc_paths(_), do: ["lib"]

  # Specifies your project dependencies.
  #
  # Type `mix help deps` for examples and options.
  defp deps do
    [
      {:phoenix, "~> 1.4.7"},
      {:phoenix_pubsub, "~> 1.1"},
      {:phoenix_ecto, "~> 4.0"},
      {:ecto_sql, "~> 3.0"},
      {:postgrex, ">= 0.0.0"},
      {:gettext, "~> 0.11"},
      {:jason, "~> 1.0"},
      {:plug_cowboy, "~> 2.0"},
      {:spandex, "~> 2.4"},
      {:spandex_datadog, "~> 0.4"},
      {:spandex_phoenix, "~> 0.3"},
      {:spandex_ecto, "~> 0.4"},
      {:decorator, "~> 1.3"}
    ]
  end

  # Aliases are shortcuts or tasks specific to the current project.
  # For example, to create, migrate and run the seeds file at once:
  #
  #     $ mix ecto.setup
  #
  # See the documentation for `Mix` for more info on aliases.
  defp aliases do
    [
      "ecto.setup": ["ecto.create", "ecto.migrate", "run priv/repo/seeds.exs"],
      "ecto.reset": ["ecto.drop", "ecto.setup"],
      test: ["ecto.create --quiet", "ecto.migrate", "test"]
    ]
  end
end

Config:

# This file is responsible for configuring your application
# and its dependencies with the aid of the Mix.Config module.
#
# This configuration file is loaded before any dependency and
# is restricted to this project.

# General application configuration
use Mix.Config

config :tracer_test,
  ecto_repos: [TracerTest.Repo]

# Configures the endpoint
config :tracer_test, TracerTestWeb.Endpoint,
  url: [host: "localhost"],
  secret_key_base: "WxUUs1viTsgEfy19PykE2p+4crTaZth4LVyyc00+9oXFp18zDBK9MoCmOELliQnJ",
  render_errors: [view: TracerTestWeb.ErrorView, accepts: ~w(json)],
  pubsub: [name: TracerTest.PubSub, adapter: Phoenix.PubSub.PG2]

# Configures Elixir's Logger
config :logger, :console,
  format: "$time $metadata[$level] $message\n",
  metadata: [:request_id]

# Use Jason for JSON parsing in Phoenix
config :phoenix, :json_library, Jason

# Datadog tracing
config :tracer_test, TracerTest.Tracer,
  service: :voucher,
  adapter: SpandexDatadog.Adapter,
  disabled?: false,
  env: System.get_env("ENV_NAME") || "development"

config :spandex_phoenix,
  tracer: TracerTest.Tracer

config :spandex_ecto, SpandexEcto.EctoLogger, tracer: TracerTest.Tracer

config :spandex, :decorators, tracer: TracerTest.Tracer

# Import environment specific config. This must remain at the bottom
# of this file so it overrides the configuration defined above.
import_config "#{Mix.env()}.exs"

Tracer:

defmodule TracerTest.Tracer do
  @moduledoc """
  Spandex Tracer for service. Bounds datadog and other tracing configuration
  """

  use Spandex.Tracer, otp_app: :voucher_service

  def datadog_opts do
    [
      host: System.get_env("DD_ADDR") || "localhost",
      port: System.get_env("DD_PORT") || 8126,
      batch_size: 1,
      sync_threshold: 100,
      http: HTTPoison,
      verbose?: true
    ]
  end

  def current_trace_id_string do
    string_integer(current_trace_id())
  end

  def current_span_id_string do
    string_integer(current_span_id())
  end

  defp string_integer(nil), do: "0"
  defp string_integer(integer), do: to_string(integer)

  defmodule ModuleTracer do
    defmacro __using__(_opts) do
      quote do
        use Spandex.Decorators

        @decorate_all span()
      end
    end
  end
end

I guess my next step would be to test against elixir 1.8, using distillery.

[benwilson512]

Where is ENV_NAME set? You're pulling it at compile time but I don't see it as a build arg or env in the docker file.

[zumbalogy]

I had a potentially related issue that others coming here might have.
I was locally getting the following when running mix test but it mix phx.start was fine. It was in a worker/supervisor separate from the rest of our Phoenix stuff.

== Compilation error in file foo.ex ==
** (CompileError) foo:3: module Spandex.Decorators is not loaded and could not be found
    (elixir 1.10.2) expanding macro: Kernel.use/1
    foo.ex:3: Foo.Bar.Baz (module)

But CI server was fine. Changing the decorator lib to be {:decorator, "1.2.3"} and then running it worked, and then changing it back to the latest (1.3.2) it now works fine. Not confidence inspiring, and potentially user error, but maybe this can help someone.

[wizardone]

I managed to resolve the issue.
I settled on this Dockerfile:

# ---- Build Base Stage ----
FROM elixir:1.9.4-alpine AS app_builder
RUN apk add --no-cache gcc g++ git make

RUN mix do local.hex --force, local.rebar --force	

# ---- Main Build Stage ----
WORKDIR app/
FROM app_builder AS releaser
COPY mix.exs mix.lock ./
ARG MIX_ENV=prod
ENV MIX_ENV=$MIX_ENV
RUN mix deps.get -- only=$MIX_ENV
COPY config ./config
COPY lib ./lib
COPY priv ./priv
RUN mix release 

# ---- Final Image Stage ----
FROM alpine as app
RUN apk add --no-cache bash libstdc++ openssl
EXPOSE 4000
COPY --from=releaser ./app/_build .
CMD ["sh","-c","./prod/rel/my_app/bin/my_app start"]

Apart from the slight rearranging the main thing is that I removed mix deps.compile (The command used to be RUN mix do deps.get --only=$MIX_ENV, deps.compile)
While debugging the build I noticed that a _build folder was already generated for me before I run mix release, so I decided to manually delete it as a step and...voala, everything worked. I saw that the folder was generated by mix deps.compile, so I removed that step completely(maybe it was unnecessary from the start?).
In any case I would be really interested in hearing a rational explanation as to why this happened in the first place, was it just completely wrong to use mix deps.compile?

Thanks to everyone who jumped in here and helped!

[zachdaniel]

Since the workaround was documented here, we can close this.

[quintinm-dev]

@zumbalogy FWIW, I was able to solve this without removing mix deps.compile, which isn't ideal as it prevents dependency layer caching. My issue was that config.exs contained Spandex configuration, and therefore needed to be copied to the container prior to running mix deps.compile. The Phoenix sample Dockerfile was particularly helpful.