Errors on Application.stop in simple Mix Task #212

shayne-lp · 2020-04-20T19:37:09Z

GenServer error in simple Mix Task
Hi there, I'm trying to instrument the following simple Mix Task:

defmodule Mix.Tasks.Foo.Test do
  use Mix.Task
  require Logger

  alias Foo.{
    Bar,
  }

  require Bar.Time

  @shortdoc "Test task for experiments"
  def run(_) do
    Mix.Task.run "app.start", []
    {status, started} = Application.ensure_all_started(:new_relic_agent)

    IO.inspect {status, started}

    {_, seconds} = Bar.Time.measure do
      task()
    end

    log "done in #{seconds} seconds."
    Application.stop(:new_relic_agent)
  end

  defp log(msg) do
    Logger.info msg
  end

  defp task do
    log "hello"
  end
end

but I keep getting this error:

test[info] [alarm_handler: {:set, {:system_memory_high_watermark, []}}]
{:ok, []}
[info] hello
[info] done in 0.007538 seconds.
[error] Task #PID<0.514.0> started from #PID<0.418.0> terminating
** (stop) exited in: GenServer.call(NewRelic.Harvest.Collector.TransactionEvent.HarvestCycle, :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/gen_server.ex:979: GenServer.call/3
    (new_relic_agent) lib/new_relic/harvest/collector/harvest_cycle.ex:40: NewRelic.Harvest.Collector.HarvestCycle.manual_shutdown/1
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<1.28298676/0 in NewRelic.Harvest.Supervisor.manual_shutdown/0>
    Args: []
[error] Task #PID<0.517.0> started from #PID<0.418.0> terminating
** (stop) exited in: GenServer.call(NewRelic.Harvest.Collector.CustomEvent.HarvestCycle, :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/gen_server.ex:979: GenServer.call/3
    (new_relic_agent) lib/new_relic/harvest/collector/harvest_cycle.ex:40: NewRelic.Harvest.Collector.HarvestCycle.manual_shutdown/1
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<1.28298676/0 in NewRelic.Harvest.Supervisor.manual_shutdown/0>
    Args: []
[error] Task #PID<0.515.0> started from #PID<0.418.0> terminating
** (stop) exited in: GenServer.call(NewRelic.Harvest.Collector.SpanEvent.HarvestCycle, :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/gen_server.ex:979: GenServer.call/3
    (new_relic_agent) lib/new_relic/harvest/collector/harvest_cycle.ex:40: NewRelic.Harvest.Collector.HarvestCycle.manual_shutdown/1
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<1.28298676/0 in NewRelic.Harvest.Supervisor.manual_shutdown/0>
    Args: []
[error] Task #PID<0.513.0> started from #PID<0.418.0> terminating
** (stop) exited in: GenServer.call(NewRelic.Harvest.Collector.TransactionTrace.HarvestCycle, :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/gen_server.ex:979: GenServer.call/3
    (new_relic_agent) lib/new_relic/harvest/collector/harvest_cycle.ex:40: NewRelic.Harvest.Collector.HarvestCycle.manual_shutdown/1
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<1.28298676/0 in NewRelic.Harvest.Supervisor.manual_shutdown/0>
    Args: []
[error] Task #PID<0.512.0> started from #PID<0.418.0> terminating
** (stop) exited in: GenServer.call(NewRelic.Harvest.Collector.Metric.HarvestCycle, :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/gen_server.ex:979: GenServer.call/3
    (new_relic_agent) lib/new_relic/harvest/collector/harvest_cycle.ex:40: NewRelic.Harvest.Collector.HarvestCycle.manual_shutdown/1
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<1.28298676/0 in NewRelic.Harvest.Supervisor.manual_shutdown/0>
    Args: []
[error] Task #PID<0.518.0> started from #PID<0.418.0> terminating
** (stop) exited in: GenServer.call(NewRelic.Harvest.Collector.ErrorTrace.HarvestCycle, :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/gen_server.ex:979: GenServer.call/3
    (new_relic_agent) lib/new_relic/harvest/collector/harvest_cycle.ex:40: NewRelic.Harvest.Collector.HarvestCycle.manual_shutdown/1
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<1.28298676/0 in NewRelic.Harvest.Supervisor.manual_shutdown/0>
    Args: []
[error] Task #PID<0.516.0> started from #PID<0.418.0> terminating
** (stop) exited in: GenServer.call(NewRelic.Harvest.Collector.TransactionErrorEvent.HarvestCycle, :pause, 5000)
    ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/gen_server.ex:979: GenServer.call/3
    (new_relic_agent) lib/new_relic/harvest/collector/harvest_cycle.ex:40: NewRelic.Harvest.Collector.HarvestCycle.manual_shutdown/1
    (elixir) lib/task/supervised.ex:90: Task.Supervised.invoke_mfa/2
    (elixir) lib/task/supervised.ex:35: Task.Supervised.reply/5
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Function: #Function<1.28298676/0 in NewRelic.Harvest.Supervisor.manual_shutdown/0>
    Args: []
warning: deprecated time unit: :seconds. A time unit should be :second, :millisecond, :microsecond, :nanosecond, or a positive integer
  (rollbax) lib/rollbax.ex:229: Rollbax.report_exception/1
  (rollbax) lib/rollbax/logger.ex:70: Rollbax.Logger.handle_event/2
  (stdlib) gen_event.erl:577: :gen_event.server_update/4
  (stdlib) gen_event.erl:559: :gen_event.server_notify/4
  (stdlib) gen_event.erl:300: :gen_event.handle_msg/6
  (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3

[error] GenServer #PID<0.418.0> terminating
** (stop) exited in: Task.await(%Task{owner: #PID<0.418.0>, pid: #PID<0.512.0>, ref: #Reference<0.565282695.737148932.2883>}, 5000)
    ** (EXIT) exited in: GenServer.call(NewRelic.Harvest.Collector.Metric.HarvestCycle, :pause, 5000)
        ** (EXIT) no process: the process is not alive or there's no process currently associated with the given name, possibly because its application isn't started
    (elixir) lib/task.ex:573: Task.await/2
    (elixir) lib/enum.ex:1327: Enum."-map/2-lists^map/1-0-"/2
    (stdlib) gen_server.erl:673: :gen_server.try_terminate/3
    (stdlib) gen_server.erl:858: :gen_server.terminate/10
    (stdlib) proc_lib.erl:249: :proc_lib.init_p_do_apply/3
Last message: {:EXIT, #PID<0.402.0>, :shutdown}
State: nil
[info] Application new_relic_agent exited: :stopped
[os_mon] cpu supervisor port (cpu_sup): Erlang has closed

Environment

Elixir & Erlang version (elixir -v):

Erlang/OTP 22 [erts-10.4.4] [source] [64-bit] [smp:12:12] [ds:12:12:10] [async-threads:1] [hipe]

Elixir 1.8.1 (compiled with Erlang/OTP 20)

Agent version (mix deps | grep new_relic_agent):

* new_relic_agent 1.17.1 (Hex package) (mix)
  locked at 1.17.1 (new_relic_agent) bd8ce395

Any ideas on what may be the problem? Thank you!

The text was updated successfully, but these errors were encountered:

binaryseed · 2020-04-24T00:47:30Z

Hello thanks for the report!

I took a look locally and I think your task completes too fast for the Agent to have completed it's boot process. The Agent needs to make a request to NewRelic upon boot which is not done synchronously in the supervision tree (that'd block your app).

A quick fix for this would be to make a call to a GenServer that will only respond after it's fully connected:

Application.ensure_all_started(:new_relic_agent)
GenServer.call(NewRelic.Harvest.Collector.AgentRun, :ping)

I can add simpler function that can be called instead of this one and also protect against the failure you are seeing

shayne-lp · 2020-04-24T12:33:44Z

Hey @binaryseed thanks for the explanation and quick fix tip, I appreciate it! What you said makes sense and that simple test task was probably a snowflake, but I appreciate you making an API update to proactively prevent it in the future. Thanks again!

shayne-lp · 2020-04-24T14:13:57Z

I had one final quick question in this timing regard, @binaryseed. Is there a way to flush the metrics to NewRelic before Application.stop(:new_relic_agent)? I'm curious as I no longer get errors, but I also do not see any transactions or activity in NewRelic from this Task. Does it only show up in Distributed Tracing, perhaps? Thanks!

binaryseed · 2020-04-24T23:29:23Z

It does flush everything upon shutdown, what data are you expecting?

There won't be an automatic Transaction created for the task, that's something you'd currently need to instrument yourself.

Perhaps I can wrap up all of this & auto-create a Transaction in the function I was talking about...

shayne-lp · 2020-04-27T12:17:03Z

Hey @binaryseed thanks for clarifying. Indeed, I was hoping an automatic Transaction would be created for the Mix Task. That would be great if you could autowrap all of that into a single function call! 👍

Also, can you please point me to any docs/snippets that show what I would need to manually do for a Transaction in the meantime? Thank you!

binaryseed · 2020-04-27T16:34:30Z

https://hexdocs.pm/new_relic_agent/NewRelic.html#start_transaction/2

and

https://hexdocs.pm/new_relic_agent/NewRelic.html#stop_transaction/0

shayne-lp · 2020-04-27T16:35:59Z

Perfect thanks sorry I missed that!

binaryseed · 2020-05-09T00:03:15Z

I have a PR that adds nice & easy Mix.Task instrumentation:

#221

shayne-lp · 2020-05-11T13:05:35Z

That is great, thanks @binaryseed !

shayne-lp closed this as completed Apr 24, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Errors on Application.stop in simple Mix Task #212

Errors on Application.stop in simple Mix Task #212

shayne-lp commented Apr 20, 2020 •

edited

Loading

binaryseed commented Apr 24, 2020

shayne-lp commented Apr 24, 2020

shayne-lp commented Apr 24, 2020

binaryseed commented Apr 24, 2020

shayne-lp commented Apr 27, 2020

binaryseed commented Apr 27, 2020

shayne-lp commented Apr 27, 2020

binaryseed commented May 9, 2020

shayne-lp commented May 11, 2020

Errors on Application.stop in simple Mix Task #212

Errors on Application.stop in simple Mix Task #212

Comments

shayne-lp commented Apr 20, 2020 • edited Loading

binaryseed commented Apr 24, 2020

shayne-lp commented Apr 24, 2020

shayne-lp commented Apr 24, 2020

binaryseed commented Apr 24, 2020

shayne-lp commented Apr 27, 2020

binaryseed commented Apr 27, 2020

shayne-lp commented Apr 27, 2020

binaryseed commented May 9, 2020

shayne-lp commented May 11, 2020

shayne-lp commented Apr 20, 2020 •

edited

Loading